7

7343696

V1

2023/02/02阅读:16主题:默认主题

特殊恢复:通过Trace文件,定位触发报错的sql语句的执行计划、访问的数据库及等待事件

我们的文章会在微信公众号“Oracle恢复实录”和博客网站“www.htz.pw” 同步更新 ,欢迎关注收藏,也欢迎大家转载,但是请在文章开始地方标注文章出处,谢谢! 由于博客中有大量代码,通过页面浏览效果更佳。

下面分享来至于一个朋友的提问:数据库在启动过程中触发ORA-00704、ORA-00604、ORA-01555报错时,怎么通过Trace文件定位触发报错的sql的执行计划、等待事件及访问的数据块。

这个问题对于一些老司机来说比较简单,但是对于一些刚学习特殊恢复的人来说还是具有一些难度。

下面将使用原来在10.2.0.5的环境中模拟的ORA-00704、ORA-00604、ORA-01555的操作记录来回答这个问题。虽然数据库版本为10.2.0.5,但是此方法适合于9i及以后的版本,包括最新的21C的版本。

方法其实很简单,只需要搜几个关键字就可以找到报错的sql语句、执行计划、等待事件及访问的数据块。

1,测试版本

www.htz.pw > select * from v$version where rownum<3;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
PL/SQL Release 10.2.0.5.0 - Production
www.htz.pw > !lsb_release -a
LSB Version:    :core-4.0-amd64:core-4.0-ia32:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-ia32:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-ia32:printing-4.0-noarch
Distributor ID: RedHatEnterpriseServer
Description:    Red Hat Enterprise Linux Server release 4.8 (Tikanga)
Release:        4.8
Codename:       Tikanga

2,故障现象

Errors in file /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc:
ORA-00704: bootstrap process failure
ORA-00604: error occurred at recursive SQL level 1
ORA-01555: snapshot too old: rollback segment number 8 with name "_SYSSMU8$" too small

这里看到已经出现ORA-01555的报错,但是默认Trace文件中未包含我们需要的信息,此时需要我们开启10046 level 12、1555的errorstack level 12的日志。

3,配置10046与errorstack

www.htz.pw > oradebug setmypid
Statement processed.
www.htz.pw > oradebug event 10046 trace name context forever,level 12;
Statement processed.
www.htz.pw > oradebug event 1555 trace name errorstack forever,level 12;
Statement processed.
www.htz.pw > alter database open resetlogs;

在alert文件中可以发现下面的详细信息

ORA-01555 caused by SQL statement below (SQL ID: 2ajy4zgqrakrx, SCN: 0x0001.4000007b):
Sun Jul 20 22:16:45 CST 2014
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clucols,0),audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,blkcnt,empcnt,avgspc,chncnt,avgrln,analyzetime, samplesize,cols,property,nvl(degree,1),nvl(instances,1),avgspc_flb,flbcnt,kernelcols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spare6 from tab$ where obj#=:1
Sun Jul 20 22:16:45 CST 2014
Errors in file /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc:
ORA-01555: snapshot too old: rollback segment number 8 with name "???" too small
Sun Jul 20 22:16:47 CST 2014
Errors in file /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc:
ORA-01555: snapshot too old: rollback segment number 8 with name "_SYSSMU8$" too small
Sun Jul 20 22:16:48 CST 2014
Errors in file /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-01555: snapshot too old: rollback segment number 8 with name "_SYSSMU8$" too small
Sun Jul 20 22:16:48 CST 2014
Errors in file /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc:
ORA-00704: bootstrap process failure
ORA-00604: error occurred at recursive SQL level 1
ORA-01555: snapshot too old: rollback segment number 8 with name "_SYSSMU8$" too small

这里看到了报错的Trace文件。

4,查询详细信息

4.1 查找块与每个块的ITL信息

[root@www.htz.pw ~]#grep -E "^Block he|^0x0" /oracle/app/oracle/admin/asm10g/udump/asm10g_ora_4251.trc
Block header dump:  0x00400026
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000
Block header dump:  0x0040007c
0x01   0x0007.017.000000b3  0x008062d3.0093.2a  --U-    1  fsc 0x0000.00034536
Block header dump:  0x00400032
0x01   0x0004.029.000000ef  0x0080cfb0.00b9.02  C---    0  scn 0x0000.0005661e
Block header dump:  0x00400033
0x01   0x0005.00e.00000024  0x00800f39.0012.01  CB--    0  scn 0x0000.000109ca
0x02   0x0008.02d.000000d2  0x0080007e.00b9.05  --U-    1  fsc 0x0000.0005ed04
Block header dump:  0x00400026
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000
Block header dump:  0x004000ca
0x01   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0000.044.00000027  0x0040019f.0035.3b  --U-    1  fsc 0x0000.0005e5cc
Block header dump:  0x0040006a
0x01   0x0000.02e.0000002a  0x00400016.0037.19  --U-    1  fsc 0x0000.00075d1a
Block header dump:  0x00400026
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000
Block header dump:  0x0040007c
0x01   0x0007.017.000000b3  0x008062d3.0093.2a  --U-    1  fsc 0x0000.00034536
Block header dump:  0x00400032
0x01   0x0004.029.000000ef  0x0080cfb0.00b9.02  C---    0  scn 0x0000.0005661e
Block header dump:  0x00400033
0x01   0x0005.00e.00000024  0x00800f39.0012.01  CB--    0  scn 0x0000.000109ca
0x02   0x0008.02d.000000d2  0x0080007e.00b9.05  --U-    1  fsc 0x0000.0005ed04
Block header dump:  0x00400026
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000
Block header dump:  0x004000ca
0x01   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0000.044.00000027  0x0040019f.0035.3b  --U-    1  fsc 0x0000.0005e5cc
Block header dump:  0x0040006a
0x01   0x0000.02e.0000002a  0x00400016.0037.19  --U-    1  fsc 0x0000.00075d1a
Block header dump:  0x0040007c
0x01   0x0007.017.000000b3  0x008062d3.0093.2a  --U-    1  fsc 0x0000.00034536
Block header dump:  0x00400032
0x01   0x0004.029.000000ef  0x0080cfb0.00b9.02  C---    0  scn 0x0000.0005661e
Block header dump:  0x00400033
0x01   0x0005.00e.00000024  0x00800f39.0012.01  CB--    0  scn 0x0000.000109ca
0x02   0x0008.02d.000000d2  0x0080007e.00b9.05  --U-    1  fsc 0x0000.0005ed04
Block header dump:  0x00400026
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000
Block header dump:  0x004000ca
0x01   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0000.044.00000027  0x0040019f.0035.3b  --U-    1  fsc 0x0000.0005e5cc
Block header dump:  0x0040006a
0x01   0x0000.02e.0000002a  0x00400016.0037.19  --U-    1  fsc 0x0000.00075d1a

