如何阅读Oracle Errorstack Output

最新推荐文章于 2021-04-10 07:31:08 发布

置顶出埃及

最新推荐文章于 2021-04-10 07:31:08 发布

阅读量919

点赞数 1

分类专栏： Oracle Internal and Scripts 文章标签： oracle output session sql delete function

Oracle Internal and Scripts 专栏收录该内容

3 篇文章 0 订阅

订阅专栏

Wirte By tanelpoder,translation by me.
当oracle发生关键的错误诸如：ora-600，Errorstack dump是自动被oracle dump。当你在alert.log里面看见错误，将产生trace文件，trace中以“ksedmp:internal or fatal
error"开头，诸如这样的错误(ORA-7445或者ORA-600附有一些参数)。"kesdmp"意味着Kernel Service Error Dump，所以此行下面的就是errorstack dump。
Errorstack dump也可以被手动的调用通过使用Oradebug dump errorstack 3(当使用Oradebug setospid设定了目标进程之后)。Oradebug Errorstack对于当一个session似乎Hang(
但是在v$session_wait里面并未出现合理的wait event)或者是比正常时消耗更多资源并且你想知道当前sql的具体变量值。

Errorstack trace文件有很多信息，对于我们troubleshooting或多或少都有用。但是大量的数据和二进制的转储可能使你摸不着头脑，这里我将给你展示可以理解的一些结构。
在这片文章里我们将探讨以下话题：
1.从errorstack trace file中发现当前正在执行SQL文本。
2.从errorstack trace file中发现当前正在执行PL/SQL package和PL/SQL source code line number。
3.从errorstack trace file中发现当前bind variable value。
4.从errorstack trace file中发现一个cursor正在使用多少private memory(UGA)。

我将在下面的阐述中粘贴一个errorstack dump的相关部分。
1.从errorstack trace file中发现当前正在执行SQL文本。
你将非常容易找到当前sql的文本信息，这个语句在tracefile的前端("Current SQL statement for this session")部分：

*** 2010-02-14 15:30:32.830
*** SERVICE NAME:(SOL102) 2010-02-14 15:30:32.829
*** SESSION ID:(156.974) 2010-02-14 15:30:32.829
Received ORADEBUG command 'dump errorstack 3' from process Unix process pid: 8556, image:
*** 2010-02-14 15:30:32.830
ksedmp: internal or fatal error
Current SQL statement for this session:
DELETE FROM MYTAB WHERE OWNER = :B1

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
38d172270         8  function SYS.DELETE_FUNC
38d1518f0         1  anonymous block
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst()+23          ?        0000000000000001     0017B342C 000000000 0FFDF2420
                                                   0FFFFFD7F
ksedmp()+636         ?        0000000000000001     0017B1EC1 000000000 00601C7E0
                                                   000000000
ksdxfdmp()+1062      ?        0000000000000001     0018A3F03 000000000 00601C7E0
                                                   000000000
ksdxcb()+1238        ?        0000000000000001     0018A22D3 000000000 0FF2DCC80
....

2.从errorstack trace file中发现当前正在执行PL/SQL package和PL/SQL source code line number。

*** 2010-02-14 15:30:32.830
ksedmp: internal or fatal error
Current SQL statement for this session:
DELETE FROM MYTAB WHERE OWNER = :B1

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
38d172270         8  function SYS.DELETE_FUNC
38d1518f0         1  anonymous block

----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst()+23          ?        0000000000000001     0017B342C 000000000 0FFDF2420
                                                   0FFFFFD7F
ksedmp()+636         ?        0000000000000001     0017B1EC1 000000000 00601C7E0
                                                   000000000
ksdxfdmp()+1062      ?        0000000000000001     0018A3F03 000000000 00601C7E0

