db2診斷系列之---捕獲sql執行情況

          作者:tacy lee

          在應用使用過程中,我們經常會碰到應用響應時間很慢,甚至沒有響應,但是應用服務器可能并不是很繁忙,cpu利用率也非常低,引起這種狀況的原因有很多種,比如環境問題,應用資源泄漏,數據庫原因等等,本文主要是從一次應用性能診斷過程來談談如何通過數據庫診斷應用性能問題。

          問題:

          測試過程中發現應用中某個跳轉頁面執行時間比較長,系統壓力不大,cpu利用很低,該頁面需要從cache中取數據,第一次的時候加載cache(從數據庫中查詢回數據并cache)。

          診斷:

          頁面邏輯比較簡單,我們先用loadrunner模擬并發測試一下這個頁面,然后再數據庫端捕獲sql執行情況。

          1、打開db2監控開關

          #db2 connect to eos
          #db2 update monitor switches using statement on
          #db2 reset monitor all

          2、幾分鐘之后,我們收集sql統計快照

          #db2 get snapshot for dynamic sql on eos > dysqlstatus.out

          現在統計信息已經存放在dysqlstatus.out中,你可以使用任意方便的文本處理工具查看,我一般用windows上的gvim來處理,打開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

          ......

          簡單說一下vi中的處理

          :g!/Total execution time/d
          只保留文本中的sql執行時間,我們要按照執行時間來排序

          通過vim的visual功能選擇執行時間塊(等號后面的數字),然后排序
          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

          排序后的結果(部分)
          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

          可以看到最長時間的sql total執行時間耗費了3797.905123s.

          現在我們到dysqlstatus.out中去找這條語句

          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

          這條語句總共執行了4602次,平均每次的執行時間2S,而且這些數據應該是被cache起來的   ;)

          總結:

          上面的方法簡單總結了從數據庫層面對應用的性能問題診斷,希望對大家有所幫助,對于數據庫快照診斷問題的思路對于任意數據庫通用

           

          補充一個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)
           
          del.icio.us Tags: ,,,

          posted on 2007-11-25 14:51 tacy lee 閱讀(640) 評論(0)  編輯  收藏 所屬分類: 性能相關數據庫

          主站蜘蛛池模板: 宁波市| 辽宁省| 高密市| 蓝山县| 乳源| 南丹县| 平阴县| 廉江市| 台北市| 栾城县| 通河县| 旅游| 门头沟区| 亚东县| 河源市| 太谷县| 哈密市| 郧西县| 东乡县| 清水县| 莒南县| 彰化市| 乐平市| 安康市| 锡林浩特市| 静安区| 越西县| 盐山县| 葫芦岛市| 中江县| 任丘市| 鄂托克前旗| 泾源县| 鄂伦春自治旗| 荆州市| 枝江市| 五莲县| 芦溪县| 徐汇区| 林西县| 东兰县|