记一次Exadata故障

来源：互联网发布：淘宝暴龙眼镜编辑：程序博客网时间：2024/05/17 00:13

懒得整理了，直接把故障分析报告黏贴上来了。

【故障基本信息描述】

故障基本信息

2012年8月07日上午08:15左右，系统管理员接到后置应用人员反映批处理出现了异常，经检查发现是数据库服务器的根目录/和oracle软件安装目录/u01都满了，临时删除一些日志后后置批处理继续。影响时间：2012-08-07.04:00 – 2012-08-07.08:30，共计3小时30分。

故障处理过程

2012年8月07日

【约08:15】后置应用人员通知系统管理员，批处理出现了异常，要求协助处理。

【约08:25】经排查发现是由于数据库服务器1的根目录/和oracle软件安装目录/u01都写满了所致。

【约08:30】临时删除掉一些日志后批处理继续进行。

【约09:30】经过统计发现根目录/的实际使用空间仅为10G，而系统上显示的却是已使用了39G，怀疑是根目录上的文件被删除后空间没有被释放。

【约11:00】经过排查发现的确是oracle用户的sendmail进程占据了约20G的临时文件没有被释放，把oracle用户的sendmail进程kill掉后空间释放。

【约13:10】经排查发现oracle软件安装目录/u01满了是由于当前数据库节点在system级别设置了10046 event所致。

【约13:20】把system级别的10046 event关闭就不会再记录那么多trace日志。

系统分析

2012年08月07日早上04:00至2012年08月07日上午8:30，后置批处理出现了异常，原因是由于数据库服务器1的根目录/和oracle软件安装目录/u01都被写满所致，问题分析过程如下：

问题1，oracle软件安装目录/u01被写满：

/u01目录被写满是由于记录了过多的trace日志所致，这些日志中最大的可达20G，而/u01目录的大小只有100G：

[root@dm01db01 trace]# du -sm *|awk '{if ($1 > 256){print $1" "$2}}'

1143 SRCBFIN1_j001_77325.trc

2588 SRCBFIN1_lck0_12400.trc

2753 SRCBFIN1_lms0_12338.trc

2726 SRCBFIN1_lms1_12343.trc

1053 SRCBFIN1_ora_71039.trc

20713 SRCBFIN1_ora_71049.trc

1326 SRCBFIN1_ora_71051.trc

1048 SRCBFIN1_ora_71055.trc

截取部分trace日志内容如下：

[root@dm01db01 trace]# tail -1000 SRCBFIN1_ora_71049.trc  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414363274FETCH #47110460361400:c=1000,e=91,p=0,cr=6,cu=0,mis=0,r=1,dep=2,og=1,plh=3657960566,tim=1344247414363381CLOSE #47110460361400:c=0,e=1,dep=2,type=3,tim=1344247414363407BINDS #47110460361400: Bind#0  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=64 off=0  kxsbbbfp=2ad8c182d5c0  bln=32  avl=03  flg=05  value="CNY" Bind#1  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414365769FETCH #47110460361400:c=0,e=88,p=0,cr=6,cu=0,mis=0,r=1,dep=2,og=1,plh=3657960566,tim=1344247414365872CLOSE #47110460361400:c=0,e=1,dep=2,type=3,tim=1344247414365895BINDS #47110460361400: Bind#0  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=64 off=0  kxsbbbfp=2ad8c182d5c0  bln=32  avl=03  flg=05  value="CNY" oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414377423FETCH #47110460361400:c=0,e=88,p=0,cr=6,cu=0,mis=0,r=1,dep=2,og=1,plh=3657960566,tim=1344247414377526CLOSE #47110460361400:c=0,e=2,dep=2,type=3,tim=1344247414377549BINDS #47110460361400: Bind#0  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=64 off=0  kxsbbbfp=2ad8c182d5c0  bln=32  avl=03  flg=05  value="CNY" Bind#1  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414377628FETCH #47110460361400:c=0,e=87,p=0,cr=6,cu=0,mis=0,r=1,dep=2,og=1,plh=3657960566,tim=1344247414377731CLOSE #47110460361400:c=0,e=2,dep=2,type=3,tim=1344247414377754BINDS #47110460361400: Bind#0  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=64 off=0  kxsbbbfp=2ad8c182d5c0  bln=32  avl=03  flg=05  value="CNY" Bind#1  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414377831FETCH #47110460361400:c=0,e=86,p=0,cr=6,cu=0,mis=0,r=1,dep=2,og=1,plh=3657960566,tim=1344247414377933CLOSE #47110460361400:c=0,e=1,dep=2,type=3,tim=1344247414377956BINDS #47110460361400: Bind#0  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=64 off=0  kxsbbbfp=2ad8c182d5c0  bln=32  avl=03  flg=05  value="CNY" Bind#1  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00  oacflg=03 fl2=1206001 frm=01 csi=871 siz=0 off=32  kxsbbbfp=2ad8c182d5e0  bln=32  avl=06  flg=01  value="201201"EXEC #47110460361400:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=3657960566,tim=1344247414378036FE[root@dm01db01 trace]#

