一條sql導致資料庫整體效能下降的診斷和解決的全過程(轉)
讀了BT大師的一篇文章,發現statspack在解決效能問題的時候還可以這樣用:
http://blog.itpub.net/post/330/2230
今天早上一來，資料庫load就比往常高了許多。想想資料庫唯一的變化是昨天早上我曾經重新分析過資料庫物件。
發現資料庫load很高，首先看top發現沒有特別異常的程式，在資料庫中適時抓取正在執行的sql也沒發現異常(通常執行時間非常短的sql是不能被抓取到的)。詢問相關應用程式人員，最近沒有變動。檢查應用程式日誌發現今天早上跟往常也沒有過多登陸和操作。基本上可以圈定是在資料庫伺服器本身上面。
但是這個時候我還沒有辦法確定到底是哪個應用的哪個查詢的問題，因為數百個程式的幾十臺server連著，我不能去及時的追蹤。打算等到10點過去後，抽取8/9/10高峰期的整點的statspack出來，跟上星期的這個時間產生的報告對比看看。
通過對比報告我們發現 CPU TIME 今天一小時內增加了大約1200秒（2,341 - 1,175 ）。這是一個重大的變化，很顯然是兩種可能
1：今天過多地執行了某些sql
2：某些sql的執行計劃發生變化導致cpu使用過多
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 2,341 42.60
db file sequential read 387,534 2,255 41.04
global cache cr request 745,170 231 4.21
log file sync 98,041 229 4.17
log file parallel write 96,264 158 2.88
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 346,851 1,606 47.60
CPU time 1,175 34.83
global cache cr request 731,368 206 6.10
log file sync 90,556 91 2.71
db file scattered read 37,746 90 2.66
接下來我對比了 sql 部分內容，發現
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
17,899,606 47,667 375.5 55.6 1161.27 1170.22 3481369999
Module: /home/oracle/AlitalkSrv/config/../../AlitalkSrv/
SELECT login_id, to_char(gmt_create, 'YYYY-MM-DD HH24:MI:SS')
from IM_BlackList where black_id = :b1
這條sql出現在了今天報告的前列，而以往的報告中該sql根本不排在 buffer gets 前面位置，顯然這條sql消耗了大約 1161.27 秒 cpu time .檢查原來的報告
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
107,937 47,128 2.3 0.8 7.39 6.94 3481369999
Module: /home/oracle/AlitalkSrv/config/../../AlitalkSrv/
SELECT login_id, to_char(gmt_create, 'YYYY-MM-DD HH24:MI:SS')
from IM_BlackList where black_id = :b1
我們發現只消耗了 7.39 秒的 cpu time 。
到這個時候我基本可以斷定，是由於這個sql沒有走索引而走了全表掃描。但是為什麼會走全表掃描呢，這是一個問題，接下來我檢查了表的索引：
SQL> select index_name,column_name from user_ind_columns where table_name = 'IM_BLACKLIST';
IM_BLACKLIST_PK LOGIN_ID
IM_BLACKLIST_PK BLACK_ID
IM_BLACKLIST_LID_IND BLACK_ID
很顯然存在著 black_id 的單獨的索引，應該正常使用才對。於是我在生產庫上執行這個sql一看，卻發現走了全表掃描。為此我到一個週六的standby的opren read only 的資料庫上查詢了一下該索引欄位的histogram（這個時候昨天早上分析物件的日誌還沒有被應用過去）
sys@OCN> select COLUMN_NAME ,ENDPOINT_NUMBER, ENDPOINT_VALUE , ENDPOINT_ACTUAL_VALUE from dba_histograms
2 where table_name = 'IM_BLACKLIST' and column_name = 'BLACK_ID';
COLUMN_NAME ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
------------------------------ --------------- -------------- ------------------------------
BLACK_ID 0 2.5031E+35
BLACK_ID 1 2.6065E+35
BLACK_ID 2 2.8661E+35
BLACK_ID 3 5.0579E+35
BLACK_ID 4 5.0585E+35
BLACK_ID 5 5.0585E+35
BLACK_ID 6 5.0589E+35
BLACK_ID 7 5.0601E+35
BLACK_ID 8 5.1082E+35
BLACK_ID 9 5.1119E+35
BLACK_ID 10 5.1615E+35
BLACK_ID 11 5.1616E+35
BLACK_ID 12 5.1628E+35
BLACK_ID 13 5.1646E+35
BLACK_ID 14 5.2121E+35
BLACK_ID 15 5.2133E+35
BLACK_ID 16 5.2155E+35
BLACK_ID 17 5.2662E+35
BLACK_ID 18 5.3169E+35
BLACK_ID 19 5.3193E+35
BLACK_ID 20 5.3686E+35
BLACK_ID 21 5.3719E+35
BLACK_ID 22 5.4198E+35
BLACK_ID 23 5.4206E+35
BLACK_ID 24 5.4214E+35
BLACK_ID 25 5.4224E+35
BLACK_ID 26 5.4238E+35
BLACK_ID 27 5.4246E+35
BLACK_ID 28 5.4743E+35
BLACK_ID 29 5.5244E+35
BLACK_ID 30 5.5252E+35
BLACK_ID 31 5.5252E+35
BLACK_ID 32 5.5272E+35
BLACK_ID 33 5.5277E+35
BLACK_ID 34 5.5285E+35
BLACK_ID 35 5.5763E+35
BLACK_ID 36 5.6274E+35
BLACK_ID 37 5.6291E+35
BLACK_ID 38 5.6291E+35
BLACK_ID 39 5.6291E+35
BLACK_ID 40 5.6291E+35
BLACK_ID 42 5.6311E+35
BLACK_ID 43 5.6794E+35
BLACK_ID 44 5.6810E+35
BLACK_ID 45 5.6842E+35
BLACK_ID 46 5.7351E+35
BLACK_ID 47 5.8359E+35
BLACK_ID 48 5.8887E+35
BLACK_ID 49 5.8921E+35
BLACK_ID 50 5.9430E+35
BLACK_ID 51 5.9913E+35
BLACK_ID 52 5.9923E+35
BLACK_ID 53 5.9923E+35
BLACK_ID 54 5.9931E+35
BLACK_ID 55 5.9947E+35
BLACK_ID 56 5.9959E+35
BLACK_ID 57 6.0428E+35
BLACK_ID 58 6.0457E+35
BLACK_ID 59 6.0477E+35
BLACK_ID 60 6.0479E+35
BLACK_ID 61 6.1986E+35
BLACK_ID 62 6.1986E+35
BLACK_ID 63 6.1994E+35
BLACK_ID 64 6.2024E+35
BLACK_ID 65 6.2037E+35
BLACK_ID 66 6.2521E+35
BLACK_ID 67 6.2546E+35
BLACK_ID 68 6.3033E+35
BLACK_ID 69 6.3053E+35
BLACK_ID 70 6.3069E+35
BLACK_ID 71 6.3553E+35
BLACK_ID 72 6.3558E+35
BLACK_ID 73 6.3562E+35
BLACK_ID 74 6.3580E+35
BLACK_ID 75 1.1051E+36
然後對比了一下當前的histograms
COLUMN_NAME ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
------------------------------ --------------- -------------- ------------------------------
BLACK_ID 0 1.6715E+35
BLACK_ID 1 2.5558E+35
BLACK_ID 2 2.7619E+35
BLACK_ID 3 2.9185E+35
BLACK_ID 4 5.0579E+35
BLACK_ID 5 5.0589E+35
BLACK_ID 6 5.0601E+35
BLACK_ID 7 5.1100E+35
BLACK_ID 8 5.1601E+35
BLACK_ID 9 5.1615E+35
BLACK_ID 10 5.1624E+35
BLACK_ID 11 5.1628E+35
BLACK_ID 12 5.1642E+35
BLACK_ID 13 5.2121E+35
BLACK_ID 14 5.2131E+35
BLACK_ID 15 5.2155E+35
BLACK_ID 16 5.2676E+35
BLACK_ID 17 5.3175E+35
BLACK_ID 18 5.3684E+35
BLACK_ID 19 5.3727E+35
BLACK_ID 20 5.4197E+35
BLACK_ID 21 5.4200E+35
BLACK_ID 22 5.4217E+35
BLACK_ID 23 5.4238E+35
BLACK_ID 24 5.4244E+35
BLACK_ID 25 5.4755E+35
BLACK_ID 26 5.5252E+35
BLACK_ID 27 5.5252E+35
BLACK_ID 28 5.5252E+35
BLACK_ID 29 5.5283E+35
BLACK_ID 30 5.5771E+35
BLACK_ID 31 5.6282E+35
BLACK_ID 32 5.6291E+35
BLACK_ID 33 5.6291E+35
BLACK_ID 34 5.6291E+35
BLACK_ID 35 5.6299E+35
BLACK_ID 36 5.6315E+35
BLACK_ID 37 5.6794E+35
BLACK_ID 39 5.6816E+35
BLACK_ID 40 5.6842E+35
BLACK_ID 41 5.7838E+35
BLACK_ID 42 5.8877E+35
BLACK_ID 43 5.8917E+35
BLACK_ID 44 5.9406E+35
BLACK_ID 45 5.9909E+35
BLACK_ID 46 5.9923E+35
BLACK_ID 47 5.9923E+35
BLACK_ID 48 5.9946E+35
BLACK_ID 49 5.9950E+35
BLACK_ID 50 5.9960E+35
BLACK_ID 51 5.9960E+35
BLACK_ID 52 5.9960E+35
BLACK_ID 53 5.9960E+35
BLACK_ID 54 5.9960E+35
BLACK_ID 55 5.9960E+35
BLACK_ID 56 5.9960E+35
BLACK_ID 57 6.0436E+35
BLACK_ID 58 6.0451E+35
BLACK_ID 59 6.0471E+35
BLACK_ID 60 6.1986E+35
BLACK_ID 61 6.1998E+35
BLACK_ID 62 6.2014E+35
BLACK_ID 63 6.2037E+35
BLACK_ID 64 6.2521E+35
BLACK_ID 65 6.2544E+35
BLACK_ID 66 6.3024E+35
BLACK_ID 67 6.3041E+35
BLACK_ID 68 6.3053E+35
BLACK_ID 69 6.3073E+35
BLACK_ID 70 6.3558E+35
BLACK_ID 71 6.3558E+35
BLACK_ID 72 6.3558E+35
BLACK_ID 73 6.3558E+35
BLACK_ID 74 6.3580E+35
BLACK_ID 75 1.1160E+36
我們發現原來的histograms值分佈比較均勻，而昨天分析後的值分佈就有一些地方是集中的，參考上面紅色部分。
於是我再做了個 10053 dump對比，昨天分析之前
通過 alter session set events '10053 trace name context forever';
然後執行相關的sql 再去看trace檔案
Table stats Table: IM_BLACKLIST Alias: IM_BLACKLIST
TOTAL :: CDN: 57477 NBLKS: 374 AVG_ROW_LEN: 38
-- Index stats
INDEX NAME: IM_BLACKLIST_LID_IND COL#: 2
TOTAL :: LVLS: 1 #LB: 219 #DK: 17181 LB/K: 1 DB/K: 2 CLUF: 44331
INDEX NAME: IM_BLACKLIST_PK COL#: 1 2
TOTAL :: LVLS: 1 #LB: 304 #DK: 57477 LB/K: 1 DB/K: 1 CLUF: 55141
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
SINGLE TABLE ACCESS PATH
Column: BLACK_ID Col#: 2 Table: IM_BLACKLIST Alias: IM_BLACKLIST
NDV: 17181 NULLS: 0 DENS: 5.8204e-05
NO HISTOGRAM: #BKT: 1 #VAL: 2
TABLE: IM_BLACKLIST ORIG CDN: 57477 ROUNDED CDN: 3 CMPTD CDN: 3
Access path: tsc Resc: 38 Resp: 38
Access path: index (equal)
Index: IM_BLACKLIST_LID_IND
TABLE: IM_BLACKLIST
RSC_CPU: 0 RSC_IO: 4
IX_SEL: 0.0000e+00 TB_SEL: 5.8204e-05
Skip scan: ss-sel 0 andv 27259
ss cost 27259
table io scan cost 38
Access path: index (no sta/stp keys)
Index: IM_BLACKLIST_PK
TABLE: IM_BLACKLIST
RSC_CPU: 0 RSC_IO: 309
IX_SEL: 1.0000e+00 TB_SEL: 5.8204e-05
BEST_CST: 4.00 PATH: 4 Degree: 1
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***********************
Join order[1]: IM_BLACKLIST [IM_BLACKLIST]
Best so far: TABLE#: 0 CST: 4 CDN: 3 BYTES: 75
Final:
CST: 4 CDN: 3 RSC: 4 RSP: 4 BYTES: 75
IO-RSC: 4 IO-RSP: 4 CPU-RSC: 0 CPU-RSP: 0
這是昨天分析之後的
SINGLE TABLE ACCESS PATH
Column: BLACK_ID Col#: 2 Table: IM_BLACKLIST Alias: IM_BLACKLIST
NDV: 17069 NULLS: 0 DENS: 1.4470e-03
HEIGHT BALANCED HISTOGRAM: #BKT: 75 #VAL: 75
TABLE: IM_BLACKLIST ORIG CDN: 57267 ROUNDED CDN: 83 CMPTD CDN: 83
Access path: tsc Resc: 38 Resp: 38
Access path: index (equal)
Index: IM_BLACKLIST_LID_IND
TABLE: IM_BLACKLIST
RSC_CPU: 0 RSC_IO: 65
IX_SEL: 0.0000e+00 TB_SEL: 1.4470e-03
Skip scan: ss-sel 0 andv 27151
ss cost 27151
table io scan cost 38
Access path: index (no sta/stp keys)
Index: IM_BLACKLIST_PK
TABLE: IM_BLACKLIST
RSC_CPU: 0 RSC_IO: 384
IX_SEL: 1.0000e+00 TB_SEL: 1.4470e-03
BEST_CST: 38.00 PATH: 2 Degree: 1
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***********************
Join order[1]: IM_BLACKLIST [IM_BLACKLIST]
Best so far: TABLE#: 0 CST: 38 CDN: 83 BYTES: 2407
Final:
CST: 38 CDN: 83 RSC: 38 RSP: 38 BYTES: 2407
IO-RSC: 38 IO-RSP: 38 CPU-RSC: 0 CPU-RSP: 0
我發現分析之前之後全表掃描cost都是38，但是分析之後的根據索引掃描卻成為了 65 ，而分析之前是4。
很顯然是由於這個查詢導致昨天早上分析之後走了全表掃描。於是我再對錶進行了分析，只不過這次我沒有分析索引欄位，而是
analyze table im_blacklist compute statistics;
這樣之後，dbms_histograms 中資訊只剩下
COLUMN_NAME ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
------------------------------ --------------- -------------- ------------------------------
GMT_CREATE 0 2452842.68
GMT_MODIFIED 0 2452842.68
LOGIN_ID 0 2.5021E+35
BLACK_ID 0 1.6715E+35
GMT_CREATE 1 2453269.44
GMT_MODIFIED 1 2453269.44
LOGIN_ID 1 6.3594E+35
BLACK_ID 1 1.1160E+36
再執行該sql，就走了索引，從而使得資料庫的load降了下來。
分析這整個過程中，我無法知道oracle的走索引cost 65 是怎麼計算出來的，當然是跟 histograms有關，但計算方法我卻是不清楚的。
這條sql是bind var，但是卻走了全表掃描，這是由於920中資料庫在對bind var 的sql進行第一次解析的時候去histograms中窺視了資料分佈從而根據cost選擇了FTS。然後後面繼續執行的sql呢，則不論是否該走索引，都走了FTS。這是920這個版本的特性的弊病。也就是說，這有偶然性因素的存在。 但是對於這個表，我做了分析(不分析索引欄位)之後不存在histograms，則sql無論如何都走了索引掃描。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/12361284/viewspace-246236/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 使用SQL_TRACE進行資料庫診斷(轉)SQL資料庫
- 儲存意外斷電導致raid資訊丟失的解決過程AI
- sql server資料庫附加錯誤的解決過程SQLServer資料庫
- 一條Sql的執行過程SQL
- ODX 診斷資料庫轉換工具 — DDC資料庫
- SAN LUN Mapping出錯導致的資料丟失恢復全過程APP
- 解Bug之路-記一次中介軟體導致的慢SQL排查過程SQL
- Part II 診斷和優化資料庫效能優化資料庫
- 記一次使用gdb診斷gc問題全過程GC
- .記一次使用gdb診斷gc問題全過程GC
- 一次.net code中的placeholder導致的高cpu診斷
- 基於等待事件的效能診斷(轉)事件
- raid5癱瘓導致資料庫損壞的恢復過程AI資料庫
- Optional 的使用會導致效能下降嗎？
- 一條主鍵索引SQL導致的CPU被打滿索引SQL
- MySQL 中一條 sql 的執行過程MySql
- 一條 sql 的執行過程詳解SQL
- 一條sql語句的執行過程SQL
- MySQL 預插入的資料條數過多導致異常MySql
- MySQL使用event等待事件進行資料庫效能診斷MySql事件資料庫
- 一次DG故障診斷過程分析
- 如何診斷和解決db2問題DB2
- 【資料庫資料恢復】透過資料頁恢復Sql Server資料庫資料的過程資料庫資料恢復SQLServer
- 如何解決SQL Server資料庫的軟硬體效能瓶頸OCSQLServer資料庫
- 【資料庫資料恢復】斷電導致Oracle資料庫資料丟失的資料恢復案例資料庫資料恢復Oracle
- 一次死鎖導致CPU異常飄高的整個故障排查過程
- Sql Server 資料庫中呼叫dll檔案的過程SQLServer資料庫
- 一次對pool的誤用導致的.net頻繁gc的診斷分析GC
- 有問題的mybatis的sql導致對資料庫進行了批量的修改MyBatisSQL資料庫
- 如何分析一條sql的效能SQL
- 效能分析（5）- 軟中斷導致 CPU 使用率過高的案例
- Spark效能優化：診斷記憶體的消耗Spark優化記憶體
- 【資料庫】資料庫儲存過程(一)資料庫儲存過程
- 【恩墨學院】基於裸資料的異地資料庫效能診斷與最佳化資料庫
- MongoDB 分片叢集均衡器導致的效能下降MongoDB
- sql 多組條資料取最新的一條資料SQL
- 【資料庫資料恢復】Sql Server資料庫檔案丟失的資料恢復過程資料庫資料恢復SQLServer
- go 協程操作map導致的資料競爭及解決方法Go
- 【資料庫資料恢復】磁碟空間不足導致sql server錯誤的資料恢復資料庫資料恢復SQLServer