[20200417]跟蹤特定sql語句以及v$open_cursor檢視.txt
[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。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2686680/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20200417]跟蹤特定sql語句以及v$open_cursor檢視2.txtSQL
- [20200424]跟蹤特定sql語句以及v$open_cursor檢視(再補充).txtSQL
- [20200422]跟蹤特定sql語句以及v$open_cursor檢視(補充).txtSQL
- [20130226]跟蹤特定IP的sql語句.txtSQL
- phalcon:跟蹤sql語句SQL
- [20150527]跟蹤單個sql語句.txtSQL
- sqlplus 跟蹤sql語句SQL
- [20160704]從跟蹤檔案抽取sql語句.txtSQL
- 使用10046跟蹤sql語句SQL
- Oracle執行語句跟蹤 使用sql trace實現語句追蹤OracleSQL
- mysql如何跟蹤執行的sql語句MySql
- 【MySQL】如何對SQL語句進行跟蹤（trace）？MySql
- 依據錯誤號來跟蹤sql語句SQL
- [20131031]從跟蹤檔案中抽取sql語句.txtSQL
- SQL效能的度量 - 語句級別的SQL跟蹤autotraceSQL
- 檢視低效的SQL語句SQL
- 使用oracle的10046事件跟蹤SQL語句Oracle事件SQL
- 檢視v$sql_shared_cursor檢視獲取sql語句為什麼不能共享?SQL
- [20200326]dbms_monitor跟蹤與SQL語句分析.txtSQL
- oracle 使用者跟蹤 需要的sql語句總結OracleSQL
- [20160720]檢視了解oracle跟蹤事件.txtOracle事件
- 20140321]檢視大量消耗資源的sql語句.txtSQL
- [ZT]v$sqlarea,v$sql,v$sqltext這三個檢視提供的sql語句有什麼區別SQL
- 跟蹤oracle特定報錯 errorstackOracleError
- [20161230]檢視父遊標中sql語句.txtSQL
- 使用TKPROF檢視跟蹤檔案
- sql 語句網路除錯和 sql 語句低層傳輸檢視SQL除錯
- 【檢視】使用V$SQL_PLAN檢視獲取曾經執行過的SQL語句執行計劃SQL
- 檢視mysql正在執行的SQL語句MySql
- SQL語句大全—檢視錶空間（二）SQL
- SQL語句大全—檢視錶空間（一）SQL
- 透過ORADEBUG運用10046事件跟蹤SQL語句事件SQL
- [20210112]ashtop查詢特定表的SQL語句.txtSQL
- Oracle 檢視佔用undo大的sql語句OracleSQL
- sqlserver 檢視和sql語句的效率對比SQLServer
- 檢視造成等待事件的具體SQL語句事件SQL
- [20210113]ashtop查詢特定表的SQL語句2.txtSQL
- v$sql檢視和v$sqlarea檢視的構建SQL