一條簡單的sql語句導致的系統問題

dbhelper發表於2015-03-02
SQL
新年，給大家拜年了。祝大家工作順利，萬事如意。
今天照例簡單檢查了系統的情況，發現在客戶的伺服器在下午的3-5點這個時間段，資料庫負載略有上升，但是幅度不大，因為生產的awr抓取頻率是10分鐘，所以還是能夠透過awr分析出一些問題。
負載情況如下：

抓取了一個最新時間段的awr報告。
檢視資料庫負載，比平時的負載要高一些。
Host Name Platform CPUs Cores Sockets Memory (GB)
xxxxx Linux x86 64-bit 80 40 4 346.22
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 33108 19-Feb-15 15:40:21 5147 5.4
End Snap: 33109 19-Feb-15 15:50:22 5256 5.5
Elapsed:   10.01 (mins)    
DB Time:   533.14 (mins)    

從這個概覽來看還是看不出特別之處，只能對整體的情況有一個把握。這是一個10分鐘的報告。
Load profile是我檢視awr報告的重點部分。能夠發現user calls和executions的值很高。

Load Profile

Convert to CSV

Per Second Per Transaction Per Exec Per Call
DB Time(s): 53.3 0.9 0.00 0.00
DB CPU(s): 10.3 0.2 0.00 0.00
Redo size: 2.2 MB 37.4 KB    
Logical reads: 10.3 GB 179.3 MB    
Block changes: 10,738.9 182.2    
Physical reads: 1.2 GB 21.5 MB    
Physical writes: 7.8 MB 136.0 KB    
User calls: 20,256.8 343.7    
Parses: 2,447.3 41.5    
Hard parses: 4.3 0.1    
W/A MB processed: 72.5 1.2    
Logons: 4.6 0.1    
Executes: 11,414.1 193.7    
Rollbacks: 0.6 0.0    
Transactions: 58.9      

這個時候基本能夠從load profile裡面找到問題的方向了，user calls和executions的部分需要注意，首先問題的方向很可能是從sql語句級別導致的，語句執行的如此頻繁，勢必會對buffer gets有較大的影響，這個報告中parses的值很低，至少說明問題不是由於繫結變數導致的。我們可以檢視等待事件基本確定時間都去哪了，哪些等待事件是需要重點關注的。然後在sql語句部分來分析了，基本可以從order by Elapsed time, order by Gets, order by Executions這三個部分來佐證了。
等待事件如下：

Top 5 Timed Foreground Events

Event Waits Time(s) Avg wait (ms) % DB time Wait Class
db file sequential read 13,019,569 15,375 1 48.06 User I/O
enq: TX - row lock contention 403 7,779 19303 24.32 Application
DB CPU   6,185   19.34  
direct path read 425,941 1,882 4 5.88 User I/O
read by other session 1,126,812 774 1 2.42 User I/O

從這個等待事件可以看出，大部分的等待事件都集中在IO部分，當然導致的原因也是多方面的。第2個等待事件至少可以說明表中存在著鎖，這個也可能是導致資料庫負載增加的一個原因，在透過監控記錄檢視，或者抓取一個ash報告就能夠基本定位出那個時間段的鎖細節。已經做了確認，發現某一個process存在很多的併發dml操作，抓取了相應的資訊交給了開發處理。
但是這個問題和load profile中的user calls,executions的值過高應該沒有太大的關係。我們來直接進入sql資訊部分。

