打开相应的trace后。你会发现这类trace文件一般都是以“ksedmp:internal or fatal
error"开头,"kesdmp"意味着Kernel Service Error Dump,这一行以下的内容就是errorstack记录的错误堆栈!- 0 仅转储错误堆栈
- 1 转储错误堆栈和函数调用堆栈
- 2 Level 1 + ProcessState
- 3 Level 2 + Context area (一般我们诊断问题,都是使用这个级别的跟踪。)
- 实例级别: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跟踪文件中发现当前正在运行SQL文本。
- 从Errorstack跟踪文件中发现当前正在运行PL/SQL包和PL/SQL source code line number。
- 从Errorstack跟踪文件中发现当前bind variable value。
- 从Errorstack跟踪文件中发现一个cursor正在使用多少private memory(UGA)。
这一部分的内容主要參考tanelpoder大牛的博客。
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 ?
......为了排版,兴许省略......
这部分告诉你发生错误时Oracle在运行详细哪个PL/SQL过程(包or函数)以及errorstack跟踪过程中的详细哪个调用发生错误。这对我们诊断问题很有帮助
- object handle
- line number
- object name
0xfcfaebe8 7 procedure DBMON.P_DH2
0x10e7d6420 1 anonymous block
- 一个会话可能以某种方式变的很消耗CPU,而且会话的wait等待时间没有不论什么意义.
- 你须要调查什么SQL正在被运行,而且你须要查看SQL带有的绑定变量
- SQL的运行计划是正常的,可是性能却很低下
- 能够如果当某些表或者行源变的大的时候,存在数据倾斜。CBO没有计算出正确的运行计划。
errorstack跟踪文件里中包括CURSORDUMP,也就包括我们想要得到的bind variable value。
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 ?
......为了排版,兴许省略......
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。也就是这个查询运行的递归的深度
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跟踪文件里发现Cursor#2,它的state=BOUND。意味着绑定变量值已经被赋予的
- SQL文本是我们在前面已经查找出来的。我们能够看到两个绑定变量值
- Bind variale numbering是从0開始。所以假设我们想搜索第一个绑定值。须要搜索Bind#0
例如以下
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
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;
/
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
SQL > alter session set events = '1438 trace name errorstack forever,level 3';
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
[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