[20131122]跟蹤sql profile的操作.txt

lfree發表於2013-11-22
[20131122]跟蹤sql profile的操作.txt

sql profile是11G的新特性,前幾天我在給別人做最佳化時,偷懶直接使用toad,step by step分析使用sql profile,導致系統執行緩慢,不得不中斷分析.今天有空跟蹤sql profile的操作看看,瞭解一些過程.

SCOTT@test> @ver
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

1.建立測試環境:
create table t pctfree 99 as select rownum id,lpad('x',1000,'x')  name from dual connect by level<=1e3;
create index i_t_id on t(id) ;
alter table t modify(id NOT NULL);
exec dbms_stats.gather_table_stats(user, 'T',  no_invalidate => false);

2.建立測試例子:

SCOTT@test> select /*+ full(t) */ count(*) from t;
  COUNT(*)
----------
      1000

SCOTT@test> @dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  cdwnbcfy42f8b, child number 0
-------------------------------------
select /*+ full(t) */ count(*) from t
Plan hash value: 2966233522
---------------------------------------------------------
| Id  | Operation          | Name | E-Rows | Cost (%CPU)|
---------------------------------------------------------
|   0 | SELECT STATEMENT   |      |        |   279 (100)|
|   1 |  SORT AGGREGATE    |      |      1 |            |
|   2 |   TABLE ACCESS FULL| T    |   1000 |   279   (0)|
---------------------------------------------------------

--由於使用了提示執行計劃選擇全表掃描.現在使用sql profile來最佳化這條語句.

3.使用與跟蹤sql profile:

@10046on 12

DECLARE
  ret_val VARCHAR2(4000);
BEGIN
  ret_val := DBMS_SQLTUNE.CREATE_TUNING_TASK(
                sql_id          => 'cdwnbcfy42f8b',
                plan_hash_value => NULL,
                scope       => 'COMPREHENSIVE',
                time_limit  => 1800,
                task_name   => 'TASK1',
                description => 'test');
  --:rv := ret_val;
END;
/

Begin
  Dbms_Sqltune.EXECUTE_TUNING_TASK('TASK1');
End;
/
@10046off

--select Dbms_Sqltune.REPORT_TUNING_TASK('TASK1', 'TEXT', 'TYPICAL') report from dual;
--execute dbms_sqltune.accept_sql_profile(task_name => 'TASK1', replace => TRUE);

4.分析跟蹤檔案:
--$ ./trimsql.sh  /u01/app/oracle11g/diag/rdbms/test/test/trace/test_ora_26538_127_0_0_1.trc > /tmp/task1.txt
$ tkprof  /u01/app/oracle11g/diag/rdbms/test/test/trace/test_ora_27568_127_0_0_1.trc
....
********************************************************************************

SQL ID: 4jh8pskb3zgu0 Plan Hash: 2966233522

select /*+ full(t) */ count(*)
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          0          0           0
Fetch       10      0.02       0.02          0      10040          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      0.02       0.02          0      10040          0          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84     (recursive depth: 1)
********************************************************************************

SQL ID: 4jh8pskb3zgu0 Plan Hash: 3548397654

select /*+ full(t) */ count(*)
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          0          0           0
Fetch       10      0.00       0.00          0         60          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      0.00       0.00          0         60          0          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84     (recursive depth: 1)
********************************************************************************

SQL ID: 4jh8pskb3zgu0 Plan Hash: 4021579484

select /*+ full(t) */ count(*)
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          0          0           0
Fetch       10      0.00       0.00          0         40          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      0.00       0.00          0         40          0          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84     (recursive depth: 1)
********************************************************************************

--從這裡分析可以發現每種不同的執行計劃,執行10次,如果存在很慢的執行方式,在生產系統執行,簡直就是災難!
--查詢sql_id='4jh8pskb3zgu0' 看看執行計劃:

SCOTT@test> @dpc 4jh8pskb3zgu0 ''
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------
SQL_ID  4jh8pskb3zgu0, child number 0
-------------------------------------
/* SQL Analyze(68,0) */ select /*+ full(t) */ count(*) from t

Plan hash value: 2966233522

