由一条sql语句导致的系统IO问题

早上来到公司，照例进行了简单的检查，发现系统负载不高，就开始计划一些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多个。
SESS_ID         USERNAME        OSUSER          MACHINE              PROGRAM                        QCSID  QCSERIAL#     DEGREE    SERVER# REQ_DEGREE
--------------- --------------- --------------- -------------------- ------------------------- ---------- ---------- ---------- ---------- ----------
3060,19215      PRDUSER         prdwrk01        client1             oracle@dbmachine (P000)          6912      12521          4          1          4
5903,31549      PRDUSER         prdwrk01        client1             oracle@dbmachine (P001)          6912      12521          4          2          4
6338,17097      PRDUSER         prdwrk01        client1             oracle@dbmachine (P002)          6912      12521          4          3          4
3670,37601      PRDUSER         prdwrk01        client1             oracle@dbmachine (P003)          6912      12521          4          4          4
5963,10235      PRDUSER         prdwrk01        client1             oracle@dbmachine (P004)          6912      12521          4          1          4
6289,37919      PRDUSER         prdwrk01        client1             oracle@dbmachine (P005)          6912      12521          4          2          4
432,51019       PRDUSER         prdwrk01        client1             oracle@dbmachine (P006)          6912      12521          4          3          4
3299,17439      PRDUSER         prdwrk01        client1             oracle@dbmachine (P007)          6912      12521          4          4          4
3894,9907       PRDUSER         prdwrk01        client1             oracle@dbmachine (P008)           497      18425          2          1          2
4403,13615      PRDUSER         prdwrk01        client1             oracle@dbmachine (P009)           497      18425          2          2          2
400,25915       PRDUSER         prdwrk01        client1             oracle@dbmachine (P010)           497      18425          2          1          2
6509,61063      PRDUSER         prdwrk01        client1             oracle@dbmachine (P011)           497      18425          2          2          2
6912,12521      PRDUSER         prdwrk01        client1             scanner@client1 (TNS V1-V3)       6912                                                                     
497,18425       PRDUSER         prdwrk01        client2             JDBC Thin Client                  497


通过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...

在停掉了额外消耗的客户端进程后，系统的负载就恢复了正常。
通过这个案例也可以得出,并行的使用也是需要考量的,而且需要平衡系统的资源使用情况。可能看似很小的一个问题放大就是一个很严重的问题。