一次效能突發情況的緊急修復(r9筆記第18天)
昨天中午的時候，接到開發同學的電話，說有一個線上資料遷移，碰到了一些問題，希望我能夠幫忙看看是哪裡的原因。
從電話裡的反饋得知，他們在做業務數遷移，會把資料庫1中的資料遷移到資料庫2中，當然會根據邏輯要求遷移大部分的資料。基於這種邏輯的複雜性，所以這次 遷移時由開發同學來主導，我們來負責支援。從他們的描述，遷移之後有一些頁面直接卡住不動了。影響到了內部的一些業務，所以希望我能夠緊急協助看看能不能 優化一下。
趕到公司之後，首先我查看了整體的複雜情況，發現CPU使用率較高。top的結果如下：
top - 10:01:59 up 962 days, 15:53, 2 users, load average: 5.64, 5.10, 4.25
Tasks: 329 total, 3 running, 319 sleeping, 0 stopped, 7 zombie
Cpu(s): 28.9%us, 1.0%sy, 0.0%ni, 49.7%id, 20.3%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 32867892k total, 32660452k used, 207440k free, 16280k buffers
Swap: 16777200k total, 7332520k used, 9444680k free, 29440936k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11588 oracle 20 0 12.0g 43m 43m R 99.8 0.1 29809:08 oraclehadoop (LOCAL=NO)
20028 oracle 20 0 12.0g 143m 143m R 99.8 0.4 29796:54 oraclehadoop (LOCAL=NO)
8851 oracle 20 0 12.0g 944m 924m D 29.2 2.9 5:52.34 oraclehadoop (LOCAL=NO)
19119 mysql 20 0 8605m 1.1g 4148 S 2.7 3.6 62546:09 /usr/sbin/mysqld --basedir=/usr/ --datadir=/home/mysql_3306 --plugin-di
22408 oracle 20 0 12.0g 1.3g 1.3g D 2.0 4.0 0:19.05 oraclehadoop (LOCAL=NO)
$ sh showpid.sh 11588 ******************************************* Process has found, pid: 11588 , addr: 000000034F08CAE0 ####### Process Information from OS level as below ######## oracle 11588 1 99 May10 ? 20-16:50:45 oraclehadoop (LOCAL=NO) oracle 26906 26639 0 10:03 pts/2 00:00:00 sh showpid.sh 11588 ############################################## SID SERIAL# USERNAME OSUSER MACHINE PROCESS TERMINAL TYPE LOGIN_TIME ---------- ---------- --------------- --------------- -------------------- --------------- --------------- ---------- ------------------- 572 43627 APP_XXX_BG xxxx xxxxxx 5312:9940 XXXX USER 2016-05-10 16:19:19 SQL_ID SQL_TEXT ------------------------------ ------------------------------------------------------------ af3gvjsgn5d06 select clicktime from ua_td_click_log where not regexp_like (clicktime, '^(-{0,1}+{0,1})[0-9]+(.{0,1}[0-9]+)$')
看到這個語句，著實讓我嚇了一跳，也折射出對於這方面監控還不到位，裡面有個會話竟然活躍天數達到了20多天。而執行的語句就是一個簡單的select. 查看了執行計劃，資源消耗還是很驚人的。所以當即和開發同學取得了聯絡，他們確認可以清理掉這兩個會話。 kill session這類操作我們需要給自己留一點後路，那就是在kill之前呢還是要找到指定的程序號，這樣在資料庫層面kill session後，可以馬上在系統層面可以驗證是否資源合理釋放，而如果資料庫層面處理不夠到位，我們還可以從系統層面來輔助，當然這充分證明我的猜想。 kill session果真出現了延遲，會話被標記為KILLED，但是遲遲沒有釋放系統資源，這個時候從系統層面來進一步清理來輔助，在系統層面清理了程序之 後，資料庫層面的會話資源馬上就得到了釋放。 當然這個處理只是一個很自然的排查思路，可以處理一些看起來很明顯的問題，但是我們需要進一步思考，這個系統目前有系統的頁面來呼叫顯示實時資料，但是目 前業務系統頁面是卡頓的，說明這個語句存在問題，而目前找到的兩個top會話相關的資料是兩個開發人員連線資料的客戶端，純屬個人行為，和業務系統的卡頓 影響不大。還有一個問題就是iowait,可以看到系統的iowait還是很高的。如果單單是查詢不足以產生這樣的影響，而且也說不通，我們需要著重關注 那些DML語句。 所以這個時候問題分析才剛剛開始，我們需要關注那些資源消耗較高的會話，可以結合ASH繫結v$session來處理，可以看到當前的活躍會話執行的 SQL情況。果然不出所料，發現了大量的會話執行SQL的時間超過了30分鐘，有些持續近1個小時，這些會話執行的語句都是指向了一個select,一個 insert，如此一來，問題似乎就說得通了。當然為什麼insert會卡頓，主要原因還是在於insert語句是子查詢的形式，根本還是在於 select的問題。經過一番分析，這樣的語句有2個。 面對這種情況，和開發同學進行了進一步溝通，首先先清理了哪些持續時間依舊的會話，然後他們調整語句的執行頻度，關注執行情況，我在後臺分析語句的執行計 劃情況。因為語句很長，而且執行計劃較為複雜，涉及的表又很多，很快得出一個行之有效的方案著實是有難度的，但是和開發同學的反饋得知，這個系統是從資料 庫1遷移而來，在資料庫1中執行還是很快的，他們從前臺的頁面就有直觀的感受，有了這一點非常寶貴的資訊之後，為問題的分析和排查就提供了很有效的幫助。 我在源資料庫中檢視到了同樣的SQL_ID的語句，發現執行計劃確實存在一些差別，兩個庫中的表結構都是一致的，資料基本一致，出現這種情況，首先要排除 統計資訊的干擾，當然我在目標庫中分析之後也嘗試收集了統計資訊，但是開發再次執行查詢問題還是依舊。所以由此可見統計資訊並沒有對語句的執行計劃產生根 本性的改進。 對於這個問題，我抓緊使用Tuning包收集了一個報告，Oracle給出的建議是調整一些索引，調整執行計劃等，這些索引可以按照建議的方式去加，但是 風險不可控，很可能添加了索引之後，其它相關的語句的執行計劃也會隨著影響，這種牽一髮而動全身的方式還是有一些風險。 我們可以移花積木，把源庫中的執行計劃關鍵資訊拷貝出來，直接替換目標庫中的執行計劃。這個工作聽起來還是挺有意思，用SQLT實現就會很輕鬆。我用 SQLT指定的包匯出了執行計劃的詳細資訊，然後拷貝到目標端。調整之後再次讓開發同學密切關注，發現語句的效能一下子就好了很多，原來的CPU使用率問 題馬上得到了環節，而iowait也隨著語句的改進也保持在一個很低的值。這個操作就充分證明了調優的效果還是很明顯的。 後面持續關注，根據開發同學的反饋，業務都恢復了正常，終於鬆了一口氣。 而這類問題我們需要跟進一步，來探索一下為什麼同樣表結構，基本一致的資料為什麼會產生截然不同的SQL語句，我相信結局一定讓人唏噓感嘆。