---------------------------------------------------------
| Id  | Operation          | Name | E-Rows | Cost (%CPU)|
---------------------------------------------------------
|   0 | SELECT STATEMENT   |      |        |   279 (100)|
|   1 |  SORT AGGREGATE    |      |      1 |            |
|   2 |   TABLE ACCESS FULL| T    |   1000 |   279   (0)|
---------------------------------------------------------

Note
-----
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level

SQL_ID  4jh8pskb3zgu0, child number 1
-------------------------------------
/* SQL Analyze(68,0) */ select /*+ full(t) */ count(*) from t

Plan hash value: 3548397654

--------------------------------------------------------------
| Id  | Operation             | Name   | E-Rows | Cost (%CPU)|
--------------------------------------------------------------
|   0 | SELECT STATEMENT      |        |        |     3 (100)|
|   1 |  SORT AGGREGATE       |        |      1 |            |
|   2 |   INDEX FAST FULL SCAN| I_T_ID |   1000 |     3   (0)|
--------------------------------------------------------------

Note
-----
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level

SQL_ID  4jh8pskb3zgu0, child number 2
-------------------------------------
/* SQL Analyze(68,0) */ select /*+ full(t) */ count(*) from t

Plan hash value: 4021579484

----------------------------------------------------
| Id  | Operation        | Name   | E-Rows | Cost  |
----------------------------------------------------
|   0 | SELECT STATEMENT |        |        |     4 |
|   1 |  SORT AGGREGATE  |        |      1 |       |
|   2 |   INDEX FULL SCAN| I_T_ID |   1000 |     4 |
----------------------------------------------------

Note
-----
   - cpu costing is off (consider enabling it)
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level

61 rows selected.

--可以發現oracle選擇3中方式:1.全表掃描 2.INDEX FAST FULL SCAN 3. INDEX FULL SCAN.
--實際上還要檢查統計資訊是否stale,還有stale還有分析表等情況,如果這些表很大,執行更慢,以後要在具體最佳化過程中注意.

5.檢視分析報告:
SCOTT@test> select Dbms_Sqltune.REPORT_TUNING_TASK('TASK1', 'TEXT', 'TYPICAL') report from dual;
REPORT
-------------------------------------------------------------------------------
GENERAL INFORMATION SECTION
-------------------------------------------------------------------------------
Tuning Task Name   : TASK1
Tuning Task Owner  : SCOTT
Workload Type      : Single SQL Statement
Scope              : COMPREHENSIVE
Time Limit(seconds): 1800
Completion Status  : COMPLETED
Started at         : 11/22/2013 10:01:22
Completed at       : 11/22/2013 10:01:23

-------------------------------------------------------------------------------
Schema Name: SCOTT
SQL ID     : cdwnbcfy42f8b
SQL Text   : select /*+ full(t) */ count(*) from t

-------------------------------------------------------------------------------
FINDINGS SECTION (1 finding)
-------------------------------------------------------------------------------

1- SQL Profile Finding (see explain plans section below)
--------------------------------------------------------
  A potentially better execution plan was found for this statement.

  Recommendation (estimated benefit: 99.4%)
  -----------------------------------------
  - Consider accepting the recommended SQL profile.
    execute dbms_sqltune.accept_sql_profile(task_name => 'TASK1', task_owner
            => 'SCOTT', replace => TRUE);

  Validation results
  ------------------
  The SQL profile was tested by executing both its plan and the original plan
  and measuring their respective execution statistics. A plan may have been
  only partially executed if the other could be run to completion in less time.

                           Original Plan  With SQL Profile  % Improved
                           -------------  ----------------  ----------
  Completion Status:            COMPLETE          COMPLETE
  Elapsed Time (s):              .00276           .000155      94.38 %
  CPU Time (s):                 .002799             .0001      96.42 %
  User I/O Time (s):                  0                 0
  Buffer Gets:                     1004                 6       99.4 %
  Physical Read Requests:             0                 0
  Physical Write Requests:            0                 0
  Physical Read Bytes:                0                 0
  Physical Write Bytes:               0                 0
  Rows Processed:                     1                 1
  Fetches:                            1                 1
  Executions:                         1                 1

  Notes
  -----
  1. Statistics for the original plan were averaged over 10 executions.
  2. Statistics for the SQL profile plan were averaged over 10 executions.

