以前写过一篇文章是关于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的。详情可见下图：
在后台我们还可以看到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子系统异常。