如果dump的tracefile中这个进程是一个PL/SQL调用，那么PL/SQL调用堆也被dump(在PL/SQL Call Stack部分)。这部分告诉你当错误发生时Oracle在执行那个PL/SQL过程以及
dump的时候过程中的那个调用发生错误。
PL/SQL call stack报告3列：
1.object handle
object handle是这个对象(PL/SQL存储过程或者匿名块)被load进library cache中的地址。你可以通过映射这个地址通过X$KGLOB.KGLHDADR以发现那个对象是正在被处理。
然而对象的owner和name是在第三列被报告。
2.line number
这个是非常重要的信息，它将告诉你当errorstack dump发生时正在执行的精确的PL/SQL source code。例如，在如上的输出中，这个匿名块调用了SYS.DELETE_FUNC在第一行(
匿名块的第一行)。当errorstack dump发生时正在执行SYS.DELETE_FUNC的PL/SQL source code的第八行。
3.object name
PL/SQL存储的对象名(或者匿名块，当对象并没有存储在一个过程中).当是匿名块的情况下(匿名块的文本可以通过V$SQL发现),你可以关联这个地址和V$SQL.ADDRESS来发现匿名块的文本信息。

以上的PL/SQL call stack仅仅包含两行。
38d172270 8 function SYS.DELETE_FUNC
38d1518f0 1 anonymous block
你应该从下而上来阅读一个PL/SQL call stack：
1.底部的行可以告诉我们正在执行一个匿名块以及在这个匿名块的第一行，它在调用这个函数(SYS.DELETE_FUNC)。
2.顶部信息告诉我们SYS.DELETE_FUNC是正在执行，在第八行导致了错误，errorstack信息被转储。
通过查询DBA_SOURCE，我们可以从dump和行号等信息中发现这个对象的owner和name。
SQL> select line, text
2 from dba_source
3 where owner = 'SYS'
4 and name = 'DELETE_FUNC'
5 -- and line between X and Y
6 and type = 'FUNCTION' -- PROCEDURE,PACKAGE BODY,TYPE BODY
7 order by line asc
8 /

      LINE TEXT
---------- -------------------------------------------------------------------
         1 function delete_func (owner_name in varchar2) return number
         2 as
         3    num_deleted number;
         4 begin
         5    -- this is a demo procedure
         6    -- it does not do anything useful!
         7
         8    DELETE FROM mytab WHERE owner = owner_name;
         9    COMMIT;
        10
        11    num_deleted := SQL%ROWCOUNT;
        12    DBMS_OUTPUT.PUT_LINE('Deleted rows ='|| TO_CHAR(num_deleted));
        13
        14    return num_deleted;
        15 end;
15 rows selected.

