暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

I/O slave wait 导致CPU 100%

Roger 2019-06-17
726

问题描述

某客户的一个rac 节点CPU使用率为100%,导致整体系统运行缓慢。    通过mpstat命令检查发现系统CPU使用率为100%,系统的CPU idle几乎为0. 导致系统整体负载极高,如下:

<pre class="brush:plain"> [oracle@ecdbs1 ~]$ mpstat 1 10
Linux 2.6.9-89.5AXS2largesmp (ecdbs1)   2014年10月04日
 
09时52分39秒  CPU   %user   %nice %system %iowait    %irq   %soft   %idle    intr/s
09时52分40秒  all   82.42    0.00   17.52    0.00    0.00    0.06    0.00   5321.00
09时52分41秒  all   82.63    0.00   17.30    0.00    0.00    0.06    0.00   3562.00
09时52分42秒  all   81.52    0.00   18.36    0.00    0.00    0.13    0.00   6107.07
09时52分43秒  all   82.36    0.00   17.45    0.00    0.06    0.13    0.00   4194.06
09时52分44秒  all   82.47    0.00   17.53    0.00    0.00    0.00    0.00   3551.52
09时52分45秒  all   82.63    0.00   17.24    0.00    0.00    0.13    0.00   3553.54
09时52分46秒  all   83.29    0.00   16.71    0.00    0.00    0.00    0.00   3526.73
09时52分47秒  all   82.48    0.00   17.40    0.00    0.00    0.13    0.00   3553.54
09时52分48秒  all   82.47    0.00   17.35    0.00    0.06    0.13    0.00   6888.00
09时52分49秒  all   82.15    0.00   17.78    0.00    0.00    0.06    0.00   5739.60
Average:        all   82.44    0.00   17.46    0.00    0.01    0.08    0.00   4601.00


专家解答

由于这个主机节点上跑了2个实例,其中一个是rac的实例,另外一个是单实例。通过top 检查发现cpu基本上都是被该节点上的

单实例的进程所消耗,如下:

<pre class="brush:plain">top - 16:34:59 up 747 days, 20:49,  9 users,  load average: 139.68, 140.21, 140.37
Tasks: 861 total, 141 running, 720 sleeping,   0 stopped,   0 zombie
Cpu(s): 82.4% us, 17.5% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.1% si
Mem:  66002524k total, 63895780k used,  2106744k free,   165428k buffers
Swap: 12289716k total,   503928k used, 11785788k free,  4302948k cached
 
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                    
12066 oracle    25   0 10.1g 4.1g 4.1g R 13.5  6.5   1573:36 oracle                                                                                                     
12232 oracle    25   0 10.1g 4.2g 4.2g R 13.5  6.7   1030:02 oracle                                                                                                     
........省略部分内容                                                                                                 
 9543 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.6 379:27.64 oracle                                                                                                     
10963 oracle    25   0 10.1g 4.3g 4.3g R 13.2  6.9 544:54.84 oracle                                                                                                     
11483 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1425:30 oracle                                                                                                     
13387 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1509:03 oracle                                                                                                     
13737 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1051:15 oracle                                                                                                     
14163 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.6 227:22.63 oracle                                                                                                     
14842 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1051:56 oracle                                                                                                     
15413 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1043:22 oracle                                                                                                     
16816 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.6 382:09.71 oracle                                                                                                     
17000 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1033:54 oracle                                                                                                     
17524 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.6 389:02.27 oracle                                                                                                     
18087 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 814:07.48 oracle                                                                                                     
18613 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 811:07.11 oracle                                                                                                     
19750 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 585:21.47 oracle                                                                                                     
19886 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1434:08 oracle                                                                                                     
23159 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1556:51 oracle                                                                                                     
23242 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1492:47 oracle                                                                                                     
23361 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 608:33.05 oracle                                                                                                     
24589 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5   1037:20 oracle                                                                                                     
26459 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 602:28.33 oracle                                                                                                     
27194 oracle    25   0 10.2g 4.4g 4.4g R 13.2  7.0 785:01.96 oracle                                                                                                     
27907 oracle    25   0 10.1g 4.1g 4.1g R 13.2  6.5 787:36.62 oracle

根据进程号,定位到相关的user process:

<pre class="brush:plain">SQL&gt; oradebug setospid 20377
Oracle pid: 115, Unix process pid: 20377, image: oracle@ecdbs1
SQL&gt; select s.sid,s.serial#,p.spid from v$process p,v$session s where p.addr=s.paddr and p.spid=17000;
 
       SID    SERIAL# SPID
---------- ---------- ------------------------------------
      2586        959 17000
 
