[轉自Oracle官方中文博客]關于sys CPU usage 100%問題的分析

2019-11-08 20:27:51

字體：大中小

來源：轉載

供稿：網友

原文鏈接為:

https://blogs.Oracle.com/Database4CN/entry/%E5%85%B3%E4%BA%8Esys_cpu_usage_100_%E9%97%AE%E9%A2%98%E7%9A%84%E5%88%86%E6%9E%90

關于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 15CPU_COUNT 32zzz ***Fri Dec 2 17:05:03 CST 2016procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------r b swpd free buff cache si so bi bo in cs us sy id wa st48 0 0 22026868 213392 37138888 0 0 21 31 13 39 6 8 86 0 044 1 0 21968452 213392 37138900 0 0 0 360 1093 537 8 92 0 0 044 1 0 21941632 213392 37139028 0 0 0 288 1080 371 9 91 0 0 0......zzz ***Fri Dec 2 17:10:12 CST 2016procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------r b swpd free buff cache si so bi bo in cs us sy id wa st121 2 0 21495944 218356 37142412 0 0 21 31 13 39 6 9 85 0 0122 4 0 21486192 218356 37142432 0 0 0 308 119 753 7 93 0 0 0121 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/SessionBegin Snap: 38119 02-Dec-16 16:00:28 255 63.2End Snap: 38121 02-Dec-16 18:00:18 193 48.7Elapsed: 119.83 (mins)DB Time: 335.30 (mins)  <<< ------------相當空閑Top 5 Timed EventsEvent    Waits    Time(s)    Avg Wait(ms)    % Total Call Time    Wait ClassCPU time         18,345         91.2     os thread startup    971    937    965    4.7    Concurrencylatch free    582    657    1,128    3.3    Otherdb file sequential read    4,712,799    345    0    1.7    User I/Olog file parallel write    247,562    258    1    1.3    System I/OAWR中沒發現什么異常，DB的alert log顯示一些無法fork進程的消息，估計是資源緊張了。Fri Dec  2 17:06:16 2016Process q002 died, see its trace fileFri Dec  2 17:06:16 2016ksvcreate: 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/0xe9Dec  2 17:05:23 erpdb1 kernel:  [<ffffffff80007c1b>] unmap_vmas+0x522/0x904Dec  2 17:05:23 erpdb1 kernel:  [<ffffffff80012d08>] unmap_region+0xb8/0x12bDec  2 17:05:23 erpdb1 kernel:  [<ffffffff80011e45>] do_munmap+0x21b/0x29aDec  2 17:05:23 erpdb1 kernel:  [<ffffffff800655ab>] __down_write_nested+0x12/0x92Dec  2 17:05:23 erpdb1 kernel:  [<ffffffff80121e88>] sys_shmdt+0x5b/0x133Dec  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.datzzz ***Fri Dec 2 17:04:18 CST 2016 - 235zzz ***Fri Dec 2 17:04:33 CST 2016 - 236zzz ***Fri Dec 2 17:04:48 CST 2016 - 229zzz ***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 - 283zzz ***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 2016top - 17:05:05 up  9:24,  3 users,  load average: 41.76, 28.54, 19.68Tasks: 660 total,  45 running, 615 sleeping,   0 stopped,   0 zombieCpu(s):  8.3%us, 91.7%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stMem:  65993408k total, 44046040k used, 21947368k free,   213392k buffersSwap: 62918564k total,        0k used, 62918564k free, 37139028k cached  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND19610 oracle   25   0 9917m 8.5g 8.5g R 101.8 13.6   1:19.76 oracle19756 oracle   25   0 9917m 7.0g 7.0g R 100.9 11.1   1:05.76 oracle19760 oracle   25   0 9917m 6.7g 6.7g R 100.9 10.7   1:06.56 oracle19942 oracle   25   0 9917m 5.1g 5.1g R 100.9  8.0   0:46.67 oracle20107 oracle   25   0 9917m 3.1g 3.1g R 100.9  4.9   0:26.39 oracle20204 oracle   25   0 9917m 1.2g 1.2g R 100.9  1.9   0:10.63 oracle19486 oracle   25   0 9917m 9.3g 9.3g R 99.9 14.8   1:25.10 oracle19721 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 examplewhen it needs to allocate memory, perform some I/O, or it needs tocreate 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 COMMANDDec 2 17:03:17 oracle  19610     1  14 78.5  0.9 10155628 605564 -   R 17:03:10 00:00:05 ora_q002_XXXXDec 2 17:03:32 oracle  19610     1  14 57.6  2.1 10155628 1437940 -  R 17:03:09 00:00:13 ora_q002_XXXXDec 2 17:03:47 oracle  19610     1  14 67.6  4.3 10155628 2868692 -  R 17:03:10 00:00:25 ora_q002_XXXXDec 2 17:04:02 oracle  19610     1  14 75.8  6.9 10155628 4559708 -  R 17:03:09 00:00:40 ora_q002_XXXXDec 2 17:04:18 oracle  19610     1  14 76.7  9.1 10155628 6015688 -  R 17:03:10 00:00:52 ora_q002_XXXXDec 2 17:04:33 oracle  19610     1  14 70.9 10.4 10155628 6865876 -  R 17:03:09 00:00:59 ora_q002_XXXXDec 2 17:04:48 oracle  19610     1  14 67.7 11.6 10155628 7684088 -  R 17:03:09 00:01:07 ora_q002_XXXXDec 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 COMMANDDec 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 psVSZ: virtual memory usage of entire process. vm_lib + vm_exe + vm_data + vm_stackRSS: 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    10250878976sga_target    8304721920pre_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這個信息誤導了我們。