早上收到数据库报告,分析最后的结论是18点到19点,系统处于不可用的状态。19点到20点情况数据库负载比起之前一个小时降低了很多。数据库负载高的根本原因是数据泵expdp备份导致。
Snap Id | Snap Time | Sessions | Cursors/Session | |
---|---|---|---|---|
Begin Snap: | 31722 | 07-May-13 18:00:31 | 259 | 19.6 |
End Snap: | 31723 | 07-May-13 19:00:47 | 273 | 20.4 |
Elapsed: | 60.25 (mins) | |||
DB Time: | 8,796.21 (mins) |
Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
---|---|---|---|---|---|
latch: cache buffers chains | 883,811 | 173,470 | 196 | 32.9 | Concurrency |
CPU time | 14,125 | 2.7 | |||
wait list latch free | 51,245 | 1,241 | 24 | .2 | Other |
db file sequential read | 1,915,255 | 768 | 0 | .1 | User I/O |
latch free | 2,558 | 517 | 202 | .1 | Other |
分析18:00-19:00的AWR报告,分析TOP5等待事件latch: cache buffers chains排在第一位,等待时长为173,470s。数据库在取数据块时为了保护内存的数据结构而加了latch(一种锁,很短暂),当SQL逻辑读过高,在并发的情况下大家都要去相同的数据块而产生等待事件。
然后分析SQL执行时间的排行,发现都是试验模块的SQL,四月份也发生过类似的问题。对比4月22日11:00-12:00数据库CPU 100%的报告,当时latch: cache buffers chains等待时长是11,720s。相比之下,4月22日的SQL并发比5月7日的要大,而等待的时间却只是7日的十分之一。继续分析发现BEGIN SYS.KUPW$WORKER.MAIN('FULL126', 'SYSTEM'); END; ,这说明此时数据泵正在执行。
问题变得明朗,expdp需要全表扫,要把数据块都读到内存中,进行导出,当进入内存后,expdp获得了数据块的latch,但是这时候有个大sql进来了,要访问的数据块expdp正在访问,大SQL也要获得latch,虽然latch很快,但是此时访问的特别多,然后悲剧就发生了。
给出的建议:
现在备份是18:00,要调到晚一点,越少用户使用越好。