Db2性能：操作系統CPU高問題分析的一些思路

1. 如何判斷CPU高?

有很多操作系統的命令可以看出來，比如ps -elf，iostat， vmstat, top/topas,

2. 收集數據

CPU高分為usr高和sys高，前者表示系統在執行應用代碼，一般需要應用（比如Db2）來查原因。後者表示系統在執行kernal code，一般需要OS工程師協助分析。

1. sys CPU高

如果是%sys CPU高，這意味著系統在執行kernel code，這種情況下需要操作系統工程師一塊支持，來從操作系統層面收集數據，例如:

AIX:
1) OS trace — perfpmr.sh

Solaris:
1) dtrace script

Linux:
1) systemTap 工具
2) 如果能確定是Db2進程導致的，則收集db2sysc進程的strace -c 數據。

Db2:

Db2層面也可以收集一些數據，Db2導致的sys CPU高時，往往伴隨著很多的latch，所以建議收集db2pd -latch和db2pd -stack的數據。

1. usr CPU高

如果是%usr CPU高，一般意味著系統正在執行應用的代碼，很大可能是Db2執行的SQL語句導致的。需要找到佔用CPU較多的SQL語句，看看在執行什麼操作：

B1. 可以通過mon_get_pkg_cache_stmt找到佔用CPU較多的動態SQL語句
db2 “select TOTAL_CPU_TIME/NUM_EXEC_WITH_METRICS as AVG_CPU_TIME, NUM_EXEC_WITH_METRICS, substr(STMT_TEXT,1,100) as STMT_TEXT from table( mon_get_pkg_cache_stmt (null, null,null,null)) as T where T.NUM_EXEC_WITH_METRICS <> 0 order by AVG_CPU_TIME DESC”

如果是routine佔用了較多的CPU，比如存儲過程，可以參考下面的鏈接：
調查routine的高 CPU 佔用率
https://www.ibm.com/support/knowledgecenter/zh/SSEPGG_10.5.0/com.ibm.db2.luw.admin.mon.doc/doc/t0060667.html

B2. 可以通過db2pd -edus interval=120 來收集120秒之內每個edu佔用的CPU時間，結合其他的信息，比如db2pd -eve、application snapshot的輸出，來看一下edu對應的應用，以及應用執行的SQL語句是什麼，針對這些SQL語句來優化。

SQL語句使用CPU較多的原因，簡單說幾個
–頻繁地掃描環境池中的表、join操作、排序操作都會使用較多的CPU。
–獲取鎖和釋放鎖的過程，也要用較多的CPU。

對於如何解決，一般就是調優SQL了，比如通過建立適當的索引來避免表掃描、當需要鎖較多時而對並發性要求不高時，直接在整個表上加鎖、不需要那麼多數據的時候使用fetch first xxx rows only等。這裡不做闡述（因為我也不擅長），有興趣的可以看參考資料。

3. 一個示例

環境: db2 10.5.0.5, suse linux 11

問題：%usr CPU高，大約95%，db2sysc進程使用的最多

數據收集：
在問題出現期間，收集了以下數據：

vmstat 1 10 > vmstat.1
ps -elf > pself.1
ps aux > psaux.1
iostat 1 10 > iostat.1

db2pd -eve > db2pd_eve.out
db2pd -edus interval=120 > db2pd_edu_120.out
db2pd -stack all

db2 GET SNAPSHOT FOR APPLICATIONS ON <db_name> GLOBAL > applications.log
db2 GET SNAPSHOT FOR DATABASE ON <db_name> GLOBAL > DB.log
db2 get snapshot for all on <db_name> > dbsnap

數據分析：

3.1

iostat 輸出顯示 user CPU 很高.

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

89.42    0.01    4.55    1.89    0.00    4.12

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

94.41    0.00    5.59    0.00    0.00    0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

95.42    0.00    4.58    0.00    0.00    0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

94.67    0.00    5.33    0.00    0.00    0.00

3.2

ps aux的輸出顯示db2sysc進程使用了最多的CPU

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND

root         1  0.0  0.0  10540   884 ?        Ss   Oct15   0:01 init [5]

root         2  0.0  0.0      0     0 ?        S    Oct15   0:00 [kthreadd]

…

root      7065  0.0  0.2 1029412 75296 ?       Sl   Oct15   0:00 db2wdog 0 [db2inst1]

db2inst1  7067 1127 69.2 29760484 22761184 ?   Sl   Oct15 13895:25 db2sysc 0

root      7069  0.0  0.1 1035728 47704 ?       S    Oct15   0:02 db2ckpwd 0

root      7070  0.0  0.1 1035728 47632 ?       S    Oct15   0:02 db2ckpwd 0

root      7071  0.0  0.1 1035728 47632 ?       S    Oct15   0:02 db2ckpwd 0

db2inst1  7079  0.0  0.1 502756 41276 ?        S    Oct15   0:00 db2vend (PD Vendor Process – 1) 0

db2inst1  7089  0.0  0.1 592156 33260 ?        Sl   Oct15   0:22 db2acd 0 ,0,0,0,1,0,0,0,0000,1,0,995bc4,14,1e014,2,0,1,41fc0,0x210000000,0x210000000,1600000,c8010,2,128021

