Skip to content

一次诡异的log file sync分析处理

以前写过一篇文章是关于Log File Sync的，详情可见《关于log file sync的解惑》。但是这篇文章并不足以解释所有log file sync的问题，有些问题比较诡异，比较难以定位。今天我分享的这个案例就是一个比较诡异的例子。首先还是来交待一下背景。

背景介绍：

客户反馈数据库运行缓慢，系统是一套Solaris上的10.2.0.4的RAC。

问题原因分析

Top 5 Timed Events

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
db file sequential read 275,305 17,973 65 42.7 User I/O
log file sync 221,528 17,447 79 41.5 Commit
CPU time   7,725   18.4  
gcs log flush sync 170,027 941 6 2.2 Other
read by other session 565 343 608 .8 User I/O

我们可以看到AWR报告中,等待事件db file sequential read和log file sync都很严重。这两个等待事件同时出现，我们首先应该怀疑是否I/O出现了问题。因为我们以前介绍过log file sync等待事件中是包含了log file parallel write的。详情可见下图：

捕获1

在后台我们还可以看到lgwr的trace,写几KB的数据都需要7-18秒的时间。

Warning: log write time 770ms, size 10KB
*** 2014-01-11 14:33:05.287
Warning: log write time 18780ms, size 2KB
*** 2014-01-11 14:33:10.241
Warning: log write time 760ms, size 1KB
*** 2014-01-11 14:34:49.333
Warning: log write time 22850ms, size 2KB
*** 2014-01-11 14:34:51.692
Warning: log write time 1650ms, size 104KB
*** 2014-01-11 14:36:23.280
Warning: log write time 16680ms, size 3KB
*** 2014-01-11 14:36:31.259
Warning: log write time 660ms, size 8KB
*** 2014-01-11 14:38:02.595
Warning: log write time 16090ms, size 9KB
*** 2014-01-11 14:38:11.100
Warning: log write time 740ms, size 6KB
*** 2014-01-11 14:39:45.532
Warning: log write time 19130ms, size 2KB
*** 2014-01-11 14:39:51.275
Warning: log write time 780ms, size 9KB

同时，我们做了一个ADDM报告出来，ADDM报告显示:

The throughput of the I/O subsystem was significantly lower than expected.

但是很奇怪的一个地方在于，我们看到AWR关于log file parallel write等待事件的时间确是很低的。

Wait Events

  • s – second
  • cs – centisecond – 100th of a second
  • ms – millisecond – 1000th of a second
  • us – microsecond – 1000000th of a second
  • ordered by wait time desc, waits desc (idle events last)
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
log file sync 134,365 78.54 10,530 78 0.41
db file sequential read 110,506 0.00 7,029 64 0.34
gcs log flush sync 58,364 99.28 393 7 0.18
read by other session 388 77.58 309 796 0.00
Streams AQ: qmn coordinator waiting for slave to start 8 100.00 44 5561 0.00
gc cr grant 2-way 45,633 0.00 35 1 0.14
gc current block 2-way 23,397 0.03 33 1 0.07
SQL*Net more data from dblink 14,193 0.00 29 2 0.04
db file scattered read 2,166 0.00 27 12 0.01
enq: TX – index contention 67 67.16 23 338 0.00
SQL*Net break/reset to client 84,010 0.00 22 0 0.26
log file parallel write 27,989 0.00 22 1 0.09

在这里我们可以看到我们的log file parallel write的时间是1ms，这也就间接说明了这不是I/O的问题，那为什么反映到数据库的层面就会显示是I/O subsystem的问题呢？在这期间，主机工程师和存储工程师都已经到达现场，他们分别检查了主机和存储，均未发现有任何重大报错，那究竟是为什么呢？为了排除存储方面可能出现的问题，我们把联机日志切换到本地的归档目录上（归档目录是另外一组磁盘，但是属于同一存储），居然意外的发现在这个过程中lgwr的后台trace不再出现,log file sync的等待事件大大的减少。同时我们还做了测试对数据文件进行dd，发现dd的速度很快，能够达到150m/s。究竟在那个地方出了问题？这个疑惑我们一直没解开。这期间我们开了1级的sr，sr认为可能是数据库的bug。它让我们打patch 7716356，我们打完了patch，做了压力测试，结果效果没有任何改善，我们只得回退了这个patch。

