【案例】常駐查詢引發的thread pool 效能問題之二

風塵_NULL發表於2017-02-17
一 現象 
   某業務單機4個例項中的一個例項出現連線數遠高於其他三個例項(正常是4K,問題例項是8K+),但是這4個例項的配置完全相同。業務開發反饋為部分連線失敗。   
 執行show processlist結果顯示:
      存在大量的Killed狀態的連線126個,處於Connect狀態的6K+,以及6個binlog dump連線(如果看了前面一篇文章是否有點觸動,會不會是這個導致的?)
  執行pt-pmp結果顯示:
      mysqld 十分的空閒
  執行show engine innodb status:
    不存在空閒大事務

二 處理
     根據上一篇文章的知識,初步判斷該資料庫例項遇到為Thread Pool的部分group被阻塞了,(能把query堵在login階段的大部分為threadpool排程的問題,當然也不排除是因為邏輯原因造成login中出現內部鎖等待)
在調整thread_pool_oversubscribe後所有的Connect/Killed狀態的連線全部消失,連線數恢復正常。

三 問題分析
     雖然問題是解決了,但是還有大量的疑問存在,顯然在原因未知的情況下,如果在業務高峰期意外出現類似現象,後果非常嚴重,因此我們開始挖掘深層次的原因。
【曲折】
     既然調整thread_pool_oversubscribe後問題就解決了,很顯然是有group被阻塞了,因此最重要的就是找出是什麼阻塞了Thread Pool
     這次最能引起人注意的現象當然是這126個Killed狀態的連線了,我們知道當連線在執行中,被kill後處於回滾階段時,會顯示Killed。一般來說這個階段非常短暫(除非有大量的rollback工作,但是State資訊是空的,顯然不是在rollback),pt-pmp的結果也證明了這一點。最開始一直懷疑是這些Killed的連線阻塞了threadpool的某些group,但是想來想去沒有想到合理的解釋,這裡浪費了很多的時間。
【柳暗花明】
   在Killed session上走不通,那隻能看看其他session了,這時發現被阻塞的Connect連線的thread id十分有規律:
  1. | 4261587 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
  2. | 4261619 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
  3. | 4261651 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
  4. | 4261683 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
  5. | 4261715 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
  6. | 4261747 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   間隔32遞增,很明顯是其中一個group被阻塞了。對32取模後發現全部為19號group,那看來是binlog dump沒跑了。
對binlog dump執行緒的thread id對32取模後發現,6個thread中有4個在19號group中,而thread_pool_oversubscribe才3(內部限制為3+1),因此把19號group完全堵死。
到這裡完全解釋了本次擁堵產生的原因。本次問題中的126個Killed session極大的誤導了我們的判斷。

【深入分析】
   回過頭來有人會問,那126個Killed session是怎麼來的呢?
這裡就需要講一下Thread Pool對kill處理的原理:
  1. 當一個正在執行的連線被kill的時候,它所執行的sql會失敗,其thd->killed會被置為THD::KILL_CONNECTION,同時通知Thread Pool(回撥函式)。Thread Pool在回撥函式中會發出一個io訊號,worker需要捕獲這個event(和正常的event一樣處理)後,才會退出這個session,否則一直可以在show processlist看上類似本例子中126個session的狀態。
但是本case中,在這126個session被kill以後,剛好有一個binlog dump連線連到了即將擁堵的19號group。
  1. | 4261363 | xxxx | 10.9.6.57:10843| xxxx_0133 | Killed  | 246196 |                                                                 | NULL |
  2. | 4261395 | xxxx | 10.8.9.18:35401| xxxx_0133 | Killed  | 246186 |                                                                 | NULL |
  3. | 4261459 | xxxx | 10.8.2.61:60919| NULL| Binlog Dump | 246110| Master has sent all binlog to slave; waiting for binlog to be updated | NULL |
  4. | 4261491 | unauthenticated user  | connecting host | NULL    | Connect    | NULL   | login                                           | NULL |
  5. | 4261502 | xxxx  | 10.8.2.41:11862 | xxxx_0133 | Sleep       | 1      |                                                              | NULL |
  6. | 4261523 | unauthenticated user   | connecting host | NULL   | Connect     | NULL   | login                                          | NULL |
看上圖緊跟在Killed連線後面的4261459連線,使得19號group徹底被堵住,可憐的Killed連線連退出的機會都沒有了,這就是這126個Killed連線的由來...

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

相關文章