通过日志的内容怀疑是数据库在system级别启用了10046 event trace，通过alter日志发现的确是在8月3日启用system级别的10046 event trace：

Fri Aug 03 18:16:48 2012

OS Pid: 95899 executed alter system set events '10046 trace name context forever,level 12'

使用以下命令检查当前的event 级别：

SRCBFIN1@SYS> oradebug setmypid

SRCBFIN1@SYS> oradebug eventdump system

sql_trace level=12

原来数据库管理员最近在协助oracle工程师分析后置Exadata上使用insert /*+ append */效率低的问题，需要进程抓取一些10046 event trace，本来是要设置成session级别的但是错误的写成了system级别，然后没有及时关闭，才导致了后续新建立的连接都会以及其详细的日志进行记录，最终导致了/u01目录由于没有及时清理而被写满，从而造成了8月7日后置批处理异常。

使用如下命令关闭10046 event trace：

alter system set events '10046 trace name context off';

同时oracle工程师建议把trace日志大小进行限制，即建议修改系统参数max_dump_file_size值大小为1G(=2097152个文件系统块大小(512字节，select max(lebsz) os_block_size from x$kccle;))，这些参数都是即时生效。

alter system set max_dump_file_size=2097152 scope=both sid='*';

问题2，根目录/被写满：

对根目录/进行du统计发现/var/目录空间使用率最大，经过逐层过滤后发现是/var/spool/clientmqueue目录里面的一个临时文件比较大，达到20G：

[root@dm01db01 clientmqueue]# ls -l dfq76AUB4H003918

-rw-rw---- 1 oracle smmsp 20224466944 Aug 5 13:30 dfq755U1Tg026331

于是把这个文件删除，但是还是发现根目录的空间并没有被释放：

[root@dm01db01 /]# df

Filesystem Size Used Avail Use% Mounted on

/dev/mapper/VGExaDb-LVDbSys1

30G 27G 1.3G 96% /

/dev/sda1 502M 30M 447M 7% /boot

/dev/mapper/VGExaDb-LVDbOra1

99G 63G 31G 68% /u01

tmpfs 81G 48G 33G 60% /dev/shm

/dev/mapper/VGExaDb-LVDbBak1

30G 315M 28G 2% /backup

hzhisdb:/hisbackup 5.0T 4.7T 389G 93% /hisbackup

hzhisdb:/exbak 4.9T 3.2T 1.8T 64% /exbak

经过排查发现这个文件仍然被oracle的sendmail进程所占用：

[root@dm01db01 /]# lsof | grep deleted

oracle 463 oracle 14w REG 253,3 3924 9373151 /u01/app/oracle/diag/rdbms/srcbfin/SRCBFIN1/trace/SRCBFIN1_ora_463.trc (deleted)

oracle 463 oracle 15w REG 253,3 618 9373152 /u01/app/oracle/diag/rdbms/srcbfin/SRCBFIN1/trace/SRCBFIN1_ora_463.trm (deleted)

sendmail 3918 oracle 3uW REG 253,0 20224466944 3867381 /var/spool/clientmqueue/dfq76AUB4H003918 (deleted)

杀掉改进程后空间被释放：

[root@dm01db01 /]# kill -9 3918