4.2 查看报错SQL的等待事件

=====================
PARSING IN CURSOR #2 len=343 dep=1 uid=0 oct=3 lid=0 tim=1372915825389474 hv=3983887101 ad='83688078'
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clucols,0),audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,blkcnt,empcnt,avgspc,chncnt,avgrln,analyzetime, samplesize,cols,property,nvl(degree,1),nvl(instances,1),avgspc_flb,flbcnt,kernelcols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spare6 from tab$ where obj#=:1
END OF STMT
EXEC #2:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1372915825389473
WAIT #2: nam='db file sequential read' ela= 254 file#=1 block#=38 blocks=1 obj#=4 tim=1372915825389837

这里可能会存在SQL语句多次执行的现象,那么此时需要关注执行的ID。

4.3 查看SQL的绑定变量信息

Bind#0这里就是绑定变量的编号,从0开始,value=255为绑定变量的值。

Cursor#2(0x2ba396ac1a88) state=FETCH curiob=0x2ba396adafc8
 curflg=8007 fl2=200000 par=0x2ba396ac1a20 ses=0x83b8f158
 sqltxt(0x83688078)=
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clucols,0),audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,blkcnt,empcnt,avgspc,chncnt,avgrln,analyzetime, samplesize,cols,property,nvl(degree,1),nvl(instances,1),avgspc_flb,flbcnt,kernelcols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spare6 from tab$ where obj#=:1
  hash=3a1c00e80fafeffb2547c4fbed754afd
  parent=0x8038f1d0 maxchild=01 plk=0x80b3f668 ppn=n
cursor instantiation=0x2ba396adafc8 used=1405865804
 child#0(0x83687e48) pcs=0x8038e7f0
  clk=0x80b259b0 ci=0x8038e4c8 pn=0x836ead50 ctx=0x7ff93148
 kgsccflg=1 llk[0x2ba396adafd0,0x2ba396adafd0] idx=fe
 xscflg=e01414f6 fl2=45000401 fl3=4022210c fl4=100
 Bind bytecodes
  Opcode = 1   Unoptimized
  Offsi = 48, Offsi = 0
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2ba3971a9ba0  bln=22  avl=03  flg=05
  value=255

4.4 查看SQL语句访问的块

查看报错时的正在访问的块,在上2步中,我们看到了Cursor#2,在10046中可以找到PARSING IN CURSOR #2,可以看到SQL的WAIT中WAIT #2: nam='db file sequential read' ela= 254 file#=1 block#=38 blocks=1 obj#=4 tim=1372915825389837,这就代表最后访问的一个块是1,38。最简单的版本我们也可以在相同的版本的处于open状态的数据库中去查询数据块所对应的对象信息,当然也可以在trace中以1/38去查看,能找到下面的信息:

BH (0x79ff8f58) file#: 1 rdba: 0x00400026 (1/38) class: 1 ba: 0x79f68000
  set: 3 blksize: 8192 bsi: 0 set-flg: 2 pwbcnt: 0
  dbwrid: 0 obj: 2 objn: 4 tsn: 0 afn: 1
  hash: [833bebb8,833bebb8] lru: [79ff90e8,79ff8ec8]
  obj-flags: object_ckpt_list
  ckptq: [829a5d30,829a5d30] fileq: [829a5d50,829a5d50] objq: [80b4d860,80b4d860]
  use: [829956a0,829956a0] wait: [NULL]
  st: XCURRENT md: SHR tch: 0
  flags: buffer_dirty redo_since_read
  LRBA: [0x1.3.0] HSCN: [0x1.4000007b] HSUB: [1]
  buffer tsn: 0 rdba: 0x00400026 (1/38)
  scn: 0x0001.4000007b seq: 0x01 flg: 0x00 tail: 0x007b0601
  frmt: 0x02 chkval: 0x0000 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1

再以0x00400026能查找到下面信息

Block header dump:  0x00400026
 Object id on Block? Y
 seg/obj: 0x2  csc: 0x01.4000007b  itc: 2  flg: -  typ: 1 - DATA
     fsl: 0  fnx: 0x0 ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0000.007.00000011  0x00400017.0019.43  C---    0  scn 0x0000.000008f6
0x02   0x0008.012.000000fe  0x008009f2.00dd.02  ----    2  fsc 0x0000.00000000

到此时,触发报错的数据块的信息已经找到了。

分类:

后端

标签:

数据库

作者介绍

7
7343696
V1