[20200326]dbms_monitor跟蹤與SQL語句分析.txt

[20200326]dbms_monitor跟蹤與SQL語句分析.txt

--//昨天最佳化sql語句,我使用dbms_monitor.session_trace_enable獲取繫結變數時遇到一些問題開始理解出現問題.
--//自己也做一個記錄.避免以後再次困惑.

1.環境:
SCOTT@book> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

2.測試1,使用10046事件跟蹤:
--//開啟資料庫後沒有沒有執行select * from dept where deptno=10;語句。
@ 10046on 12
select * from dept where deptno=10;
select * from dept where deptno=10;
select * from dept where deptno=10;
select * from dept where deptno=10;
select * from dept where deptno=10;
select * from dept where deptno=10;
--//執行6次.
@ 10046off

3.分析:
--//透過其它方式獲取sql_id='4xamnunv51w9j'.
$ grep "^PARSING" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_57847.trc | grep 4xamnunv51w9j
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206626007 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206627952 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206629393 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
--//PARSING IN CURSOR 出現3次。

$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_57847.trc | grep '#140522922765496'
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206626007 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
PARSE #140522922765496:c=66990,e=68295,p=0,cr=282,cu=0,mis=1,r=0,dep=0,og=1,plh=2852011669,tim=1585187206626005
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206627952 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
PARSE #140522922765496:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187206627951
PARSING IN CURSOR #140522922765496 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187206629393 hv=911274289 ad='7dbb5068' sqlid='4xamnunv51w9j'
PARSE #140522922765496:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187206629392
PARSE #140522922765496:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187206630780
PARSE #140522922765496:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187206631987
PARSE #140522922765496:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187207691309
--//PARSING IN CURSOR 出現3次。PARSE 出現6次。相當於3次之後以後剩下的都是軟軟解析。

4.測試2,使用dbms_monitor包跟蹤:
--//退出再登入,session 1:
SCOTT@book> @ spid

       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
         1       7895 57880                    DEDICATED 57881       24          3 alter system kill session '1,7895' immediate;

select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
--//執行6次.
--//開啟新會話session 2,執行:
exec dbms_monitor.session_trace_enable(session_id => 1,serial_num => 7895 , waits => true , binds => true);

--//session 1:
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
--//執行5次.

--//session 2:
exec dbms_monitor.session_trace_disable(session_id => 1,serial_num => 7895);

5.分析:
--//sql_id='80baj2c2ur47u'
$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_57881.trc | grep 80baj2c2ur47u
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499817057 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499818641 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499822332 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
--//PARSING IN CURSOR 出現3次。因為在登入前我已經執行6次，游標已經cache。出現PARSING IN CURSOR意味重新分析SQL語句。

SYS@book> @ tpt/sqlid 80baj2c2ur47u %
Show SQL text, child cursors and execution stats for SQLID 80baj2c2ur47u child nvl('%','%')

HASH_VALUE PLAN_HASH_VALUE  CH# SQL_TEXT
---------- --------------- ---- ----------------------------------
  95129850      2852011669    0 select * from dept where deptno=20

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED ROWS_PER_FETCH    CPU_SEC CPU_SEC_EXEC    ELA_SEC ELA_SEC_EXEC       LIOS  LIOS_EXEC       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- -------------- ---------- ------------ ---------- ------------ ---------- ---------- ---------- ---------- ---------------
   0 000000007C1BCD68 000000007C90C368 2852011669          6          1          6          6              6              1       .001   .000166667    .001922   .000320333         12          2          0          0               0
   1 000000007C1BCD68 000000007E243730 2852011669          5          1          5          5              5              1       .002        .0004    .002232     .0004464         10          2          0          0               0
--//生成新的子游標。

$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_57881.trc | grep "139700468146096"
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499817057 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
PARSE #139700468146096:c=1000,e=1700,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2852011669,tim=1585187499817051
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499818641 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
PARSE #139700468146096:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187499818639
PARSING IN CURSOR #139700468146096 len=34 dep=0 uid=83 oct=3 lid=83 tim=1585187499822332 hv=95129850 ad='7c1bcd68' sqlid='80baj2c2ur47u'
PARSE #139700468146096:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187499822331
PARSE #139700468146096:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187499826357
PARSE #139700468146096:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1585187500664529
--//PARSING IN CURSOR 出現3次。PARSE 出現5次。相當於3次之後以後剩下的都是軟軟解析。

6.這個意味著什麼呢？有可能我在跟蹤時重新生成的執行計劃發生了改變與原來不同。
--//這樣不幸的事情竟然給我遇到了，真是奇葩，導致我分析錯誤，再寫另外一篇blog說明遇到的問題。
--//如果你現在再次執行如下：

--//session 1:
SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS

SCOTT@book> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  80baj2c2ur47u, child number 0
-------------------------------------
select * from dept where deptno=20
Plan hash value: 2852011669
----------------------------------------------------------------------------------------
| Id  | Operation                   | Name    | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |        |       |     1 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| DEPT    |      1 |    20 |     1   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | PK_DEPT |      1 |       |     0   (0)|          |
----------------------------------------------------------------------------------------
--//使用child number 0.

--//session 2:
SYS@book> exec dbms_monitor.session_trace_enable(session_id => 1,serial_num => 7895 , waits => true , binds => true);
PL/SQL procedure successfully completed.

--//session 1:
SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS

SCOTT@book> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  80baj2c2ur47u, child number 1
-------------------------------------
select * from dept where deptno=20
Plan hash value: 2852011669
---------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name    | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |      1 |        |       |     1 (100)|          |      1 |00:00:00.01 |       2 |
|   1 |  TABLE ACCESS BY INDEX ROWID| DEPT    |      1 |      1 |    20 |     1   (0)| 00:00:01 |      1 |00:00:00.01 |       2 |
|*  2 |   INDEX UNIQUE SCAN         | PK_DEPT |      1 |      1 |       |     0   (0)|          |      1 |00:00:00.01 |       1 |
---------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1 / DEPT@SEL$1
   2 - SEL$1 / DEPT@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("DEPTNO"=20)
--//使用child number 1.

SYS@book> exec dbms_monitor.session_trace_disable(session_id => 1,serial_num => 7895);
PL/SQL procedure successfully completed.

--//現在還會選擇child number 0的情況，這樣就出現我跟蹤時語句突然變好了，我取消跟蹤問題又再次出現變慢的情況。
--//也就是要理解當exec dbms_monitor.session_trace_enable時，對應會話執行的語句要硬分析，生成新的子游標。在跟蹤分析問題時注意。