…

root     27022 50.0  0.0   4940   972 pts/1    R+   13:59   0:00 ps aux

root     27499  0.0  0.0      0     0 ?        S    12:06   0:00 [kworker/9:0]

patrol   27604  0.0  0.0  11300  1048 ?        Ss   Oct15   0:00 /bin/bash

patrol   27605  0.0  0.0  11300  1052 ?        Ss   Oct15   0:00 /bin/bash

root     28654  0.0  0.0      0     0 ?        S    Oct15   0:01 [kworker/8:1]

 

3.3

db2pd_edu_120.out 輸出按照對EDU按照佔用的CPU時間排序

1. Database Member 0 — Active — Up 0 days 21:21:14 — Date 2017-10-16-14.48.37.897471
3. List of all EDUs for database member 0
5. db2sysc PID: 7067
6. db2wdog PID: 7065
7. db2acd PID: 7089
9. EDU ID TID                  Kernel TID           EDU Name                               USR (s)         SYS (s)        USR DELTA    SYS DELTA

• ========================================================================================================================================
• 110 140354128963328 28988                db2agent (SAMPLE) 0                590000   478.060000   42.250000     1.080000
• 85 140354313512704 16300                db2agent (SAMPLE) 0                440000   454.140000   40.980000     0.900000
• 87 140354531616512 16316                db2agent (SAMPLE) 0                870000   446.600000   40.830000     0.850000
• 122 140353910859520 348                  db2agent (SAMPLE) 0                420000   430.300000   40.600000     1.000000
• 88 140354514839296 16324                db2agent (SAMPLE) 0                550000   443.450000   40.640000     0.900000
• 91 140354464507648 16327                db2agent (SAMPLE) 0                210000   438.320000   40.660000     0.880000
• 114 140354061854464 13529                db2agent (SAMPLE) 0                820000   436.550000   40.540000     0.900000
• 79 140354900715264 8439                 db2agent (SAMPLE) 0                830000   450.830000   40.540000     0.840000
• 108 140354162517760 21738                db2agent (SAMPLE) 0                730000   450.920000   40.430000     0.920000
• 106 140354196072192 21722                db2agent (SAMPLE) 0                360000   445.650000   40.440000     0.900000
• 119 140353961191168 21841                db2agent (SAMPLE) 0                160000   427.530000   40.450000     0.850000
• 80 140354883938048 16295                db2agent (SAMPLE) 0                770000   443.420000   40.270000     1.020000
• 115 140353776641792 15710                db2agent (SAMPLE) 0                610000   435.050000   40.340000     0.920000
• 111 140354112186112 29588                db2agent (SAMPLE) 0                810000   446.610000   40.340000     0.900000
• 117 140353994745600 16907                db2agent (SAMPLE) 0                840000   433.260000   40.330000     0.910000
• 109 140354145740544 28987                db2agent (SAMPLE) 0                250000   450.080000   40.220000     1.010000
• 84 140354816829184 16299                db2agent (SAMPLE) 0                960000   443.260000   40.250000     0.980000
• 112 140354095408896 6654                 db2agent (SAMPLE) 0                780000   445.550000   40.270000     0.920000
• 118 140353977968384 18404                db2agent (SAMPLE) 0                640000   419.450000   39.990000     0.960000
• 78 140354917492480 8433                 db2agent (SAMPLE) 0                590000   442.670000   39.970000     0.930000
• 121 140353927636736 23958                db2agent (SAMPLE) 0                700000   427.340000   39.910000     0.970000
• 116 140354011522816 15711                db2agent (SAMPLE) 0                390000   437.080000   39.990000     0.870000
• 81 140354867160832 16296                db2agent (SAMPLE) 0                230000   448.500000   39.830000     1.020000
• 104 140354229626624 19731                db2agent (SAMPLE) 0                980000   450.790000   39.910000     0.920000
• 123 140353894082304 1767                 db2agent (SAMPLE) 0                450000   423.550000   39.840000     0.930000
• 113 140354078631680 7525                 db2agent (SAMPLE) 0                950000   437.310000   39.740000     0.870000
• 124 140353877305088 2185                 db2agent (SAMPLE) 0                260000   423.640000   39.640000     0.910000
• …

 

3.4

這裡以EDU ID 110為例子，可以通過db2pd_eve.out找到其執行的SQL語句（這裡可能不準確，因為抓取的是當前正在執行的SQL, 推薦結合mon_get_pkg_cache_stmt的輸出）

1. Dynamic SQL Statements:
2. Address AnchID StmtUID    NumEnv     NumVar     NumRef
3. NumExe Text
4. …
5. 0x00007FAC67B6C640 740 1          1          1          41         41
6. select * from TEST1 where KPICODE like ‘2222|!|!|%’ order
7. by DCTIME desc fetch first 20 rows only with ur
8. …

 

3.5 

Application SNAPSHOT顯示sort、rows read都非常高

Application Snapshot

 

Application handle                         = 109

Application status                         = UOW Executing

..

Rows inserted                              = 12335

Rows updated                               = 0

Rows selected                              = 25680

Rows read                                  = 175961810541

Rows written                               = 12335

..

Total sorts                                = 1284

..

 

以下文章點擊率最高