[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时，对应会话执行的语句要硬分析，生成新的子光标。在跟踪分析问题时注意。