[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語句。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2686681/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20200417]跟蹤特定sql語句以及v$open_cursor檢視.txtSQL
- [20200422]跟蹤特定sql語句以及v$open_cursor檢視(補充).txtSQL
- [20200424]跟蹤特定sql語句以及v$open_cursor檢視(再補充).txtSQL
- Oracle執行語句跟蹤 使用sql trace實現語句追蹤OracleSQL
- [20210113]ashtop查詢特定表的SQL語句2.txtSQL
- [20200326]dbms_monitor跟蹤與SQL語句分析.txtSQL
- sql 語句網路除錯和 sql 語句低層傳輸檢視SQL除錯
- [20201207]12c v$open_cursor檢視.txt
- [20231025]跟蹤rename操作2.txt
- [20200324]SQL語句優化的困惑2.txtSQL優化
- MySQL_通過binlog檢視原始SQL語句MySql
- [20210112]ashtop查詢特定表的SQL語句.txtSQL
- [20210220]gdb跟蹤邏輯讀2.txt
- [20190329]探究sql語句相關mutexes補充2.txtSQLMutex
- oracle資料庫檢視鎖表的sql語句整理Oracle資料庫SQL
- Laravel ORM SQL 語句查詢、檢視，附贈 IDE ORM 語法提示LaravelORMSQLIDE
- [20200211]使用DBMS_SHARED_POOL.MARKHOT與sql語句2.txtSQL
- [20190125]簡單快速檢視那些sql語句正在執行.txtSQL
- SQLServer進行SQL跟蹤SQLServer
- MySQL檢視建表語句MySql
- oracle檢視物件DDL語句Oracle物件
- Oracle資料庫跟蹤SQLOracle資料庫SQL
- DM7聯機執行SQL語句進行加密備份與設定跟蹤日誌SQL加密
- Java中如何解析SQL語句、格式化SQL語句、生成SQL語句？JavaSQL
- SQL語句SQL
- PostgreSQL 原始碼解讀（15）- Insert語句(執行過程跟蹤)SQL原始碼
- [20200818]12c 10046跟蹤時間戳2.txt時間戳
- 檢視 Laravel 查詢資料語句Laravel
- 資料庫基礎知識詳解四：儲存過程、檢視、遊標、SQL語句優化以及索引資料庫儲存過程SQL優化索引
- 【VIEW】Oracle如何查詢固定檢視的定義或底層sql語句ViewOracleSQL
- T-SQL運維指令碼——檢視SQLServer平均最耗資源時間的SQL語句SQL運維指令碼Server
- 【SQL】9 SQL INSERT INTO 語句SQL
- 【SQL】10 SQL UPDATE 語句SQL
- 【SQL】11 SQL DELETE 語句SQLdelete
- SQL SELECT 語句SQL
- sql常用語句SQL
- oracle v$sqlare 分析SQL語句使用資源情況OracleSQL
- PostgreSQL 原始碼解讀（21）- 查詢語句#6（PlannedStmt詳解-跟蹤分析）SQL原始碼