你可以发现dump中正在执行的PL/SQL第八行(递归的DELETE查询).
通常,当error dump，crash，hang发生时(顶部的行是”parent"function调用的“child”function正在执行的代码)，PL/SQL errorstack告诉我们精确的PL/SQL code。
3.从errorstack trace file中发现当前bind variable value
这个问题是经常被问的，让我来这样回答：
1.一个session可能一某种方式变的非常消耗CPU,并且没有任何有意义的wait event.
2.所以你需要调查什么SQL正在被执行并且你需要查看SQL带有的绑定变量.
3.SQL的执行计划是正常的，但是性能却机器糟糕。
4.可以假设当某些表或者行源变的大的时候，存在数据倾斜，CBO没有计算出正确的执行计划。
所以，你需要知道当问题发生时SQL使用的绑定变量是什么，不幸的是并没有一个V$视图让我们去查看某个session的当前绑定变量值。如果你考虑使用V$SQL_BIND_CAPTURE,你就错了(它仅仅随机的采样绑定变量值，并不存储所有的被使用的绑定变量值).

Oracle 11gR2中实时的SQL Monitoring特性能够大道此目的。在V$SQL_MONITOR中有一列BIND_XML,此列包含正在运行的足够长时间(默认占用CPU超过5s的SQL，都会出现在次视图中)的bind variable values.但是这个只有在11gR2并且具有Diag+Tuning pack licenses时才有效。
为什么我们不能跟踪到绑定变量值的原因在于绑定变量值存在于进程的private memory。所以我们不能很容易的跟踪另一个进程private memory。这也是为什么我们使用ORADEBUG连接到出现问题的进程并且发出信号，使得它dump errorstack。很幸运的dump tracefile中包含CURSORDUMP,包含bind variable value。
注：关于V$SQL_MONITOR,我写过一篇blog，参见：V$SQL_MONITOR
下面的例子中，数字8213是我们将要dump的问题session的OS PROCESS ID(V$PROCESS.SPID)：
SQL> oradebug setospid 8213
Oracle pid: 15, Unix process pid: 8213, image: oracleSOL102@solaris02
SQL> oradebug dump errorstack 3
Statement processed.
当然，如果你诊断CRASH或者ORA-600(错误已经发生，dump file已经存在)你肯定不需要使用ORADEBUG。继续看看如下dump：

*** 2010-02-14 15:30:32.830
ksedmp: internal or fatal error
Current SQL statement for this session:
DELETE FROM MYTAB WHERE OWNER = :B1
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
38d172270         8  function SYS.DELETE_FUNC
38d1518f0         1  anonymous block
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst()+23          ?        0000000000000001     0017B342C 000000000 0FFDF2420
                                                   0FFFFFD7F
ksedmp()+636         ?        0000000000000001     0017B1EC1 000000000 00601C7E0
                                                   000000000
ksdxfdmp()+1062      ?        0000000000000001     0018A3F03 000000000 00601C7E0
                                                   000000000
ksdxcb()+1238        ?        0000000000000001     0018A22D3 000000000 0FF2DCC80
                                                   0FFFFFD7F
....

当打开trace file，我通常做的是搜索第一个"Session Cursor Dump",当我搜索它的时候，我将看到如下的输出：

******************** Session Cursor Dump **********************
Current cursor: 6, pgadep: 1
Open cursors(pls, sys, hwm, max): 5(3, 1, 64, 300)
 NULL 1 SYNTAX 0 PARSE 0 BOUND 4 FETCH 0 ROW 0
Cached frame pages(total, free):
 4k(41, 38), 8k(1, 1), 16k(1, 1), 32k(0, 0)
  pgactx: 38cc705e0 ctxcbk: 38cc701f0 ctxqbc: 0 ctxrws: 39392a188
Explain plan:

Dumping stream from 0 to 97
----------------------------------

0000: 143 136 161 146 147   3   0   0   0 137 119   1   0  16   0   0   0   3   1   2    ..........w.........
0020:   0   0   0   0   0  59   7   3   6   3 121 101 115   5   9   1   1   3  83  89    .....;....yes.....SY
0040:  83  12   8 106 108 109 224 152 228 163 113 111   3   2   3   3   2   0   0 143    S..jlm....qo........
0060:  56 164 146 147   3   0   0   0 134 116   2  38  24 133  86 229  24 144 100 133    8........t.&..V...d.
0080:  81 193 219 234 223 154 138   3   1   2 192 214 188   3   2  14 142                Q................
============
Plan Table
============
--------------------------------------+-----------------------------------+
| Id  | Operation           | Name    | Rows  | Bytes | Cost  | Time      |
--------------------------------------+-----------------------------------+
| 0   | DELETE STATEMENT    |         |       |       |  1366 |           |
| 1   |  DELETE             | MYTAB   |       |       |       |           |
| 2   |   TABLE ACCESS FULL | MYTAB   |  119K | 2023K |  1366 |  00:00:17 |
--------------------------------------+-----------------------------------+

我们可以发现Current cursor:6,这个告诉我们在此session的UGA中打开的cursor中正在执行Cursor#6.
the pgadep：1变量告诉我们PGA depth，也就是这个查询执行的递归的深度。如果pgadep是0，它意味着这个查询是一个top-level查询，正在被用户或者应用通过OCI接口在执行。pgadep为1以为这个它是一个递归的查询，通过递归程序接口(RPI)来执行，可能是数据字典查询或者仅仅是被通过PL/SQL执行的SQL。
所以，能够发现当前正在执行的当前查询的绑定变量值，我们需要做的是在trace file中朝前搜索Cursor6#，记住：这个是大小写敏感的。

Cursor#6(fffffd7ffddb1918) state=BOUND curiob=fffffd7ffdd0f380
 curflg=cd fl2=0 par=0 ses=398f72fe8
 sqltxt(38d15d0f8)=DELETE FROM MYTAB WHERE OWNER = :B1
  hash=332a8a504bccd7f1a4a726a2879e71d9
  parent=38ca516d0 maxchild=01 plk=395bf4dd8 ppn=n
cursor instantiation=fffffd7ffdd0f380 used=1266132628
 child#0(38d151620) pcs=38ca512e0
  clk=395b767b8 ci=38ca509c8 pn=38d179e58 ctx=38cc705e0
 kgsccflg=0 llk[fffffd7ffdd0f388,fffffd7ffdd0f388] idx=0
 xscflg=c0110676 fl2=1d120000 fl3=4228218c fl4=100
 Bind bytecodes
  Opcode = 6   Bind Rpi Scalar Sql In(may be out) Nocopy NoSkip
  Offsi = 48, Offsi = 0
kkscoacd
 Bind#0
  oacdty=01 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=01 csi=31 siz=32 off=0
  kxsbbbfp=fffffd7ffdd31808  bln=32  avl=03  flg=09
  value="SYS"
 Frames pfr fffffd7ffdd3f8c0 siz=4488 efr fffffd7ffdd3f800 siz=4464
  enxt: 3.0x000004b0  enxt: 2.0x00000020  enxt: 1.0x00000ca0
  pnxt: 2.0x00000008  pnxt: 1.0x00000010
 kxscphp  fffffd7ffddc0388 siz=984 inu=472 nps=344
 kxscbhp  fffffd7ffdcef1a8 siz=1008 inu=120 nps=0
 kxscwhp  fffffd7ffddc0748 siz=10496 inu=6608 nps=6608

1.我们已经发现Cursor#6从trace file中，它的state=BOUND，意味着绑定变量值已经被赋予的。
2.SQL文本是我们在前面已经查找出来的，我们可以看到仅仅一个绑定变量值(它是被PL/SQL执行引擎自动的放置).
3.Bind variale numbering是从0开始，所以如果我们想去卡第一个绑定值，我们需要搜索Bind#0。
这是我们可以系统化和很可靠的找到被使用的绑定变量值。
4.从errorstack trace file中发现一个cursor正在使用多少private memory(UGA)
最后，我们继续前面的例子，我们能够度量某个session的某些游标使用了多少UGA私有内存。

Cursor frame dump
  enxt: 3.0x000004b0  enxt: 2.0x00000020  enxt: 1.0x00000ca0
  pnxt: 2.0x00000008  pnxt: 1.0x00000010
 kxscphp  fffffd7ffddc0388 siz=984 inu=472 nps=344
 kxscbhp  fffffd7ffdcef1a8 siz=1008 inu=120 nps=0
 kxscwhp  fffffd7ffddc0748 siz=10496 inu=6608 nps=6608

在cursor frame dump部分我们可以看见kxsc开始的一些信息，这些意味着Kernel eXECUTION Shared Cursor。其中的每一行的siz告诉我们当前分配的私有内存大小。当然，我们需要汇总所有的siz，这个值就是此游标的memory usage。
下面是我的一些猜测汇总：

Heap description     Meaning
kxscphp              Cursor permanent heap. Allocated when cursor is opened   
kxscdfhp             Cursor default heap - default duration allocations
kxscehp              Cursor ephemeral heap - short lived duration allocations
kxscwhp              Cursor Work heap - used when actually executing the cursor (workareas etc)
kxscbhp              Cursor Bind heap - this is where bind variable values and their metadata are kept.

出埃及

关注

1
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
如何阅读Oracle Errorstack Output

Wirte By tanelpoder,translation by me.当oracle发生关键的错误诸如：ora-600，Errorstack dump是自动被oracle dump。当你在alert.log里面看见错误，将产生trace文件，trace中以“ksedmp:internal or fatalerror"开头，诸如这样的错误(ORA-7445或者ORA-600附有一些参数
复制链接

扫一扫