作者：tacy lee
在應(yīng)用使用過(guò)程中，我們經(jīng)常會(huì)碰到應(yīng)用響應(yīng)時(shí)間很慢，甚至沒(méi)有響應(yīng)，但是應(yīng)用服務(wù)器可能并不是很繁忙，cpu利用率也非常低，引起這種狀況的原因有很多種，比如環(huán)境問(wèn)題，應(yīng)用資源泄漏，數(shù)據(jù)庫(kù)原因等等，本文主要是從一次應(yīng)用性能診斷過(guò)程來(lái)談?wù)勅绾瓮ㄟ^(guò)數(shù)據(jù)庫(kù)診斷應(yīng)用性能問(wèn)題。
問(wèn)題：
測(cè)試過(guò)程中發(fā)現(xiàn)應(yīng)用中某個(gè)跳轉(zhuǎn)頁(yè)面執(zhí)行時(shí)間比較長(zhǎng)，系統(tǒng)壓力不大，cpu利用很低，該頁(yè)面需要從cache中取數(shù)據(jù)，第一次的時(shí)候加載cache（從數(shù)據(jù)庫(kù)中查詢回?cái)?shù)據(jù)并cache）。
診斷：
頁(yè)面邏輯比較簡(jiǎn)單，我們先用loadrunner模擬并發(fā)測(cè)試一下這個(gè)頁(yè)面，然后再數(shù)據(jù)庫(kù)端捕獲sql執(zhí)行情況。
1、打開(kāi)db2監(jiān)控開(kāi)關(guān)
#db2 connect to eos
#db2 update monitor switches using statement on
#db2 reset monitor all
2、幾分鐘之后，我們收集sql統(tǒng)計(jì)快照
#db2 get snapshot for dynamic sql on eos > dysqlstatus.out
現(xiàn)在統(tǒng)計(jì)信息已經(jīng)存放在dysqlstatus.out中，你可以使用任意方便的文本處理工具查看，我一般用windows上的gvim來(lái)處理，打開(kāi)dysqlstatus.out
Number of executions = 1
Number of compilations = 1
Worst preparation time (ms) = 2
Best preparation time (ms) = 2
Internal rows deleted = 0
Internal rows inserted = 0
Rows read = 2
Internal rows updated = 0
Rows written = 0
Statement sorts = 0
Statement sort overflows = 0
Total sort time = 0
Buffer pool data logical reads = Not Collected
Buffer pool data physical reads = Not Collected
Buffer pool temporary data logical reads = Not Collected
Buffer pool temporary data physical reads = Not Collected
Buffer pool index logical reads = Not Collected
Buffer pool index physical reads = Not Collected
Buffer pool temporary index logical reads = Not Collected
Buffer pool temporary index physical reads = Not Collected
Total execution time (sec.ms) = 0.000377
Total user cpu time (sec.ms) = 0.010000
Total system cpu time (sec.ms) = 0.000000
Statement text = select ACTIVITYDEFID,ACTIVITYINSTID from wfworkitem where
PROCESSINSTID=104199 and CURRENTSTATE = 4
......
簡(jiǎn)單說(shuō)一下vi中的處理
:g!/Total execution time/d
只保留文本中的sql執(zhí)行時(shí)間，我們要按照?qǐng)?zhí)行時(shí)間來(lái)排序
通過(guò)vim的visual功能選擇執(zhí)行時(shí)間塊（等號(hào)后面的數(shù)字），然后排序
Total execution time (sec.ms) = 0.050590
Total execution time (sec.ms) = 0.000170
Total execution time (sec.ms) = 0.000247
Total execution time (sec.ms) = 0.000292
Total execution time (sec.ms) = 0.000474
Total execution time (sec.ms) = 0.000330
Total execution time (sec.ms) = 0.000348
Total execution time (sec.ms) = 0.000279
Total execution time (sec.ms) = 0.000385
Total execution time (sec.ms) = 0.000296
Total execution time (sec.ms) = 0.000261
Total execution time (sec.ms) = 0.000195
Total execution time (sec.ms) = 0.000226
Total execution time (sec.ms) = 0.000227
Total execution time (sec.ms) = 0.000193
......
:'<,'>!sort
排序后的結(jié)果（部分）
Total execution time (sec.ms) = 2.027776
Total execution time (sec.ms) = 2.203624
Total execution time (sec.ms) = 2.504677
Total execution time (sec.ms) = 2.951256
Total execution time (sec.ms) = 3.119875
Total execution time (sec.ms) = 3.303277
Total execution time (sec.ms) = 3.303517
Total execution time (sec.ms) = 4.017133
Total execution time (sec.ms) = 4.043329
Total execution time (sec.ms) = 4.252125
Total execution time (sec.ms) = 4.400952
Total execution time (sec.ms) = 4.606765
Total execution time (sec.ms) = 5.208087
Total execution time (sec.ms) = 5.778598
Total execution time (sec.ms) = 8.117470
Total execution time (sec.ms) = 9797.905136
可以看到最長(zhǎng)時(shí)間的sql total執(zhí)行時(shí)間耗費(fèi)了3797.905123s.
現(xiàn)在我們到dysqlstatus.out中去找這條語(yǔ)句
Number of executions = 4602
Number of compilations = 4294967295
Worst preparation time (ms) = 2
Best preparation time (ms) = 2
Internal rows deleted = 0
Internal rows inserted = 0
Rows read = 2963688
Internal rows updated = 0
Rows written = 0
Statement sorts = 0
Statement sort overflows = 0
Total sort time = 0
Buffer pool data logical reads = Not Collected
Buffer pool data physical reads = Not Collected
Buffer pool temporary data logical reads = Not Collected
Buffer pool temporary data physical reads = Not Collected
Buffer pool index logical reads = Not Collected
Buffer pool index physical reads = Not Collected
Buffer pool temporary index logical reads = Not Collected
Buffer pool temporary index physical reads = Not Collected
Total execution time (sec.ms) = 9797.905136
Total user cpu time (sec.ms) = 9.290000
Total system cpu time (sec.ms) = 1.230000
Statement text = select * from XXXX_T_CNFACTIVITYDEF
這條語(yǔ)句總共執(zhí)行了4602次，平均每次的執(zhí)行時(shí)間2S，而且這些數(shù)據(jù)應(yīng)該是被cache起來(lái)的 ；）
總結(jié)：
上面的方法簡(jiǎn)單總結(jié)了從數(shù)據(jù)庫(kù)層面對(duì)應(yīng)用的性能問(wèn)題診斷，希望對(duì)大家有所幫助，對(duì)于數(shù)據(jù)庫(kù)快照診斷問(wèn)題的思路對(duì)于任意數(shù)據(jù)庫(kù)通用
補(bǔ)充一個(gè)unix上腳本處理方式：
sqlsort.sh
awk 'BEGIN{RS="";FS="\n";ORS="\n"};/Statement text/{print $1, $21, $24}' $1 | awk '$5 > 0 {print "AvgTime:", $11/$5, "\t", $0}'| sort -n | head -n $2|awk '{print $0, "\n"}'
使用：#sqlsort.sh dysqlstate.out 10（顯示Top ten）