-------------------------------------------------------------------------------
EXPLAIN PLANS SECTION
-------------------------------------------------------------------------------

1- Original With Adjusted Cost
------------------------------
Plan hash value: 2966233522

-------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Cost (%CPU)| Time     |
-------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |   279   (0)| 00:00:04 |
|   1 |  SORT AGGREGATE    |      |     1 |            |          |
|   2 |   TABLE ACCESS FULL| T    |  1000 |   279   (0)| 00:00:04 |
-------------------------------------------------------------------

2- Using SQL Profile
--------------------
Plan hash value: 3548397654

------------------------------------------------------------------------
| Id  | Operation             | Name   | Rows  | Cost (%CPU)| Time     |
------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |        |     1 |     3   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE       |        |     1 |            |          |
|   2 |   INDEX FAST FULL SCAN| I_T_ID |  1000 |     3   (0)| 00:00:01 |
------------------------------------------------------------------------

--建議執行如下:
execute dbms_sqltune.accept_sql_profile(task_name => 'TASK1', task_owner=> 'SCOTT', replace => TRUE);

SCOTT@test> execute dbms_sqltune.accept_sql_profile(task_name => 'TASK1', task_owner=> 'SCOTT', replace => TRUE);
PL/SQL procedure successfully completed.

SCOTT@test> select /*+ full(t) */ count(*) from t;
  COUNT(*)
----------
      1000

SCOTT@test> @dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  cdwnbcfy42f8b, child number 0
-------------------------------------
select /*+ full(t) */ count(*) from t

Plan hash value: 3548397654

--------------------------------------------------------------
| Id  | Operation             | Name   | E-Rows | Cost (%CPU)|
--------------------------------------------------------------
|   0 | SELECT STATEMENT      |        |        |     3 (100)|
|   1 |  SORT AGGREGATE       |        |      1 |            |
|   2 |   INDEX FAST FULL SCAN| I_T_ID |   1000 |     3   (0)|
--------------------------------------------------------------

Note
-----
   - SQL profile SYS_SQLPROF_01427dac70410001 used for this statement
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level


21 rows selected.

--可以發現下載執行計劃使用INDEX FAST FULL SCAN.
--即使我改動第1個字母大寫,依舊使用INDEX FAST FULL SCAN.
SCOTT@test> Select /*+ full(t) */ count(*) from t;
  COUNT(*)
----------
      1000

SCOTT@test> @dpc '' ''
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
SQL_ID  dxvbtb8hzfdr9, child number 0
-------------------------------------
Select /*+ full(t) */ count(*) from t

Plan hash value: 3548397654

--------------------------------------------------------------
| Id  | Operation             | Name   | E-Rows | Cost (%CPU)|
--------------------------------------------------------------
|   0 | SELECT STATEMENT      |        |        |     3 (100)|
|   1 |  SORT AGGREGATE       |        |      1 |            |
|   2 |   INDEX FAST FULL SCAN| I_T_ID |   1000 |     3   (0)|
--------------------------------------------------------------

Note
-----
   - SQL profile SYS_SQLPROF_01427dac70410001 used for this statement
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level
21 rows selected.

--補充1點,如果最佳化語句帶文字變數,想最佳化大量相似語句,可以在執行dbms_sqltune.accept_sql_profile
--加入:force_match=>true
--         force_match  - If TRUE this causes SQL Profiles
--                        to target all SQL statements which have the same
--                        text after normalizing all literal values into
--                        bind variables. (Note that if a combination of
--                        literal values and bind values is used in a
--                        SQL statement, no bind transformation occurs.)
--                        This is analogous to the matching algorithm
--                        used by the "FORCE" option of the
--                        CURSOR_SHARING parameter.  If FALSE, literals are
--                        not transformed.  This is analogous to the
--                        matching algorithm used by the "EXACT" option of
--                        the CURSOR_SHARING parameter.

總結:
sql profile是好東西,在生產系統使用,特別在最佳化很慢的語句時,要注意這些相關問題.


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-777298/,如需轉載,請註明出處,否則將追究法律責任。

相關文章