SQL&gt; !ps -ef|grep 17000
oracle    5438  3305  0 17:11 pts/7    00:00:00 /bin/bash -c ps -ef|grep 17000
oracle    5440  5438  0 17:11 pts/7    00:00:00 grep 17000
oracle   17000     1 14 Sep27 ?        17:18:09 oracleewms (LOCAL=NO)
SQL&gt; oradebug setospid 17000
Oracle pid: 40, Unix process pid: 17000, image: oracle@ecdbs1
SQL&gt; show parameter instance_name
 
NAME                                 TYPE                              VALUE
------------------------------------ --------------------------------- ------------------------------
instance_name                        string                            ewms
SQL&gt; oradebug dump processstate 10
Statement processed.
SQL&gt; oradebug close_trace
oradStatement processed.
SQL&gt; ebug tracefile_name
/opt/oracle/admin/ewms/udump/ewms_ora_17000.trc
SQL&gt; !

通过检查发现,存在大量的I/O salve wait 等待事件,如下:

<pre class="brush:plain">SQL&gt; select distinct sql_id,event,count(1) from v$session where event like 'i/o%' group by sql_id,event order by 3;
 
SQL_ID                                  EVENT                     COUNT(1)
--------------------------------------- ----------------------- ----------
bh329g5m6646j                           i/o slave wait                   1
7ac3yq9zzw272                           i/o slave wait                   1
du6nsuvjrpgpr                           i/o slave wait                   1
3msays95wyank                           i/o slave wait                   1
7q2at1qmgzpwm                           i/o slave wait                   1
11gwubk12a25h                           i/o slave wait                   1
206xt31taaha2                           i/o slave wait                   1
f9kc9t3gghckm                           i/o slave wait                   1
dpzmy9wbndrst                           i/o slave wait                   1
6nyq5ss342du4                           i/o slave wait                   4
c5c115p47jyh1                           i/o slave wait                  37
bh1uwqum800ab                           i/o slave wait                  85

更要命的是,我从top 命令的结果中挑选了几个cpu消耗高的进程,检查发现其对应的等待事件都是这个。

从上面的查询来看,这部分会话执行的SQL都类似,开始我怀疑难道是会话执行的SQL有问题 ? 通过dump定位到SQL语句和执行计划,发现执行计划是ok,效率还挺高。

