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

来源：这里教程网时间：2026-03-03 15:32:05 作者：

[20200417]跟踪特定sql语句以及v$open_cursor视图.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 [sql:sql_id=80baj2c2ur47u] bind=false, wait=false'; System altered. --//session 2: --//收尾执行：alter system set events 'sql_trace off'; --//session 1: --//打开新的会话,注一定要在打开跟踪后登录,切记: SCOTT@book> @ spid SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50 ---------- ---------- ------------------------ --------- ------ ------- ---------- -------------------------------------------------- 44 721 47324 DEDICATED 47325 27 16 alter system kill session '44,721' immediate; --//注：一般测试环境退出在登录sid不会变，仅仅serial#增加。 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次。 --//每次执行select * from dept where deptno=20;前在session 2 都执行@vcs 80baj2c2ur47u 44. SYS@book> @ voc 80baj2c2ur47u 44 no rows selected 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 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 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 OPEN 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 OPEN 000000008638EC10 44 SCOTT 000000007C184260 95129850 80baj2c2ur47u select * from dept where deptno=20 DICTIONARY LOOKUP CURSOR CACHED 000000008638EC10 44 SCOTT 000000007C184260 95129850 80baj2c2ur47u select * from dept where deptno=20 DICTIONARY LOOKUP CURSOR CACHED --//你可以发现执行4次出现CURSOR_TYPE='DICTIONARY LOOKUP CURSOR CACHED'.再次执行出现相同的一行。不会出现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 9 1 9 9 9 1 .007999 .000888778 .007498 .000833111 95 10.5555556 1 0 0 1 000000007C184260 000000007C930050 2852011669 5 1 5 5 5 1 .003 .0006 .002871 .0005742 10 2 0 0 0 --//你可以实际上建立新的子光标，正好执行5次。 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 OPEN 000000007C930050 1 000000008638EC10 44 SCOTT 000000007C184260 95129850 80baj2c2ur47u select * from dept where deptno=20 DICTIONARY LOOKUP CURSOR CACHED 000000007C930050 1 000000008638EC10 44 SCOTT 000000007C184260 95129850 80baj2c2ur47u select * from dept where deptno=20 DICTIONARY LOOKUP CURSOR CACHED 000000007C930050 --//后面的KGLLKHDL就是子光标的地址。指向child number#=1的子光标地址。 $ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47325.trc PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084890795500 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084894841044 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084898633156 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' PARSING IN CURSOR #140601268218120 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084902184981 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' PARSING IN CURSOR #140601268217176 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084907017138 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' --//PARSING IN CURSOR 5次，注意前面3次cursor后面的数字一样，而第4，5次cursor后面的数字与前面的不同,不知道为什么？ --//可以看出软软解析无效。 --//摘要转储内容如下： *** 2020-04-17 08:54:50.795 *** SESSION ID:(44.721) 2020-04-17 08:54:50.795 *** CLIENT ID:() 2020-04-17 08:54:50.795 *** SERVICE NAME:(SYS$USERS) 2020-04-17 08:54:50.795 *** MODULE NAME:(SQL*Plus) 2020-04-17 08:54:50.795 *** ACTION NAME:() 2020-04-17 08:54:50.795 ===================== PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084890795500 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #140601269096704:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084890795495 FETCH #140601269096704:c=0,e=68,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084890796248 STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=59 us cost=1 size=20 card=1)' STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=31 us cost=0 size=0 card=1)' FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084890796850 *** 2020-04-17 08:54:54.840 CLOSE #140601269096704:c=0,e=11,dep=0,type=0,tim=1587084894840825 ===================== PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084894841044 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #140601269096704:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084894841042 FETCH #140601269096704:c=0,e=30,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084894841206 STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=25 us cost=1 size=20 card=1)' STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=15 us cost=0 size=0 card=1)' FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084894841624 *** 2020-04-17 08:54:58.632 CLOSE #140601269096704:c=0,e=11,dep=0,type=0,tim=1587084898632954 ===================== PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084898633156 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #140601269096704:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084898633154 FETCH #140601269096704:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084898633314 STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=21 us cost=1 size=20 card=1)' STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=14 us cost=0 size=0 card=1)' FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084898633728 *** 2020-04-17 08:55:02.184 CLOSE #140601269096704:c=0,e=14,dep=0,type=1,tim=1587084902184797 ===================== PARSING IN CURSOR #140601268218120 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084902184981 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #140601268218120:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084902184979 FETCH #140601268218120:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084902185144 STAT #140601268218120 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=22 us cost=1 size=20 card=1)' STAT #140601268218120 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=15 us cost=0 size=0 card=1)' FETCH #140601268218120:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084902185536 *** 2020-04-17 08:55:07.016 CLOSE #140601268218120:c=0,e=12,dep=0,type=1,tim=1587084907016941 ===================== PARSING IN CURSOR #140601268217176 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084907017138 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u' select * from dept where deptno=20 END OF STMT EXEC #140601268217176:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084907017136 FETCH #140601268217176:c=0,e=41,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084907017310 STAT #140601268217176 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=25 us cost=1 size=20 card=1)' STAT #140601268217176 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=16 us cost=0 size=0 card=1)' FETCH #140601268217176:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084907017795 4.总结： --//感觉这是一个bug。与我以前的一个测试链接很像。 --//http://blog.itpub.net/267265/viewspace-2675362/=>[20200212]使用DBMS_SHARED_POOL.MARKHOT与视图v$open_cursor.txt --//在跟踪特定sql语句时，后登录的会话会出现前面测试所看到的情况，软软解析失效,打开v$open_cursor会看到上面的情况。 --//对于已经登录的会话呢，会出现什么情况呢，另外写一篇blog。