[20200417]跟踪特定sql语句以及v$open_cursor视图2.txt

[20200417]跟踪特定sql语句以及v$open_cursor视图2.txt --//工作需要跟踪特定sql语句，我发现一个奇特现象，有时候无法抓取sql语句,有时候跟踪的sql语句无法实现软软解析. --//分几种情况分析. --//感觉我遇到链接的情况: --//http://blog.itpub.net/267265/viewspace-2675362/=>[20200212]使用DBMS_SHARED_POOL.MARKHOT与视图v$open_cursor.txt --//做一个测试,顺便说明遇到的情况： --//测试alter system set events 'sql_trace [sql:sql_id=80baj2c2ur47u] bind=false, wait=false';执行时在此之前登录的会话的 --//情况. 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 --//session 2: SYS@book> alter system set events 'sql_trace off'; System altered. --//初始化这步不要忘记!!避免影响下面的测试。我在这里犯了几次错误。 2.测试准备： --//首先打开一个会话执行select * from dept where deptno=20;多次,保证不会挤出共享池,然后退出。 SCOTT@book> select * from dept where deptno=20;     DEPTNO DNAME          LOC ---------- -------------- -------------         20 RESEARCH       DALLAS SCOTT@book> @ hash HASH_VALUE SQL_ID        CHILD_NUMBER HASH_HEX ---------- ------------- ------------ ---------   95129850 80baj2c2ur47u            0   5ab90fa --//获得sql_id=80baj2c2ur47u. --//建立脚本利于反复执行: $ cat voc.sql column SID format 9999 column USER_NAME format a10 column CURSOR_TYPE format a32 column SQL_TEXT format a34 select * from v$open_cursor where sql_id='&&1' and sid=&&2; $ cat vocx.sql column KGLLKCTP format A32 column KGLNAOBJ format a34 SELECT inst_id       ,kgllkuse       ,kgllksnm       ,user_name       ,kglhdpar       ,kglnahsh       ,kgllksqlid       ,kglnaobj       ,kgllkest       ,DECODE (kgllkexc, 0, TO_NUMBER (NULL), kgllkexc)       ,kgllkctp       ,kgllkhdl   FROM x$kgllk  WHERE     kglhdnsp = 0        AND kglhdpar != kgllkhdl        AND kgllksqlid = '&&1'        AND kgllksnm = &&2; 3.测试: --//测试启动特定sql跟踪之前已经登录的会话执行情况: --//session 2: SYS@book> alter system set events 'sql_trace off'; System altered. --//session 1: SCOTT@book> @ spid        SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50 ---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------         44        725 47555                    DEDICATED 47556       27         18 alter system kill session '44,725' immediate; select * from dept where deptno=20; --//注：已经先于启动跟踪前，并且先执行1次。 --//session 2: SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN --//光标已经open。 SYS@book> alter system set events 'sql_trace [sql:sql_id=80baj2c2ur47u] bind=true, wait=true'; System altered. --//session 1: select * from dept where deptno=20; select * from dept where deptno=20; --//每次执行select * from dept where deptno=20;前在session 2 都执行@vcs 80baj2c2ur47u 44. SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 DICTIONARY LOOKUP CURSOR CACHED SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 SESSION CURSOR CACHED 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 000000007C184260 000000007C186A28 2852011669         12          1         12         12             12              1    .008998   .000749833    .007968      .000664        101 8.41666667          1          0               0    1 000000007C184260 000000007C930050 2852011669          8          1          8          8              8              1       .003      .000375    .003297   .000412125         16          2          0          0               0 SYS@book> @ vocx 80baj2c2ur47u 44    INST_ID KGLLKUSE           KGLLKSNM USER_NAME  KGLHDPAR           KGLNAHSH KGLLKSQLID    KGLNAOBJ                           KGLLKEST            DECODE(KGLLKEXC,0,TO_NUMBER(NULL),KGLLKEXC) KGLLKCTP                         KGLLKHDL ---------- ---------------- ---------- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ------------------------------------------- -------------------------------- ----------------          1 000000008638EC10         44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                                                 SESSION CURSOR CACHED            000000007C186A28 --//后面的KGLLKHDL就是子光标的地址。指向child number#=0的子光标地址。 --//对于已经登录的会话再跟踪的情况，光标是可以cache的。也就是可以实现软软解析。 --//但是在这样的情况下，oracle是无法跟踪对于sql语句的。 --//从前面的测试知道进程号spid=47556. $ ls -l  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc ls: /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc: No such file or directory --//可以发现并没有建立跟踪文件。 4.继续测试： --//如果你session 1一直执行：select * from dept where deptno=20;是无法抓取到这样的sql语句的。即使退出也不会生成跟踪文件。 --//但是如果你在会话执行另外的sql语句，然后在执行select * from dept where deptno=20;。 --//session 1: SCOTT@book> @ pp TRACEFILE -------------------------------------------------------------------------------- /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc SCOTT@book> host ls -l /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc ls: /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc: No such file or directory --//可以发现还是没有建立跟踪文件。 SCOTT@book> select * from dept where deptno=20;     DEPTNO DNAME          LOC ---------- -------------- -------------         20 RESEARCH       DALLAS SCOTT@book> host ls -l /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc -rw-r----- 1 oracle oinstall 1366 Apr 17 09:36 /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc --//现在已经建立跟踪文件了。 --//session 1: SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 SESSION CURSOR CACHED $ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' --//session 1: SCOTT@book> select * from dept where deptno=20;     DEPTNO DNAME          LOC ---------- -------------- -------------         20 RESEARCH       DALLAS --//session 2: SYS@book> @ voc 80baj2c2ur47u 44 SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE ---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- -------------------------------- 000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 SESSION CURSOR CACHED $ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' --//仅仅PARSING IN CURSOR 1次。 $ cat /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc Trace file /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_1 System name:    Linux Node name:      gxqyydg4 Release:        2.6.39-300.26.1.el5uek Version:        #1 SMP Thu Jan 3 18:31:38 PST 2013 Machine:        x86_64 Instance name: book Redo thread mounted by this instance: 1 Oracle process number: 27 Unix process pid: 47556, image: oracle@gxqyydg4 (TNS V1-V3) *** 2020-04-17 09:36:57.431 *** SESSION ID:(44.725) 2020-04-17 09:36:57.431 *** CLIENT ID:() 2020-04-17 09:36:57.431 *** SERVICE NAME:(SYS$USERS) 2020-04-17 09:36:57.431 *** MODULE NAME:(SQL*Plus) 2020-04-17 09:36:57.431 *** ACTION NAME:() 2020-04-17 09:36:57.431 ===================== PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #139764967743728:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587087417430861 WAIT #139764967743728: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1587087417431676 FETCH #139764967743728:c=0,e=40,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587087417431764 *** 2020-04-17 09:38:51.141 CLOSE #139764967743728:c=0,e=17,dep=0,type=3,tim=1587087531141236 EXEC #139764967743728:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587087531141445 WAIT #139764967743728: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1587087531141541 FETCH #139764967743728:c=0,e=44,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587087531141650 --//最后1次执行没有分析。 5总结： --//在跟踪特定sql语句时，已经登录的会话可能会遇到无法抓取sql语句的情况，只要跟踪开始时循环执行相同的语句，就可能出现这样的情况。 --//实际上只要启动跟踪特定sql语句，已经登录的会话执行的是不要跟踪的sql，后面再执行特定sql语句，才能生成跟踪文件，语言不好表达， --//我在这里测试很久才找到这个规律，大家可以自行测试。 --//之所以有这个测试，因为我在实际的工作环境中正好遇到这样的情况，无法跟踪特定的sql语句。