由一条sql语句导致的系统IO问题(r3笔记第31天)
公众号：杨建荣的学习笔记 · 作者：r3笔记第31天 · 发布：2014-10-20 18:28:54 · 原文链接
早上来到公司，照例进行了简单的检查，发现系统负载不高，就开始计划一些sql tuning的工作，但是过了一会,在通过shell命令查找一些sql信息的时候，发现系统的反应有些慢，当时也没在意，当我查看v$session都开始慢的时候，感觉哪里出了什么问题了，最直观的感受就是一些命令的运行都很缓慢了。
首先查看了一下数据库的负载，发现在最近的一个多小时内负载高了很多。几乎是几十倍的速度。
BEGIN_TIME————————- END_TIME————————— ELAPSED_TIME- BTIME—– WORKLOAD_PER——–
———————————– ———————————– ————- ———- ——————–
15599 ** 20-OCT-14 01.00.05.479 AM 15600 ** 20-OCT-14 02.00.07.824 AM 60.039 266.29 443%
15600 ** 20-OCT-14 02.00.07.824 AM 15601 ** 20-OCT-14 03.00.10.947 AM 60.052 215.22 358%
15601 ** 20-OCT-14 03.00.10.947 AM 15602 ** 20-OCT-14 04.00.14.461 AM 60.059 214.85 357%
15602 ** 20-OCT-14 04.00.14.461 AM 15603 ** 20-OCT-14 05.00.18.115 AM 60.061 209.35 348%
15603 ** 20-OCT-14 05.00.18.115 AM 15604 ** 20-OCT-14 06.00.21.252 AM 60.052 962.13 1602%
15604 ** 20-OCT-14 06.00.21.252 AM 15605 ** 20-OCT-14 07.00.24.555 AM 60.055 599.99 999%
15605 ** 20-OCT-14 07.00.24.555 AM 15606 ** 20-OCT-14 08.00.26.581 AM 60.034 549.54 915%
15606 ** 20-OCT-14 08.00.26.581 AM 15607 ** 20-OCT-14 09.00.29.611 AM 60.051 1391.88 2317%
15607 ** 20-OCT-14 09.00.29.611 AM 15608 ** 20-OCT-14 10.00.32.189 AM 60.043 1213.72 2021%
15608 ** 20-OCT-14 10.00.32.189 AM 15610 ** 20-OCT-14 11.38.00.930 AM 97.479 24637.09 25274%
15609 ** 20-OCT-14 11.00.39.281 AM 15610 ** 20-OCT-14 11.38.00.930 AM 37.361 18493.3 49499%
然后查看一些性能视图都开始变得极为缓慢，最后连生成awr报告的时候每一个步骤都得反应十多秒了。
首先排除了数据库中的锁问题的可能性,然后开始排查倒底是存储的IO问题还是数据库级的?
先从系统级来看，系统级的IO情况。
查看dd命令的效果时，发现系统的IO出现了严重的问题。使用dd命令在正常的情况下每秒差不多有500~700M/s的速度。现在IO基本是瘫痪的感觉。
1000+0 records out
1048576000 bytes (1.0 GB) copied, 94.1975 seconds, 11.1 MB/s
——————————
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 334.724 seconds, 3.1 MB/s
——————————
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 33.5012 seconds, 31.3 MB/s
——————————
通过如上的dd结果还不能确定。在数据库级的IO出现呢严重等待的时候也是会导致系统级的问题。
从这个思路来看，这个问题和cpu的问题关联不是很大.
通过sar来查看io的情况。IOwait也是突然增高的。
10:40:02 AM CPU %user %nice %system %iowait %steal %idle
10:50:01 AM all 21.60 0.00 4.40 0.37 0.00 73.63
11:00:01 AM all 13.94 0.00 3.55 4.57 0.00 77.94
11:10:01 AM all 8.55 0.00 2.66 5.78 0.00 83.01
11:20:02 AM all 12.06 0.00 3.22 8.71 0.00 76.01
11:30:01 AM all 9.51 0.00 2.45 10.82 0.00 77.23
11:40:01 AM all 9.75 0.00 2.55 11.51 0.00 76.19
11:50:02 AM all 7.00 0.00 2.40 12.02 0.00 78.57
有了这些思路，可以感觉可能是在特定的一个时间点里数据库里有什么动作才导致的系统的负载极具提高。
查看了top命令的结果再次得到了一些印证。
因为通过top命令，可以看到不少ora_P0xxx的进程,这个进程就是数据库中存在并行的操作。看到并行进程达到了90多个。
这个时候看到那么到的进程，如果想知道到底是哪些session在做并行的操作，可以根据如下的sql来简单查询到一些有用的信息。
select pxsess.sid||’,’||pxsess.serial# sess_id,sess.username,sess.osuser,sess.machine,sess.program,pxsess.qcsid,pxsess.qcserial#,pxsess.degree,pxsess.server#,pxsess.req_degree from v$px_session pxsess,v$session sess where pxsess.sid=sess.sid ;
得到的结果可以看到每个session并行度为4,有很大一部分都是从客户端scanner@client1发过来的。这样的session有10多个。
通过session来查找对应的sql语句，发现是一个比较大的查询,这个查询中使用了Hint来做几个大表的全表扫描,大表都是千万级的表,所以同时十多个session做并行，而且都是做几个大表的全表扫描,数据库级就是严重的io等待，反应到系统级,又使用了并行,会消耗极高的系统IO.
而且根据我的了解，这个查询时产品线中使用的,目前是最快的执行就是需要走全表扫描，但是只需要在个别的client中部署即可，这一下子运行了这么多，确实有点异常。和客户那边协调过之后，他们马上从package里面停掉了多余的进程。IO速度一下子好了起来。
在这个过程中，awr报告终于生成了。就来再次印证一下这个问题吧。
首先系统的负载很高，这个没有问题。
| Elapsed: | 60.12 (mins) | |||
| DB Time: | 6,143.79 (mins) |
从整体的Profile来看
系统的物理读很高。每秒达到了105,583.8,确实是一个很高的值了。
| Physical reads: | 105,583.8 | 2,166.4 |
在来看看等待事件,就很清楚了。全是Io相关的。
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
| db file sequential read | 21,816,629 | 178,657 | 8 | 48.47 | User I/O |
| direct path read | 1,786,153 | 60,763 | 34 | 16.48 | User I/O |
| read by other session | 1,830,998 | 31,137 | 17 | 8.45 | User I/O |
| log file sync | 216,111 | 25,437 | 118 | 6.90 | Commit |
| DB CPU | 21,645 | 5.87 |
查看time model的时候,可以看到绝大部分的时间都在sql语句的执行上了。
| Statistic Name | Time (s) | % of DB Time |
|---|---|---|
| sql execute elapsed time | 339,415.91 | 92.08 |
| DB CPU | 21,644.80 | 5.87 |
而且这个过程中IO部分占到了70%以上的消耗。
| Wait Class | Waits | %Time -outs | Total Wait Time (s) | Avg wait (ms) | %DB time |
|---|---|---|---|---|---|
| User I/O | 26,965,785 | 0 | 285,901 | 11 | 77.56 |
从上面可以得到，是有一些高IO wait的sql导致了系统极高的物理读,出现了严重的IO等待。
所以在查看sql details的时候直接查看IO wait就可以了。
最后看到前3个都是和那个scanner相关的sql语句。
| User I/O Time (s) | Executions | UIO per Exec (s) | %Total | Elapsed Time (s) | %CPU | %IO | SQL Id | SQL Module | SQL Text |
|---|---|---|---|---|---|---|---|---|---|
| 19,045.53 | 42 | 453.47 | 6.66 | 20,884.74 | 5.34 | 91.19 | 4gz51fphuarsw | JDBC Thin Client | /* scanner….. |
| 16,439.97 | 43 | 382.32 | 5.75 | 17,683.92 | 3.00 | 92.97 | 6fu3z8pqd2y9g | JDBC Thin Client | /* scanner….. |
| 16,346.01 | 43 | 380.14 | 5.72 | 16,687.58 | 2.76 | 97.95 | fg5mc598u799u | JDBC Thin Client | select /*+ leading (xxxxbpm… |
在停掉了额外消耗的客户端进程后，系统的负载就恢复了正常。
通过这个案例也可以得出,并行的使用也是需要考量的,而且需要平衡系统的资源使用情况。可能看似很小的一个问题放大就是一个很严重的问题。