经过了一夜的奋战，我们把日志全部切换到本地的归档目录下面，大大的减少了log file sync的等待，数据库性能立马提升了不少。但是在第二天白天的业务高峰期，db sequential read的等待依然非常高。由于对数据文件的直接dd很快，能达到150m/s，我们怀疑是操作系统的卷管理软件和数据库交互出了问题，也许这会是个卷管理方面的bug也说不定。

同时sr这边也无任何进展，只是丢下了下面的话。我们也不能太难为别人，有些问题确实不在别人的管辖范畴。

It is caused by bad IO performance. 
It is not only impacting log file sync , but whole database. 
You have an I/O issue. It is clear with no doubt about it. 
You should contact the System Admin or Storage Admin and ask them to look into this I/O issue.This is not ORACLE GCS's skill.

确实，这个问题很诡异，基本表象就是在文件系统上速度还可以，切换到裸设备就很慢。主机的人反馈，说卷管理软件没有任何问题。到了这个时候，我们没有任何办法，我们只能对lgwr的进程进行一次跟踪，我们把日志重新切换到裸设备上。用truss进行了一番跟踪，发现以下的一些情况。

truss -faied -D -o /tmp/trace.out -p 3842
Base	time	stamp:	1389629043		Tue	Jan	14	0:04:03	CST	2014
29396/1:	siginfo:	SIG#0								
29396:	psargs:	ora_lgwr_crmdb1								
29396/1:	175.1173 12.0148   kaio(AIOWRITE,	781,	0x381816600,	18432,	0x12782E0075D35F78)	=	0	
29396/1:	75.9295	11.3157	kaio(AIOWRITE,	781,	0x38375F000,	3072,	0x0EBA6C0075310CC8)	=	0	
29396/1:	56.5273	0.8171	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	34.3783	0.8128	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	88.3386	0.7186	kaio(AIOWRITE,	781,	0x384595200,	3584,	0x0F9DCE0075D35F78)	=	0	
29396/1:	4.0285	0.6533	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	24.1029	0.5437	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	6.1927	0.4387	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	29.0257	0.4326	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	14.5962	0.4276	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	58.0465	0.4226	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	1.5617	0.3887	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	32.7292	0.3787	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	5.0998	0.3746	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	7.6984	0.3721	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	8.1882	0.3651	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	23.1245	0.365	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	23.4913	0.3627	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	4.57	0.3616	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	39.2142	0.3601	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	Err#11	EAGAIN		
29396/1:	18.5615	0.3599	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	2.1535	0.3592	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	12.0821	0.3453	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	7.0096	0.3365	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0		
29396/1:	6.5327	0.3357	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=	0

我们做了3分钟的trace，并按照时间进行了排序，从这儿我们可以看到在裸设备上面，需要调用kaio函数去实现异步I/O写的操作，有2次操作出现了异常，分别需要12秒和11秒的时间。所以我们由此推断：solaris内核模块kaio(kernel Async I/O)出现了异常，导致函数aiowrite运行缓慢。同时主机的人也反馈了一个重要的事情。出问题之前曾经出现了内存问题，当时他们把出错的内存给屏蔽禁用掉了。这个出错时间和我们出问题的时间比较吻合。于是主机的人把趁着晚上的时间把内存进行了跟换并进行了重启。到了白天，系统的性能运行良好，所有的等待全部都变成了正常值。所以这个问题最终被定位成了内存损坏导致的？那么内存损坏怎么会导致异步I/O模块出问题呢？事实上最后主机的人给我们的解释是：当执行一个异步I/O写的操作，首先是写到内存里面，内存发生改变，然后在写I/O，当写到坏的内存的时候就会慢那么一点点，但是这些东西反馈到数据库层面就是I/O子系统异常。

分享到： 更多