[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時，對應會話執行的語句要硬分析，生成新的子游標。在跟蹤分析問題時注意。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2682615/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- phalcon:跟蹤sql語句SQL
- [20150527]跟蹤單個sql語句.txtSQL
- sqlplus 跟蹤sql語句SQL
- [20160704]從跟蹤檔案抽取sql語句.txtSQL
- 使用10046跟蹤sql語句SQL
- Oracle執行語句跟蹤 使用sql trace實現語句追蹤OracleSQL
- mysql如何跟蹤執行的sql語句MySql
- [20130226]跟蹤特定IP的sql語句.txtSQL
- 【MySQL】如何對SQL語句進行跟蹤（trace）？MySql
- 依據錯誤號來跟蹤sql語句SQL
- [20131031]從跟蹤檔案中抽取sql語句.txtSQL
- SQL效能的度量 - 語句級別的SQL跟蹤autotraceSQL
- 使用oracle的10046事件跟蹤SQL語句Oracle事件SQL
- [20200417]跟蹤特定sql語句以及v$open_cursor檢視.txtSQL
- oracle 使用者跟蹤 需要的sql語句總結OracleSQL
- [20200417]跟蹤特定sql語句以及v$open_cursor檢視2.txtSQL
- [20200424]跟蹤特定sql語句以及v$open_cursor檢視(再補充).txtSQL
- [20200422]跟蹤特定sql語句以及v$open_cursor檢視(補充).txtSQL
- oracle11g有DBMS_MONITOR跟蹤TRUNCATE操作Oracle
- 透過ORADEBUG運用10046事件跟蹤SQL語句事件SQL
- 【最佳化】DBMS_MONITOR包之生成跟蹤檔案
- [20170703]SQL語句分析執行過程.txtSQL
- DM7聯機執行SQL語句進行加密備份與設定跟蹤日誌SQL加密
- 跟蹤session 與 trace檔案分析Session
- PostgreSQL 原始碼解讀（21）- 查詢語句#6（PlannedStmt詳解-跟蹤分析）SQL原始碼
- [20240320]空格與sqlpus的sql語句.txtSQL
- SQL調整優化與10053跟蹤分析一例SQL優化
- 0624使用10035事件跟蹤無法執行的sql語句事件SQL
- [20201105]再分析sql語句.txtSQL
- [zt] oracle跟蹤檔案與跟蹤事件Oracle事件
- oracle跟蹤檔案與跟蹤事件(zt)Oracle事件
- SQL調整優化與10053跟蹤分析一例(zt)SQL優化
- [20150403]修正sql語句.txtSQL
- PL/SQL與DDL語句SQL
- SQLServer進行SQL跟蹤SQLServer
- 會話級SQL跟蹤會話SQL
- SQL 的跟蹤方法traceSQL
- sql語句的優化分析SQL優化