Oracle ErrorStack 使用和閱讀詳解
一、概述
在Oracle資料庫執行過程中，我們經常會遇到這樣或那樣的錯誤，但是錯誤的提示並不具體，加大了我們在診斷問題時的難度。
ErrorStack是Oracle提供的一種對於錯誤堆疊進行跟蹤的方法，透過設定跟蹤可以將一些指定錯誤的後臺資訊詳細的轉儲出來，寫入跟蹤檔案，幫助我們診斷問題。
備註：
1、當oracle發生關鍵的錯誤諸如：ora-600,Errorstack是自動被oracle dump寫入trace檔案中。
2、當你在alert.log裡面看見這類錯誤，並提示已經產生trace檔案。開啟對應的trace後，你會發現這類trace檔案一般都是以“ksedmp:internal or fatal error"開頭，"kesdmp"意味著Kernel Service
Error Dump，這一行下面的內容就是errorstack記錄的錯誤堆疊！
Errorstack dump也可以透過使用Oradebug errorstack 3手工呼叫，前提是先使用Oradebug setospid設定了目標程式之後。Oradebug
Errorstack對於診斷一個session似乎Hang住(但是在v$session_wait裡面並未出現合理的wait event)或者是比正常時消耗更多資源時，獲取當前session執行sql、具體的變數值等等資訊，從而幫助你找到問題根源！
二、跟蹤級別和方法
ErrorStack主要有4個跟蹤級別，如下
-
0 僅轉儲錯誤堆疊
-
1 轉儲錯誤堆疊和函式呼叫堆疊
-
2 Level 1 + ProcessState
-
3 Level 2 + Context area （一般我們診斷問題，都是使用這個級別的跟蹤！）
ErrorStack設定方法，如下（僅指定特定的錯誤程式碼，只有這個特定的錯誤出現時才能被觸發！）
-
例項級別：alter system set events='984 trace name errorstack forever,level 3' scope=spfile;
-
會話級別: alter session set events='984 trace name errorstack forever,level 3';
- oradebug： 1、oradebug setospid xxxx; 2、oradebug dump errorstack 3 --當前session正在執行的語句
三、ErrorStack跟蹤檔案中的內容
Errorstack跟蹤檔案有很多資訊，這裡我們主要講解對我們診斷問題最有用的四個部分的內容（其它很多內容我們無法看懂），如下
-
從Errorstack跟蹤檔案中發現當前正在執行SQL文字。
-
從Errorstack跟蹤檔案中發現當前正在執行PL/SQL包和PL/SQL source code line number。
-
從Errorstack跟蹤檔案中發現當前bind variable value。
-
從Errorstack跟蹤檔案中發現一個cursor正在使用多少private memory(UGA)。
針對上面的四個部分，我將透過一個具體的errorstack跟蹤檔案示例來展示盒加深理解，errorstack的跟蹤檔案如下（具體生成方式程式碼，放在最後了）。這一部分的內容主要參考tanelpoder大牛的部落格。
1、從Errorstack跟蹤檔案中發現當前正在執行SQL文字
這一部分非常容易找到，當前sql語句的文字資訊在跟蹤檔案的最前面部分(可以搜尋Current SQL statement for this session)
Trace file /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
2、從Errorstack跟蹤檔案中發現當前正在執行PL/SQL包和PL/SQL source code line number
Errorstack跟蹤檔案和前面一樣，如下
Trace file /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
注意上面跟蹤檔案中PL/SQL標紅那一部分，就是我們關注的部分。
如果進行errorstack跟蹤式，跟蹤程式執行的是一個PL/SQL呼叫，那麼PL/SQL呼叫堆也將被跟蹤下來(在PL/SQL
Call Stack部分)。這部分告訴你錯誤發生時Oracle在執行具體哪個PL/SQL過程（包or函式）以及errorstack跟蹤過程中的具體哪個呼叫發生錯誤。這對我們診斷問題非常有幫助
PL/SQL Call Stack包含三列，如下
-
object handle
-
line number
-
object name
下面我們一一介紹這三列的含義：
1、object handle
object handle是這個物件(PL/SQL過程、包、函式、匿名塊)被load進library cache中的記憶體地址，可以透過這個對映地址和X$KGLOB.KGLHDADR表列關聯起來以發現那個物件是正在被處理。如下
SQL> select kglnaown,kglnaobj,kglhdadr from X$KGLOB a where KGLHDADR='00000001075FCD10';
KGLNAOWN KGLNAOBJ KGLHDADR
---------- ---------- ----------------
DBMON P_DH1 00000001075FCD10
2、line number
這個是非常重要的資訊，它將告訴你當errorstack呼叫發生時正在執行的PL/SQL程式碼（可以定位到程式碼中的具體行）。例如，在如上的輸出中，在這個匿名塊的第1行呼叫了DBMON.P_DH2儲存過程，而DBMON.P_DH2儲存過程在第7行呼叫了另外一個儲存過程DBMON.P_DH1，當errorstack跟蹤發生時正在執行DBMON.P_DH2儲存過程中的第6行程式碼。
3、object name
PL/SQL儲存的物件名(或者匿名塊，當物件並沒有儲存在一個過程中)，如果是匿名塊(匿名塊的文字可以透過V$SQL發現),你可以關聯這個地址和V$SQL.ADDRESS來發現匿名塊的文字資訊。
以上的PL/SQL call stack僅僅包含三行。
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
應該從下而上來閱讀一個PL/SQL call stack，例如
1.底部的行可以告訴我們正在執行一個匿名塊以及在這個匿名塊的第一行，它在呼叫DBMON.P_DH2儲存過程
2.第二行可以告訴我們DBMON.P_DH2儲存過程在第7行呼叫了另外一個儲存過程DBMON.P_DH1
3.DBMON.P_DH2儲存過程中的第6行程式碼出現錯誤，errorstack資訊被轉儲。
透過查詢DBA_SOURCE，我們可以與errorstack跟蹤檔案中的PL/SQL call stack部分資訊進行驗證，如下。
SQL> select line, text from dba_source where owner = 'DBMON' and name = 'P_DH2' order by line asc;
LINE TEXT
---------- ------------------------------------------------------------
1 procedure p_dh2 as
2 v_cnt number;
3 begin
4 ----just for errorstack test
5 select count(*) into v_cnt from dh_t;
6 dbms_output.put_line('the dh_t count is '||v_cnt);
7 p_dh1;
8 end;
9
9 rows selected.
SQL> select line, text from dba_source where owner = 'DBMON' and name = 'P_DH1' order by line asc;
LINE TEXT
---------- ------------------------------------------------------------
1 procedure p_dh1 as
2 v_id number :=1234335;
3 v_name varchar2(200) :='oradh';
4 begin
5 --just for errorstack test
6 insert into dh_t values (v_id,v_name);
7 commit;
8 end;
9
9 rows selected.
你可以發現會話正在執行的PL/SQL第6行（一個insert語句導致錯誤）。
通常,當error dump，crash，hang發生時(頂部的行是”parent" function遞迴呼叫的“child”function正在執行的程式碼)，PL/SQL errorstack告訴我們精確的PL/SQL code。
3、從Errorstack跟蹤檔案中發現當前bind variable value
為什麼找到具體的語句後，我們還需要尋找具體的繫結變數值？？可以歸納為如下四種原因
-
一個會話可能以某種方式變的非常消耗CPU,並且會話的wait等待時間沒有任何意義.
-
你需要調查什麼SQL正在被執行，並且你需要檢視SQL帶有的繫結變數
-
SQL的執行計劃是正常的，但是效能卻非常低下
-
可以假設當某些表或者行源變的大的時候，存在資料傾斜，CBO沒有計算出正確的執行計劃。
因此，你需要知道當問題發生時SQL使用的繫結變數是什麼，不幸的是Oracle中並沒有一個V$檢視讓我們去檢視某個session的當前繫結變數值。V$SQL_BIND_CAPTURE檢視僅僅隨機的取樣繫結變數值，並不儲存所有的被使用的繫結變數值，而dbms_xplan.display_cursor中顯示的也只是第一次窺探的繫結變數值.
Oracle 11gR2中實時的SQL
Monitoring特效能夠達到此目的。在V$SQL_MONITOR中有一列BIND_XML,此列包含正在執行的足夠長時間(預設佔用CPU超過5s的SQL，都會出現在次檢視中)的bind
variable values.但是這個只有在11gR2並且具有Diag+Tuning pack licenses時才有效。
注意：由於SQL語句的繫結變數值存在於程式的PGA中的私有記憶體中，因此不能輕易的跟蹤另一個程式私有記憶體。errorstack跟蹤檔案中中包含CURSORDUMP,也就包含我們想要得到的bind variable value。
我們繼續看開始的跟蹤檔案，如下
Trace file /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/11.2.0
System name: Linux
Node name: 192oracle.cn100.com
Release: 2.6.32-358.el6.x86_64
Version: #1 SMP Fri Feb 22 00:31:26 UTC 2013
Machine: x86_64
Instance name: cn100
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 10848, image: oracle@192oracle.cn100.com (TNS V1-V3)
*** 2014-07-01 11:16:36.260
*** SESSION ID:(61.13360) 2014-07-01 11:16:36.260
*** CLIENT ID:() 2014-07-01 11:16:36.260
*** SERVICE NAME:(SYS$USERS) 2014-07-01 11:16:36.260
*** MODULE NAME:(SQL*Plus) 2014-07-01 11:16:36.260
*** ACTION NAME:() 2014-07-01 11:16:36.260
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-01438: value larger than specified precision allowed for this column
----- Current SQL Statement for this session (sql_id=b8n03s73k7d39) ----- --可以看到，當前SQL就在這一行下面
INSERT INTO DH_T VALUES (:B2 ,:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x1075fcd10 6 procedure DBMON.P_DH1
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFF332C8AD8 ? 000000001 ?
7FFF332CCFD8 ? 000000000 ?
......為了排版,後續省略......
開啟跟蹤檔案，通常第一步做的是搜尋第一個"Session Cursor Dump",當搜尋它的時候，將看到如下的輸出
----- Session Cursor Dump -----
Current cursor: 2, pgadep=1
Open cursors(pls, sys, hwm, max): 3(1, 1, 64, 1000)
NULL=0 SYNTAX=0 PARSE=0 BOUND=3 FETCH=0 ROW=0
Cached frame pages(total, free):
4k(11, 8), 8k(0, 0), 16k(0, 0), 32k(0, 0)
----- Current Cursor -----
xsc=0x7f5227898580 ctx=0xf92d7aa8 pgactx=0xf92d7aa8 ctxcbk=0xf92d74f8 ctxqbc=(nil) ctxrws=0x10293a4c0
----- Explain Plan Dump -----
----- Compact Format (Stream) -----
Dumping stream from 0 to 22
----------------------------------
0000: 143 137 23 1 1 0 105 0 0 0 1 0 0 0 0 21 9 4 6 7 ......i.............
0020: 0 142 ..
----- Plan Table -----
============
Plan Table
============
--------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
--------------------------------------------+-----------------------------------+
| 0 | INSERT STATEMENT | | | | 1 | |
| 1 | LOAD TABLE CONVENTIONAL | | | | | |
--------------------------------------------+-----------------------------------+
Content of other_xml column
===========================
db_version : 11.2.0.1
parse_schema : DBMON
plan_hash : 0
plan_hash_2 : 0
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
parallel_execution_enabled = true
parallel_query_forced_dop = 0
Current cursor: 2, pgadep=1
Open cursors(pls, sys, hwm, max): 3(1, 1, 64, 1000)
NULL=0 SYNTAX=0 PARSE=0 BOUND=3 FETCH=0 ROW=0
Cached frame pages(total, free):
4k(11, 8), 8k(0, 0), 16k(0, 0), 32k(0, 0)
----- Current Cursor -----
xsc=0x7f5227898580 ctx=0xf92d7aa8 pgactx=0xf92d7aa8 ctxcbk=0xf92d74f8 ctxqbc=(nil) ctxrws=0x10293a4c0
----- Explain Plan Dump -----
----- Compact Format (Stream) -----
Dumping stream from 0 to 22
----------------------------------
0000: 143 137 23 1 1 0 105 0 0 0 1 0 0 0 0 21 9 4 6 7 ......i.............
0020: 0 142 ..
----- Plan Table -----
============
Plan Table
============
--------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
--------------------------------------------+-----------------------------------+
| 0 | INSERT STATEMENT | | | | 1 | |
| 1 | LOAD TABLE CONVENTIONAL | | | | | |
--------------------------------------------+-----------------------------------+
Content of other_xml column
===========================
db_version : 11.2.0.1
parse_schema : DBMON
plan_hash : 0
plan_hash_2 : 0
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
parallel_execution_enabled = true
parallel_query_forced_dop = 0
......為了排版,後續省略......
我們可以發現如下有用的內容
-
Current cursor: 2,這個告訴我們在這個會話的UGA開啟的cursor中，當前正在執行Cursor# 6 遊標
-
the pgadep：1變數告訴我們PGA depth，也就是這個查詢執行的遞迴的深度
如果pgadep為0，它意味著這個查詢是一個top-level查詢，正在被使用者或者應用透過OCI介面在執行。
pgadep為1，意味著它是一個遞迴的查詢，透過遞迴程式介面(RPI)來執行，可能是資料字典查詢或者僅僅透過PL/SQL呼叫執行的SQL。
所以，能夠發現當前正在執行的當前查詢的繫結變數值，我們需要做的是在trace file中朝前搜尋Cursor2#，如下
注意：這個搜尋詞是大小寫敏感的。
Cursor#2(0x7f5227951aa0) state=BOUND curiob=0x7f5227898580
curflg=cd fl2=0 par=(nil) ses=0x129a8edc0
----- Dump Cursor sql_id=b8n03s73k7d39 xsc=0x7f5227898580 cur=0x7f5227951aa0 -----
LibraryHandle: Address=f68ce8d8 Hash=c723b469 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=INSERT INTO DH_T VALUES (:B2 ,:B1 )
FullHashValue=38f6bac85b76f427b45003c1c723b469 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3341005929 OwnerIdn=148
Statistics: InvalidationCount=0 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0 HandleInUse=0
Concurrency: DependencyMutex=f68ce988(0, 1, 0, 0) Mutex=f68cea00(61, 19, 0, 6)
Flags=RON/PIN/TIM/PN0/DBN/[10012841]
WaitersLists:
Lock=f68ce968[f68ce968,f68ce968]
Pin=f68ce978[f68ce948,f68ce948]
Timestamp: Current=07-01-2014 11:16:35
LibraryObject: Address=f6b87d18 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
ChildTable: size='16'
Child: id='0' Table=f6b88bc8 Reference=f6b88668 Handle=fab7b4c0
Children:
Child: childNum='0'
LibraryHandle: Address=fab7b4c0 Hash=0 LockMode=N PinMode=S LoadLockMode=0 Status=VALD
Name: Namespace=SQL AREA(00) Type=CURSOR(00)
Statistics: InvalidationCount=0 ExecutionCount=1 LoadCount=1 ActiveLocks=1 TotalLockCount=1 TotalPinCount=2
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0
Concurrency: DependencyMutex=fab7b570(0, 0, 0, 0) Mutex=f68cea00(61, 19, 0, 6)
Flags=RON/PIN/PN0/EXP/[10012111]
WaitersLists:
Lock=fab7b550[fab7b550,fab7b550]
Pin=fab7b560[fab7b530,fab7b530]
LibraryObject: Address=f6569b20 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=CCUR^c723b469 pins=0 Change=NONE
Heap=f6a0b38 Pointer=f6569c08 Extent=f6569aa0 Flags=I/-/P/A/-/-
FreedLocation=0 Alloc=3.093750 Size=3.937500 LoadTime=11473268840
Block: #='6' name=SQLA^c723b469 pins=0 Change=NONE
Heap=f6b88438 Pointer=f92d7aa8 Extent=f92d6e48 Flags=I/-/P/A/-/E
FreedLocation=0 Alloc=8.890625 Size=11.859375 LoadTime=0
NamespaceDump:
Child Cursor: Heap0=0xf6569c08 Heap6=0xf92d7aa8 Heap0 Load Time=07-01-2014 11:16:35 Heap6 Load Time=07-01-2014 11:16:35
NamespaceDump:
Parent Cursor: sql_id=b8n03s73k7d39 parent=0xf6b87e00 maxchild=1 plk=y ppn=n kkscs=0xf6b88308 nxt=(nil) flg=18 cld=0 hd=0xfab7b4c0 par=0xf6b87e00
Mutex 0xf6b88308(0, 0) idn 3000000000
ct=0 hsh=0 unp=(nil) unn=0 hvl=f6b88c60 nhv=0 ses=(nil)
hep=0xf6b88398 flg=80 ld=1 ob=0xf6569b20 ptr=0xf92d7aa8 fex=0xf92d6e48
cursor instantiation=0x7f5227898580 used=1404184595 exec_id=16777216 exec=1
child#0(0xfab7b4c0) pcs=0xf6b88308
clk=0x10d6111e0 ci=0xf6569c08 pn=0xfdf4c890 ctx=0xf92d7aa8
kgsccflg=1 llk[0x7f5227898588,0x7f5227898588] idx=6a
xscflg=c0110676 fl2=d120000 fl3=422a2188 fl4=100
----- Bind Byte Code (IN) -----
Opcode = 6 Bind Rpi Scalar Sql In(may be out) Nocopy NoSkip
Offsi = 48, Offsi = 0
Opcode = 6 Bind Rpi Scalar Sql In(may be out) Nocopy NoSkip
Offsi = 48, Offsi = 32
----- Bind Info (kkscoacd) -----
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7f5227943d08 bln=22 avl=05 flg=09
value=1234335
Bind#1
oacdty=01 mxl=2000(200) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=01 csi=852 siz=2000 off=0
kxsbbbfp=7f5227943d48 bln=2000 avl=05 flg=09
value="oradh"
Frames pfr 0x7f5227897c18 siz=3424 efr 0x7f5227897b38 siz=3376
Cursor frame dump
enxt: 3.0x00000550 enxt: 2.0x00000040 enxt: 1.0x000007a0
pnxt: 1.0x00000030
kxscphp=0x7f5227961030 siz=984 inu=584 nps=360
kxscbhp=0x7f5227961920 siz=984 inu=152 nps=0
kxscwhp=0x7f5227960f40 siz=4056 inu=56 nps=0
curflg=cd fl2=0 par=(nil) ses=0x129a8edc0
----- Dump Cursor sql_id=b8n03s73k7d39 xsc=0x7f5227898580 cur=0x7f5227951aa0 -----
LibraryHandle: Address=f68ce8d8 Hash=c723b469 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=INSERT INTO DH_T VALUES (:B2 ,:B1 )
FullHashValue=38f6bac85b76f427b45003c1c723b469 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3341005929 OwnerIdn=148
Statistics: InvalidationCount=0 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0 HandleInUse=0
Concurrency: DependencyMutex=f68ce988(0, 1, 0, 0) Mutex=f68cea00(61, 19, 0, 6)
Flags=RON/PIN/TIM/PN0/DBN/[10012841]
WaitersLists:
Lock=f68ce968[f68ce968,f68ce968]
Pin=f68ce978[f68ce948,f68ce948]
Timestamp: Current=07-01-2014 11:16:35
LibraryObject: Address=f6b87d18 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
ChildTable: size='16'
Child: id='0' Table=f6b88bc8 Reference=f6b88668 Handle=fab7b4c0
Children:
Child: childNum='0'
LibraryHandle: Address=fab7b4c0 Hash=0 LockMode=N PinMode=S LoadLockMode=0 Status=VALD
Name: Namespace=SQL AREA(00) Type=CURSOR(00)
Statistics: InvalidationCount=0 ExecutionCount=1 LoadCount=1 ActiveLocks=1 TotalLockCount=1 TotalPinCount=2
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0
Concurrency: DependencyMutex=fab7b570(0, 0, 0, 0) Mutex=f68cea00(61, 19, 0, 6)
Flags=RON/PIN/PN0/EXP/[10012111]
WaitersLists:
Lock=fab7b550[fab7b550,fab7b550]
Pin=fab7b560[fab7b530,fab7b530]
LibraryObject: Address=f6569b20 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=CCUR^c723b469 pins=0 Change=NONE
Heap=f6a0b38 Pointer=f6569c08 Extent=f6569aa0 Flags=I/-/P/A/-/-
FreedLocation=0 Alloc=3.093750 Size=3.937500 LoadTime=11473268840
Block: #='6' name=SQLA^c723b469 pins=0 Change=NONE
Heap=f6b88438 Pointer=f92d7aa8 Extent=f92d6e48 Flags=I/-/P/A/-/E
FreedLocation=0 Alloc=8.890625 Size=11.859375 LoadTime=0
NamespaceDump:
Child Cursor: Heap0=0xf6569c08 Heap6=0xf92d7aa8 Heap0 Load Time=07-01-2014 11:16:35 Heap6 Load Time=07-01-2014 11:16:35
NamespaceDump:
Parent Cursor: sql_id=b8n03s73k7d39 parent=0xf6b87e00 maxchild=1 plk=y ppn=n kkscs=0xf6b88308 nxt=(nil) flg=18 cld=0 hd=0xfab7b4c0 par=0xf6b87e00
Mutex 0xf6b88308(0, 0) idn 3000000000
ct=0 hsh=0 unp=(nil) unn=0 hvl=f6b88c60 nhv=0 ses=(nil)
hep=0xf6b88398 flg=80 ld=1 ob=0xf6569b20 ptr=0xf92d7aa8 fex=0xf92d6e48
cursor instantiation=0x7f5227898580 used=1404184595 exec_id=16777216 exec=1
child#0(0xfab7b4c0) pcs=0xf6b88308
clk=0x10d6111e0 ci=0xf6569c08 pn=0xfdf4c890 ctx=0xf92d7aa8
kgsccflg=1 llk[0x7f5227898588,0x7f5227898588] idx=6a
xscflg=c0110676 fl2=d120000 fl3=422a2188 fl4=100
----- Bind Byte Code (IN) -----
Opcode = 6 Bind Rpi Scalar Sql In(may be out) Nocopy NoSkip
Offsi = 48, Offsi = 0
Opcode = 6 Bind Rpi Scalar Sql In(may be out) Nocopy NoSkip
Offsi = 48, Offsi = 32
----- Bind Info (kkscoacd) -----
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7f5227943d08 bln=22 avl=05 flg=09
value=1234335
Bind#1
oacdty=01 mxl=2000(200) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=01 csi=852 siz=2000 off=0
kxsbbbfp=7f5227943d48 bln=2000 avl=05 flg=09
value="oradh"
Frames pfr 0x7f5227897c18 siz=3424 efr 0x7f5227897b38 siz=3376
Cursor frame dump
enxt: 3.0x00000550 enxt: 2.0x00000040 enxt: 1.0x000007a0
pnxt: 1.0x00000030
kxscphp=0x7f5227961030 siz=984 inu=584 nps=360
kxscbhp=0x7f5227961920 siz=984 inu=152 nps=0
kxscwhp=0x7f5227960f40 siz=4056 inu=56 nps=0
注意：重點關注上面標紅字型部份
ErrorStack dump是我們可以很可靠的找到SQL語句當前使用的繫結變數值一種方法。另外，還有如下說明：
-
在errorstack跟蹤檔案中發現Cursor#2，它的state=BOUND，意味著繫結變數值已經被賦予的
-
SQL文字是我們在前面已經查詢出來的，我們可以看到兩個繫結變數值
-
Bind variale numbering是從0開始，所以如果我們想搜尋第一個繫結值，需要搜尋Bind#0
4、從Errorstack跟蹤檔案中發現一個cursor正在使用多少private memory(UGA)
繼續我們前面的示例，跟蹤檔案中能夠度量一個session的某些遊標使用了多少UGA私有記憶體。如下
Cursor#2遊標部分：
Cursor frame dump
enxt: 3.0x00000550 enxt: 2.0x00000040 enxt: 1.0x000007a0
pnxt: 1.0x00000030
kxscphp=0x7f5227961030 siz=984 inu=584 nps=360
kxscbhp=0x7f5227961920 siz=984 inu=152 nps=0
kxscwhp=0x7f5227960f40 siz=4056 inu=56 nps=0
Cursor#1遊標部分：
Cursor frame dump
enxt: 12.0x000005c0 enxt: 11.0x00000fd8 enxt: 10.0x00000fa0 enxt: 9.0x00000658
enxt: 8.0x00000228 enxt: 7.0x00000fd8 enxt: 6.0x00000fa0 enxt: 5.0x00000248
enxt: 4.0x00000fa0 enxt: 3.0x00000410 enxt: 2.0x00000480 enxt: 1.0x00000f70
pnxt: 1.0x00000030
kxscphp=0x7f5227960c70 siz=2792 inu=1056 nps=424
kxscbhp=0x7f5227960e50 siz=10376 inu=10008 nps=8768
Cursor frame dump
enxt: 3.0x00000550 enxt: 2.0x00000040 enxt: 1.0x000007a0
pnxt: 1.0x00000030
kxscphp=0x7f5227961030 siz=984 inu=584 nps=360
kxscbhp=0x7f5227961920 siz=984 inu=152 nps=0
kxscwhp=0x7f5227960f40 siz=4056 inu=56 nps=0
Cursor#1遊標部分：
Cursor frame dump
enxt: 12.0x000005c0 enxt: 11.0x00000fd8 enxt: 10.0x00000fa0 enxt: 9.0x00000658
enxt: 8.0x00000228 enxt: 7.0x00000fd8 enxt: 6.0x00000fa0 enxt: 5.0x00000248
enxt: 4.0x00000fa0 enxt: 3.0x00000410 enxt: 2.0x00000480 enxt: 1.0x00000f70
pnxt: 1.0x00000030
kxscphp=0x7f5227960c70 siz=2792 inu=1056 nps=424
kxscbhp=0x7f5227960e50 siz=10376 inu=10008 nps=8768
在cursor frame
dump部分我們可以看見kxsc開始的一些資訊，這些意味著Kernel eXECUTION Shared
Cursor，其中的每一行的siz引數告訴我們當前分配的私有記憶體大小。當然，我們需要彙總所有的siz，這個值就是此遊標的memory
usage。
下面是我的一些猜測彙總：
01.Heap description Meaning
02.kxscphp Cursor permanent heap. Allocated when cursor is opened
03.kxscdfhp Cursor default heap - default duration allocations
04.kxscehp Cursor ephemeral heap - short lived duration allocations
05.kxscwhp Cursor Work heap - used when actually executing the cursor (workareas etc)
06.kxscbhp Cursor Bind heap - this is where bind variable values and their metadata are kept.
四、實驗程式碼
1、建立表和PL/SQL函式
create table dh_t (id number(2,1),name varchar2(200));
create or replace procedure p_dh1 as
v_id number :=1234335;
v_name varchar2(200) :='oradh';
begin
--just for errorstack test
insert into dh_t values (v_id,v_name);
commit;
end;
/
create or replace procedure p_dh2 as
v_cnt number;
begin
----just for errorstack test
select count(*) into v_cnt from dh_t;
dbms_output.put_line('the dh_t count is '||v_cnt);
p_dh1;
end;
/
create or replace procedure p_dh1 as
v_id number :=1234335;
v_name varchar2(200) :='oradh';
begin
--just for errorstack test
insert into dh_t values (v_id,v_name);
commit;
end;
/
create or replace procedure p_dh2 as
v_cnt number;
begin
----just for errorstack test
select count(*) into v_cnt from dh_t;
dbms_output.put_line('the dh_t count is '||v_cnt);
p_dh1;
end;
/
2、進行errorstack跟蹤
SQL*Plus: Release 11.2.0.1.0 Production on Tue
Jul 1 11:15:52 2014
Copyright (c) 1982, 2009, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
SQL> set linesize 200 pagesize 999
SQL> col tracefile format a100
SQL> select spid, tracefile
from v$process a
where addr =
(select paddr
from v$session
where sid = (select sid from v$mystat where rownum = 1));
SPID TRACEFILE
--------------- --------------------------------------------------------------------------------------------------
10848 /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
或者：
SELECT c.value || '/' || d.instance_name || '_ora_' || a.spid || '.trc' trace
FROM v$process a, v$session b, v$parameter c, v$instance d
WHERE a.addr = b.paddr
AND b.audsid = userenv('sessionid')
AND c.name = 'user_dump_dest';
SQL> alter session set events='1438 trace name errorstack forever,level 3'; ---開啟errorstack
Session altered.
SQL> exec p_dh2;
BEGIN p_dh2; END;
*
ERROR at line 1:
ORA-01438: value larger than specified precision allowed for this column
ORA-06512: at "DBMON.P_DH1", line 6
ORA-06512: at "DBMON.P_DH2", line 7
ORA-06512: at line 1
SQL>alter session set events='1438 trace name errorstack off'; ----關閉errorstack
[oracle@192oracle ~]$ ls -ltr /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
-rw-r----- 1 oracle oinstall 12190347 Jul 1 11:16 /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
Copyright (c) 1982, 2009, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
SQL> set linesize 200 pagesize 999
SQL> col tracefile format a100
SQL> select spid, tracefile
from v$process a
where addr =
(select paddr
from v$session
where sid = (select sid from v$mystat where rownum = 1));
SPID TRACEFILE
--------------- --------------------------------------------------------------------------------------------------
10848 /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
或者：
SELECT c.value || '/' || d.instance_name || '_ora_' || a.spid || '.trc' trace
FROM v$process a, v$session b, v$parameter c, v$instance d
WHERE a.addr = b.paddr
AND b.audsid = userenv('sessionid')
AND c.name = 'user_dump_dest';
SQL> alter session set events='1438 trace name errorstack forever,level 3'; ---開啟errorstack
Session altered.
SQL> exec p_dh2;
BEGIN p_dh2; END;
*
ERROR at line 1:
ORA-01438: value larger than specified precision allowed for this column
ORA-06512: at "DBMON.P_DH1", line 6
ORA-06512: at "DBMON.P_DH2", line 7
ORA-06512: at line 1
SQL>alter session set events='1438 trace name errorstack off'; ----關閉errorstack
[oracle@192oracle ~]$ ls -ltr /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
-rw-r----- 1 oracle oinstall 12190347 Jul 1 11:16 /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/31397003/viewspace-2142752/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- errorstack使用Error
- 【詳解】ThreadPoolExecutor原始碼閱讀（三）thread原始碼
- 【詳解】ThreadPoolExecutor原始碼閱讀（二）thread原始碼
- 【詳解】ThreadPoolExecutor原始碼閱讀（一）thread原始碼
- TCP/IP詳解卷一閱讀後記TCP
- TCP/IP詳解卷二閱讀後記TCP
- TCP/IP詳解卷三閱讀後記TCP
- Caddy 原始碼閱讀（一）Run 詳解原始碼
- Tomcat中session詳解（原始碼閱讀）TomcatSession原始碼
- Oracle邏輯讀詳解Oracle
- Tomcat中Lifecycle詳解（原始碼閱讀）Tomcat原始碼
- Oracle文件閱讀指南Oracle
- 完全解析！Bert & Transformer 閱讀理解原始碼詳解ORM原始碼
- Oracle Profile 使用詳解Oracle
- Oracle SPA使用詳解Oracle
- 使用errorstack解決ORA-00904一例Error
- 使用ErrorStack進行Oracle錯誤跟蹤及診斷ErrorOracle
- Oracle SCN機制詳細解讀Oracle
- Oracle AWR報告詳細解讀Oracle
- Oracle 官方教材閱讀整理Oracle
- 跟蹤oracle特定報錯 errorstackOracleError
- 磨刀不誤閱讀工 |《如何閱讀一本書》之基礎閱讀和檢視閱讀
- iOS訂閱詳解iOS
- Oracle Profile 使用詳解(轉)Oracle
- 圖解HTTP，閱讀分享圖解HTTP
- [閱讀JavaCookBook]瞭解MavenJavaMaven
- Oracle 官方文件閱讀順序Oracle
- Oracle閱讀執行計劃Oracle
- 利用errorstack event解決問題Error
- 使用OpenGrok閱讀原始碼原始碼
- 使用vim閱讀原始碼原始碼
- oracle pctfree和pctused詳解Oracle
- oracle中not in和not exsist詳解Oracle
- oracle oradebug使用詳解Oracle
- Oracle中job的使用詳解Oracle
- Oracle使用者profile詳解Oracle
- oracle外部表詳解以及使用Oracle
- Oracle_oswbba工具使用詳解Oracle