关于sys cpu usage 100%问题的分析
最近一个客户抱怨他的核心EBS数据库出现性能问题。这是一个10.2.0.3的数据库，运行在Red Hat Enterprise Linux Server release 5.5 (Linux x86-64)操作系统上。
根据客户描述，由于需要维护UPS，他们重启了数据库，结果重启数据库后他们发现只要他们的应用
开始连接数据库，那么主机的sys cpu使用率就会变成100%,但是user cpu使用率几乎是0.
而且只要停掉监听或者应用不开启新session连接数据库，这个问题就会消失。
如下是问题发生期间的vmstat输出，可见cpu中的sys（倒数第4列）几乎100%,cpu Run Queue (第1列)
非常高，而此时free memory还有20G(第4列)，看来内存很充裕。
SNAP_INTERVAL 15 cpu_COUNT 32 zzz ***Fri Dec 2 17:05:03 CST 2016 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ r b swpd free buff cache si so bi bo in cs us sy id wa st 48 0 0 22026868 213392 37138888 0 0 21 31 13 39 6 8 86 0 0 44 1 0 21968452 213392 37138900 0 0 0 360 1093 537 8 92 0 0 0 44 1 0 21941632 213392 37139028 0 0 0 288 1080 371 9 91 0 0 0 ...... zzz ***Fri Dec 2 17:10:12 CST 2016 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ r b swpd free buff cache si so bi bo in cs us sy id wa st 121 2 0 21495944 218356 37142412 0 0 21 31 13 39 6 9 85 0 0 122 4 0 21486192 218356 37142432 0 0 0 308 119 753 7 93 0 0 0 121 2 0 21478868 218364 37142424 0 0 0 592 97 517 5 95 0 0 0
首先我看了一遍客户提供的AWR，发现DB相当空闲，虽然cpu time占据了91.2，但是总的cpu Time
在119分钟的采样中只有18345秒(305分钟)，相对于客户32个cpu Core来说不是个问题。
Snap Id Snap Time Sessions Cursors/Session Begin Snap: 38119 02-Dec-16 16:00:28 255 63.2 End Snap: 38121 02-Dec-16 18:00:18 193 48.7 Elapsed: 119.83 (mins) DB Time: 335.30 (mins) <<< ------------相当空闲 Top 5 Timed Events Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class cpu time 18,345 91.2 os thread startup 971 937 965 4.7 Concurrency latch free 582 657 1,128 3.3 Other db file sequential read 4,712,799 345 0 1.7 User I/O log file parallel write 247,562 258 1 1.3 System I/OAWR中没发现什么异常，DB的alert log显示一些无法fork进程的消息，估计是资源紧张了。
Fri Dec 2 17:06:16 2016 Process q002 died,see its trace file Fri Dec 2 17:06:16 2016 ksvcreate: Process(q002) creation Failed好吧，一般情况下如果我们发现cpu高，无论是sys的还是user的，我们一般的做法是先定位top function call
然后通过这些function call来定位oracle或者OS行为，并且通过这些call来搜索与匹配已知问题。
在linux上，最方便收集这些信息的就是用perf这个工具。关于perf，参见:
https://perf.wiki.kernel.org/index.php/Tutorial
结果客户说他们无法安装perf命令，不过他提到他的OS中显示很多错误:
Dec 2 17:05:23 erpdb1 kernel: BUG: soft lockup - cpu#5 stuck for 10s! [oracle:15668] Dec 2 17:05:23 erpdb1 kernel: cpu 5: Dec 2 17:05:23 erpdb1 kernel: Call Trace: Dec 2 17:05:23 erpdb1 kernel: [<ffffffff8000e9a8>] __set_page_dirty_nobuffers+0xc2/0xe9 Dec 2 17:05:23 erpdb1 kernel: [<ffffffff80007c1b>] unmap_vmas+0x522/0x904 Dec 2 17:05:23 erpdb1 kernel: [<ffffffff80012d08>] unmap_region+0xb8/0x12b Dec 2 17:05:23 erpdb1 kernel: [<ffffffff80011e45>] do_munmap+0x21b/0x29a Dec 2 17:05:23 erpdb1 kernel: [<ffffffff800655ab>] __down_write_nested+0x12/0x92 Dec 2 17:05:23 erpdb1 kernel: [<ffffffff80121e88>] sys_shmdt+0x5b/0x133 Dec 2 17:05:23 erpdb1 kernel: [<ffffffff8005e28d>] tracesys+0xd5/0xe0
通过call stack，看来在回收内存时报错了，推测这个错误应当发生在进程退出阶段，
不过难以断定这些错误与sys cpu高的因果关系。
结合客户描述的现象，这看起来很像连接风暴，因此我们检查了ps的输出，发现进程数并未明显增加,
不过问题最严重的时间断片了。这些零碎的信息并不能给我们一个很清晰的线索。
$ awk '/$ORACLE_SID/{n++;next}/^zzz/{if(t)print t,"-",n;t=$0;n=0}END{print t,n}' XXXX_ps_16.12.02.1700.dat
zzz ***Fri Dec 2 17:04:18 CST 2016 - 235 zzz ***Fri Dec 2 17:04:33 CST 2016 - 236 zzz ***Fri Dec 2 17:04:48 CST 2016 - 229 zzz ***Fri Dec 2 17:05:03 CST 2016 - 228 <<<< 此时问题实际上已经发生了 zzz ***Fri Dec 2 17:05:19 CST 2016 - 178 <<<< 17:05 ~ 17:13 的断片了 zzz ***Fri Dec 2 17:13:19 CST 2016 - 283 <<<< zzz ***Fri Dec 2 17:13:34 CST 2016 - 283 zzz ***Fri Dec 2 17:13:49 CST 2016 - 196接下来看了top，发现虽然OS的sys cpu高，不过top的process都是oracle，表明此问题一定 与oracle有点关系。
zzz ***Fri Dec 2 17:05:03 CST 2016 top - 17:05:05 up 9:24,3 users,load average: 41.76,28.54,19.68 Tasks: 660 total,45 running,615 sleeping,0 stopped,0 zombie cpu(s): 8.3%us,91.7%sy,0.0%ni,0.0%id,0.0%wa,0.0%hi,0.0%si,0.0%st Mem: 65993408k total,44046040k used,21947368k free,213392k buffers Swap: 62918564k total,0k used,62918564k free,37139028k cached PID USER PR NI VIRT RES SHR S %cpu %MEM TIME+ COMMAND 19610 oracle 25 0 9917m 8.5g 8.5g R 101.8 13.6 1:19.76 oracle 19756 oracle 25 0 9917m 7.0g 7.0g R 100.9 11.1 1:05.76 oracle 19760 oracle 25 0 9917m 6.7g 6.7g R 100.9 10.7 1:06.56 oracle 19942 oracle 25 0 9917m 5.1g 5.1g R 100.9 8.0 0:46.67 oracle 20107 oracle 25 0 9917m 3.1g 3.1g R 100.9 4.9 0:26.39 oracle 20204 oracle 25 0 9917m 1.2g 1.2g R 100.9 1.9 0:10.63 oracle 19486 oracle 25 0 9917m 9.3g 9.3g R 99.9 14.8 1:25.10 oracle 19721 oracle 25 0 9917m 6.9g 6.8g R 99.9 10.9 1:08.22 oracle那么问题来了，oracle软件一般都是执行user code，因此大多数情况下会消耗user space 的cpu，怎么会消耗sys cpu呢？ 先man一下top:
sy - This is the amount of time that the cpu spent running the kernel. All the processes and system resources are handled by the Linux kernel. When a user space process needs something from the system,for example when it needs to allocate memory,perform some I/O,or it needs to create a child process,then the kernel is running.
这说明oracle进程是有可能消耗kernel space的cpu的，比如申请内存，执行I/O等。
挑出上面的top列出的进程，在ps输出中找规律:
$ grep 19610 Dec* TIME USER PID PPID PRI %cpu %MEM VSZ RSS WCHAN S STARTED TIME COMMAND Dec 2 17:03:17 oracle 19610 1 14 78.5 0.9 10155628 605564 - R 17:03:10 00:00:05 ora_q002_XXXX Dec 2 17:03:32 oracle 19610 1 14 57.6 2.1 10155628 1437940 - R 17:03:09 00:00:13 ora_q002_XXXX Dec 2 17:03:47 oracle 19610 1 14 67.6 4.3 10155628 2868692 - R 17:03:10 00:00:25 ora_q002_XXXX Dec 2 17:04:02 oracle 19610 1 14 75.8 6.9 10155628 4559708 - R 17:03:09 00:00:40 ora_q002_XXXX Dec 2 17:04:18 oracle 19610 1 14 76.7 9.1 10155628 6015688 - R 17:03:10 00:00:52 ora_q002_XXXX Dec 2 17:04:33 oracle 19610 1 14 70.9 10.4 10155628 6865876 - R 17:03:09 00:00:59 ora_q002_XXXX Dec 2 17:04:48 oracle 19610 1 14 67.7 11.6 10155628 7684088 - R 17:03:09 00:01:07 ora_q002_XXXX Dec 2 17:05:03 oracle 19610 1 14 68.9 13.3 10155628 8838576 - R 17:03:10 00:01:18 ora_q002_XXXX $ grep 19756 Dec* TIME USER PID PPID PRI %cpu %MEM VSZ RSS WCHAN S STARTED TIME COMMAND Dec 2 17:03:47 oracle 19756 1 16 50.0 0.3 10155628 222508 - R 17:03:44 00:00:02 oracleXXXX (LOCAL=NO) Dec 2 17:04:02 oracle 19756 1 14 47.9 1.4 10155628 961764 - R 17:03:43 00:00:09 oracleXXXX (LOCAL=NO) Dec 2 17:04:18 oracle 19756 1 14 55.5 3.0 10155628 2021664 - R 17:03:44 00:00:18 oracleXXXX (LOCAL=NO) Dec 2 17:04:33 oracle 19756 1 14 68.4 5.6 10155628 3703572 - R 17:03:43 00:00:34 oracleXXXX (LOCAL=NO) Dec 2 17:04:48 oracle 19756 1 14 75.4 8.2 10155628 5459948 - R 17:03:43 00:00:49 oracleXXXX (LOCAL=NO) Dec 2 17:05:03 oracle 19756 1 14 80.6 10.9 10155628 7217680 - R 17:03:44 00:01:04 oracleXXXX (LOCAL=NO)
从以上输出可以发现一个明显规律: 这些进程的RSS在1分多钟从几十M变成7~8G，但是VSZ却没有变化。
接着man ps
VSZ: virtual memory usage of entire process. vm_lib + vm_exe + vm_data + vm_stack RSS: resident set size,the non-swapped physical memory that a task has used (in kiloBytes). (alias RSSize,rsz).
任何一个oracle进程的VSZ约等于SGA加上这个进程的PGA(实际上VSZ还包含一些kernel内存)，正常情况下一个进程的pga是很小的。
以上输出中VSZ没有改变，因此发生巨大变化的RSS申请的内存一定不是PGA而是SGA（因为如果增长的是PAG那么VSZ也会跟着增长）。
好吧，那么只有一个可能了，那就是这个进程在touch整个sga，为什么会这样？
们需要再回到原点再看一眼AWR的数据库参数信息，赫然发现如下内容:
sga_max_size 10250878976 sga_target 8304721920 pre_page_sga TRUE <<<<------------------看这里
这个设置中的sga_max_size正好10g，与我们在ps中看到的VSZ正好相等。
问题的原因是客户设置了pre_page_sga=true，这样在oracle进程启动阶段会touch整个SGA，
这个过程中会调用OS的sys call来touch 整个 shared memory entry，因此引发了高SYS cpu消耗。
参见如下文档的描述:
Health Check Alert: Consider setting PRE_PAGE_SGA to FALSE (Doc ID 957525.1)回过头来再看alert log，观察参数pre_page_sga是什么时候改的，发现它在很久以前的很多次重启就是true了。
也就是说，这个问题一直都存在，只是客户最近维护UPS之后才发现，维护UPS这个信息误导了我们。
版权声明：本文内容由互联网用户自发贡献，该文观点与技术仅代表作者本人。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如发现本站有涉嫌侵权/违法违规的内容， 请发送邮件至 dio@foxmail.com 举报，一经查实，本站将立刻删除。