SQL ordered by Elapsed Time

  • Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text
    01:39:59 1,344 4.46 18.75 0.33 0.00 dch8sxwt6ujvc JDBC Thin Client
    /* CL_ProcessController_update...
    01:25:38 95 54.08 16.06 6.94 96.79 6csnjz5kqcffm bl1extract@ccbdbpr1 (TNS V1-V3)
    SELECT /*+ leading (list payp...
    2,612.67 206 12.68 8.17 8.55 94.69 ffnjuh9qz1wy8 bl1extract@ccbdbpr1 (TNS V1-V3)
    SELECT /*+ leading (cust rate ...
    1,800.85 519 3.47 5.63 0.01 0.00 ffv3am85ccm25 JDBC Thin Client
    /* AC_AcCloseUpdateAcControl_u...
    1,554.22 13 119.56 4.86 17.15 86.22 fg5mc598u799u JDBC Thin Client
    select /*+ leading (bpm_ai bpm...
    1,476.63 13 113.59 4.62 30.53 66.68 4gz51fphuarsw JDBC Thin Client
    /* CL_ProcInstScanner_selectAv...
    952.12 361,344 0.00 2.98 12.69 92.74 62h1u7vsgjx9p bl1extract@ccbdbpr1 (TNS V1-V3)
    /* */ SELECT CUSTOMER_ID, SUBS...
    924.90 13 71.15 2.89 30.09 66.53 6fu3z8pqd2y9g JDBC Thin Client
    /* CL_WaitScanner_selectWorkab...
    600.66 0   1.88 8.85 94.53 1taqbbq0mw35u JDBC Thin Client
    SELECT OK.BAN, OK.MSISDN, OK.P...
    565.49 0   1.77 4.19 97.80 cqrms45fqwvr3 JDBC Thin Client
    /* Formatted on 2012/04/26 16:...
    514.37 2,552,072 0.00 1.61 99.27 0.00 0mynq29fmat7d getdate_int@ccbdbpr1 (TNS V1-V3)
    select TO_CHAR(LOGICAL_DATE, '...

SQL ordered by Gets


  • Buffer Gets Executions Gets per Exec %Total Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text
    1.2 TB 2,552,072 486.9 KB 19.12 514.37 99.27 0.00 0mynq29fmat7d getdate_int@ccbdbpr1 (TNS V1-V3)
    select TO_CHAR(LOGICAL_DATE, '...
    705.8 GB 25 28.2 GB 11.39 105.95 72.71 27.95 1hg2wcuapy3y3 JDBC Thin Client
    select bl1_run_request.run_mod...
    234.0 GB 13 18.0 GB 3.78 1,476.63 30.53 66.68 4gz51fphuarsw JDBC Thin Client
    /* CL_ProcInstScanner_selectAv...
    228.4 GB 13 17.6 GB 3.69 924.90 30.09 66.53 6fu3z8pqd2y9g JDBC Thin Client
    /* CL_WaitScanner_selectWorkab...
    190.4 GB 335 582.0 MB 3.07 192.38 99.90 0.00 aty7a3bvqfxxx JDBC Thin Client
    SELECT COUNT(1) FROM (/* null_...

SQL ordered by Executions


  • Executions Rows Processed Rows per Exec Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text
    2,552,072 2,551,077 1.00 514.37 99.27 0.00 0mynq29fmat7d getdate_int@ccbdbpr1 (TNS V1-V3)
    select TO_CHAR(LOGICAL_DATE, '...
    445,868 445,865 1.00 14.05 90.20 0.20 fa311gg43yjyf JDBC Thin Client
    Select CSM_TRX_1SQ.NEXTVAL fro...
    380,095 380,041 1.00 101.08 21.71 83.42 aprfnw5vk6szs java_q4p@ccbappr7 (TNS V1-V3)
    SELECT ch_objects.obj_id, ch_o...

這個時候透過這三個部分，能夠基本定位出問題發生在sql_id 0mynq29fmat7d這個語句上，這個語句就是 一個簡單的select查詢，查詢的表也很小。但是問題就是在10分鐘的時間範圍內執行了2百多萬次，這確實很不正常。從sql order by elapased部分可以看出這個語句佔用的 db time比例不高，從sql語句的執行上還是沒有問題的，但是透過sql order by gets和execution這兩個部分，可以很明顯的看到，這條語句是top 1的語句，使用的buffer gets高達1T，這個表中的資料量就幾千條資料，大小都是MB級別的，但是在10分鐘內卻能使用1T的buffer gets，確實讓我感覺很意外。
分析了這些問題之後，我的判斷是認為程式邏輯中的問題，稍後傳送了郵件和開發做確認。

透過這個問題可以看到sql語句導致的問題不一定是差的執行計劃導致的，簡單的sql語句照樣能夠導致一些意外的情況。但是執行的頻率為什麼這麼頻繁，還是屬於應用部分，只能讓他們提供更多的資訊了。而且分析問題的時候，發現了一些問題，可能在檢查的過程中又被其它的問題干擾了，很可能會讓自己偏離問題檢查的方向，很容易造成一個情況，發現忙活了半天，查問題的針對性不夠。

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8494287/viewspace-1445408/，如需轉載，請註明出處，否則將追究法律責任。

相關文章