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文本
这一部分很easy找到，当前sql语句的文本信息在跟踪文件的最前面部分(能够搜索Current SQL statement for this session)
Trace file /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
Oracle …. - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME ..
System name: Linux
Node name: 192oracle.cn100.com
Release: …el6.x86_64
SMP Fri Feb 00:: UTC
Machine: x86_64
Instance name: cn100
Redo thread mounted
Oracle process
Unix process pid: , image: oracle@192oracle.cn100.com (TNS V1-V3)
::.
.) ::.
::.
::.
::.
::.
dbkedDefDump(): Starting a non,
mask=0x0)
----- Error Stack Dump -----
ORA: 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 procedure DBMON.P_DH1
0xfcfaebe8 procedure DBMON.P_DH2
0x10e7d6420 anonymous block
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst() call kgdsdst() 000000000 ? 000000000 ?
?
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 …. - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME ..
System name: Linux
Node name: 192oracle.cn100.com
Release: …el6.x86_64
SMP Fri Feb 00:: UTC
Machine: x86_64
Instance name: cn100
Redo thread mounted
Oracle process
Unix process pid: , image: oracle@192oracle.cn100.com (TNS V1-V3)
::.
.) ::.
::.
::.
::.
::.
dbkedDefDump(): Starting a non,
mask=0x0)
----- Error Stack Dump -----
ORA: 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() call kgdsdst() 000000000 ?
000000000 ?
?
7FFF332CCFD8 ? 000000000 ?
……为了排版,兴许省略……
注意上面跟踪文件里PL/SQL标红那一部分，就是我们关注的部分。
假设进行errorstack跟踪式，跟踪进程运行的是一个PL/SQL调用。那么PL/SQL调用堆也将被跟踪下来(在PL/SQL Call Stack部分)。
这部分告诉你发生错误时Oracle在运行详细哪个PL/SQL过程（包or函数）以及errorstack跟踪过程中的详细哪个调用发生错误。这对我们诊断问题很有帮助
PL/SQL Call Stack包括三列，例如以下
以下我们一一介绍这三列的含义：
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只包括三行。
procedure DBMON.P_DH1
procedure DBMON.P_DH2
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
为什么找到详细的语句后，我们还须要寻找详细的绑定变量值？？能够归纳为例如以下四种原因
因此。你须要知道当问题发生时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 …. - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
ORACLE_HOME ..
System name: Linux
Node name: 192oracle.cn100.com
Release: …el6.x86_64
SMP Fri Feb 00:: UTC
Machine: x86_64
Instance name: cn100
Redo thread mounted
Oracle process
Unix process pid: , image: oracle@192oracle.cn100.com (TNS V1-V3)
::.
.) ::.
::.
::.
::.
::.
dbkedDefDump(): Starting a non,
mask=0x0)
----- Error Stack Dump -----
ORA: 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() call kgdsdst() 000000000 ? 000000000 ?
?
7FFF332CCFD8 ? 000000000 ?
……为了排版,兴许省略……
打开跟踪文件。通常第一步做的是搜索第一个"Session Cursor Dump",当搜索它的时候，将看到例如以下的输出
----- Session Cursor Dump -----
, pgadep
(, , , )
SYNTAX PARSE BOUND
Cached frame pages(total, free):
, ), , ), , ), , )
----- Current Cursor -----
xsc=0x7f5227898580 ctx=0xf92d7aa8 pgactx=0xf92d7aa8 ctxcbk=0xf92d74f8 ctxqbc=(nil)
ctxrws=0x10293a4c0
----- Explain Plan Dump -----
----- Compact Format (Stream) -----
Dumping stream
----------------------------------
0000:
……i………….
: ..
----- Plan Table -----
============
Plan Table
============
--------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time
|
--------------------------------------------+-----------------------------------+
| | | |
| | LOAD TABLE CONVENTIONAL | | | | | |
--------------------------------------------+-----------------------------------+
Content of other_xml column
===========================
db_version : …
parse_schema : DBMON
plan_hash :
plan_hash_2 :
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted ..
parallel_execution_enabled = true
parallel_query_forced_dop
……为了排版,兴许省略……
我们能够发现例如以下实用的内容
假设pgadep为0。它意味着这个查询是一个top-level查询，正在被用户或者应用通过OCI接口在运行。
pgadep为1，意味着它是一个递归的查询，通过递归程序接口(RPI)来运行，可能是数据字典查询或者只通过PL/SQL调用运行的SQL。
所以，可以发现当前正在运行的当前查询的绑定变量值，我们须要做的是在trace file中朝前搜索Cursor2#。例如以下
注意：这个搜索词是大写和小写敏感的。
Cursor#2(0x7f5227951aa0) state=BOUND curiob=0x7f5227898580
curflg par=(nil) ses=0x129a8edc0
----- Dump Cursor sql_id=b8n03s73k7d39
xsc=0x7f5227898580 cur=0x7f5227951aa0 -----
LibraryHandle: Address LoadLockMode Status=VALD
ObjectName: Name=INSERT INTO DH_T VALUES (:B2 ,:B1 )
FullHashValue=38f6bac85b76f427b45003c1c723b469 Namespace=SQL AREA(00) Type=CURSOR(00)
Identifier OwnerIdn
Statistics: InvalidationCount ExecutionCount LoadCount ActiveLocks TotalLockCount TotalPinCount
Counters: BrokenCount RevocablePointer KeepDependency KeepHandle BucketInUse HandleInUse
Concurrency: DependencyMutex, , , ) Mutex, , , )
Flags]
WaitersLists:
Lock=f68ce968[f68ce968,f68ce968]
Pin=f68ce978[f68ce948,f68ce948]
::
LibraryObject: Address 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 LockMode Status=VALD
Name: Namespace=SQL AREA(00) Type=CURSOR(00)
Statistics: InvalidationCount ExecutionCount LoadCount ActiveLocks TotalLockCount TotalPinCount
Counters: BrokenCount RevocablePointer KeepDependency KeepHandle BucketInUse HandleInUse
Concurrency: DependencyMutex, , , ) Mutex, , , )
Flags]
WaitersLists:
Lock=fab7b550[fab7b550,fab7b550]
Pin=fab7b560[fab7b530,fab7b530]
LibraryObject: Address Flags=EXS[0000]
Flags2=[0000] PublicFlags=[0000]
DataBlocks:
Block: # Change=NONE
Heap=f6a0b38 Pointer=f6569c08 Extent=f6569aa0 Flags=I/-/P/A/-/-
FreedLocation Alloc. . LoadTime
Block: # Change=NONE
Heap=f6b88438 Pointer=f92d7aa8 Extent=f92d6e48 Flags=I/-/P/A/-/E
FreedLocation Alloc. . LoadTime
NamespaceDump:
Child :: Heap6 ::
NamespaceDump:
Parent plk=y
ppn cld hd=0xfab7b4c0
par=0xf6b87e00
Mutex 0xf6b88308(, ) idn
ct hsh unp hvl=f6b88c60
nhv ses=(nil)
hep ld ob=0xf6569b20 ptr=0xf92d7aa8
fex=0xf92d6e48
exec_id
child#(0xfab7b4c0) pcs=0xf6b88308
clk=0x10d6111e0 ci=0xf6569c08 pn=0xfdf4c890 ctx=0xf92d7aa8
kgsccflg llk[0x7f5227898588,0x7f5227898588] idx=6a
xscflg
----- Bind Byte Code (IN) -----
Opcode Bind Rpi Scalar Sql In(may be out)
Nocopy NoSkip
Offsi , Offsi
Opcode Bind Rpi Scalar Sql In(may be out)
Nocopy NoSkip
Offsi , Offsi
----- Bind Info (kkscoacd) -----
Bind#0
oacdty mxl() mxlc=00 mal=00
scl=00 pre=00
oacflg fl2 frm
kxsbbbfp avl flg
value=1234335
Bind#1
oacdty mxl() mxlc=00 mal=00
scl=00 pre=00
oacflg fl2 frm csi siz
kxsbbbfp avl flg
value="oradh"
Frames pfr 0x7f5227897c18 siz efr 0x7f5227897b38 siz
Cursor frame dump
enxt: .0x00000550 enxt: .0x00000040 enxt: .0x000007a0
pnxt: .0x00000030
kxscphp inu nps
kxscbhp inu nps
kxscwhp inu nps
注意：重点关注上面标红字体部份
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: .0x00000550 enxt: .0x00000040 enxt: .0x000007a0
pnxt: .0x00000030
kxscphp inu nps
kxscbhp inu nps
kxscwhp inu nps
Cursor#1游标部分：
Cursor frame dump
enxt: .0x000005c0 enxt: .0x00000fd8 enxt: .0x00000fa0 enxt: .0x00000658
enxt: .0x00000228 enxt: .0x00000fd8 enxt: .0x00000fa0 enxt: .0x00000248
enxt: .0x00000fa0 enxt: .0x00000410 enxt: .0x00000480 enxt: .0x00000f70
pnxt: .0x00000030
kxscphp inu nps
kxscbhp inu nps
在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 or replace procedure p_dh1 as
v_id ;
v_name varchar2() :='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跟踪
…. Production on Tue
Jul ::
Copyright (, , Oracle. All rights reserved.
Connected to:
Oracle …. - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining,
Oracle Database Vault and Real Application Testing options
pagesize
SQL> col tracefile format a100
));
SPID TRACEFILE
---------------
--------------------------------------------------------------------------------------------------
/u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
SQL> alter session set events='1438
trace name errorstack forever,level 3';
Session altered.
SQL> exec p_dh2;
BEGIN p_dh2; END;
*
ERROR :
ORA: value larger than specified precision allowed for this column
ORA:
ORA:
ORA:
[oracle@192oracle ~]$ ls -ltr /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
oracle
oinstall Jul : /u01/oracle/diag/rdbms/cn100/cn100/trace/cn100_ora_10848.trc
手机扫一扫
移动阅读更方便
你可能感兴趣的文章