<pre class="brush:plain">============
Plan Table
============
-------------------------------------------------------------------------+-----------------------------------+
| Id  | Operation                             | Name                     | Rows  | Bytes | Cost  | Time      |
-------------------------------------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT                      |                          |       |       |   708 |           |
| 1   |  TEMP TABLE TRANSFORMATION            |                          |       |       |       |           |
| 2   |   LOAD AS SELECT                      |                          |       |       |       |           |
| 3   |    VIEW                               |                          |     1 |   154 |   681 |  00:00:09 |
| 4   |     NESTED LOOPS                      |                          |     1 |   137 |   681 |  00:00:09 |
| 5   |      VIEW                             |                          |  1468 |  126K |   681 |  00:00:09 |
| 6   |       MERGE JOIN                      |                          |  1468 |  100K |   681 |  00:00:09 |
| 7   |        TABLE ACCESS BY INDEX ROWID    | MLOS_SM_INSTIINFO        |     1 |    27 |    10 |  00:00:01 |
| 8   |         INDEX FULL SCAN               | PK_INSTIINFO             |    46 |       |     2 |  00:00:01 |
| 9   |        SORT JOIN                      |                          |   16K |  697K |   671 |  00:00:09 |
| 10  |         TABLE ACCESS FULL             | EWMS_INV_TRANSACTION     |   16K |  697K |   669 |  00:00:09 |
| 11  |      TABLE ACCESS BY INDEX ROWID      | EWMS_BASE_CARGO          |     1 |    49 |     0 |           |
| 12  |       INDEX UNIQUE SCAN               | PK_EWMS_BASE_CARGO       |     1 |       |     0 |           |
| 13  |   COUNT                               |                          |       |       |       |           |
| 14  |    VIEW                               |                          |     1 |   398 |    27 |  00:00:01 |
| 15  |     SORT ORDER BY                     |                          |     1 |   383 |    27 |  00:00:01 |
| 16  |      HASH JOIN OUTER                  |                          |     1 |   383 |    26 |  00:00:01 |
| 17  |       HASH JOIN OUTER                 |                          |     1 |   317 |    17 |  00:00:01 |
| 18  |        HASH JOIN OUTER                |                          |     1 |   251 |    14 |  00:00:01 |
| 19  |         HASH JOIN OUTER               |                          |     1 |   185 |    10 |  00:00:01 |
| 20  |          HASH JOIN OUTER              |                          |     1 |   119 |     7 |  00:00:01 |
| 21  |           VIEW                        |                          |     1 |    53 |     3 |  00:00:01 |
| 22  |            HASH GROUP BY              |                          |     1 |    62 |     3 |  00:00:01 |
| 23  |             VIEW                      |                          |     1 |    62 |     2 |  00:00:01 |
| 24  |              TABLE ACCESS FULL        | SYS_TEMP_0FD9D6835_CC9CBC|     1 |    90 |     2 |  00:00:01 |
| 25  |           VIEW                        |                          |     1 |    66 |     3 |  00:00:01 |
| 26  |            HASH GROUP BY              |                          |     1 |    78 |     3 |  00:00:01 |
| 27  |             VIEW                      |                          |     1 |    78 |     2 |  00:00:01 |
| 28  |              TABLE ACCESS FULL        | SYS_TEMP_0FD9D6835_CC9CBC|     1 |    90 |     2 |  00:00:01 |
| 29  |          VIEW                         |                          |     1 |    66 |     3 |  00:00:01 |
| 30  |           HASH GROUP BY               |                          |     1 |    92 |     3 |  00:00:01 |
| 31  |            FILTER                     |                          |       |       |       |           |
| 32  |             VIEW                      |                          |     1 |    92 |     2 |  00:00:01 |
| 33  |              TABLE ACCESS FULL        | SYS_TEMP_0FD9D6835_CC9CBC|     1 |    90 |     2 |  00:00:01 |
| 34  |         VIEW                          |                          |     1 |    66 |     3 |  00:00:01 |
| 35  |          HASH GROUP BY                |                          |     1 |    92 |     3 |  00:00:01 |
| 36  |           FILTER                      |                          |       |       |       |           |
| 37  |            VIEW                       |                          |     1 |    92 |     2 |  00:00:01 |
| 38  |             TABLE ACCESS FULL         | SYS_TEMP_0FD9D6835_CC9CBC|     1 |    90 |     2 |  00:00:01 |
| 39  |        VIEW                           |                          |     1 |    66 |     3 |  00:00:01 |
| 40  |         HASH GROUP BY                 |                          |     1 |    78 |     3 |  00:00:01 |
| 41  |          VIEW                         |                          |     1 |    78 |     2 |  00:00:01 |
| 42  |           TABLE ACCESS FULL           | SYS_TEMP_0FD9D6835_CC9CBC|     1 |    90 |     2 |  00:00:01 |
| 43  |       VIEW                            |                          |     1 |    66 |     8 |  00:00:01 |
| 44  |        HASH GROUP BY                  |                          |     1 |   109 |     8 |  00:00:01 |
| 45  |         NESTED LOOPS                  |                          |     1 |   109 |     7 |  00:00:01 |
| 46  |          NESTED LOOPS                 |                          |     1 |    82 |     6 |  00:00:01 |
| 47  |           TABLE ACCESS FULL           | EWMS_INV_LOGINVENTORY    |   640 |   21K |     6 |  00:00:01 |
| 48  |           TABLE ACCESS BY INDEX ROWID | EWMS_BASE_CARGO          |     1 |    49 |     0 |           |
| 49  |            INDEX UNIQUE SCAN          | PK_EWMS_BASE_CARGO       |     1 |       |     0 |           |
| 50  |          TABLE ACCESS BY INDEX ROWID  | MLOS_SM_INSTIINFO        |     1 |    27 |     1 |  00:00:01 |
| 51  |           INDEX UNIQUE SCAN           | PK_INSTIINFO             |     1 |       |     0 |           |
-------------------------------------------------------------------------+-----------------------------------+

由此可以判断,应该跟SQL本身的效率是没有关系的。从dump的processstate strace还发现了一点有价值的信息:

<pre class="brush:plain">WARNING:io_submit failed due to kernel limitations MAXAIO for process=0 pending aio=0
WARNING:asynch I/O kernel limits is set at AIO-MAX-NR=65536 AIO-NR=65529
WARNING:1 Oracle process running out of OS kernelI/O resources aiolimit=0 
ksfdgo()+1488&lt;-ksfdaio1()+9848&lt;-kfkUfsIO()+594&lt;-kfkDoIO()+631&lt;-kfkIOPriv()+616&lt;-

............

根据这个AIO的告警,mos上一搜,果然是跟AIO有关系。例如存在类似这样的bug:

Bug 9949948 Linux: Process spin under ksfdrwat0 if OS Async IO not configured high enough

最后建议调整Linux AIO参数之后目前一切正常。


「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论