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