mysql one thread cpu 100%

標籤：kth   統一   cli   5.5   cal   sch   com   cache   效能最佳化   

昨天晚上，營運過來說有台生產伺服器的mysql cpu一直100%，新的用戶端登入不了，但是已經在啟動並執行應用都正常可用。

登入伺服器後，top -H看了下，其中一個線程的cpu 一直100%，其他的幾乎都空閑。

MySQL thread id 14560536, OS thread handle 0x7f1255ef1700, query id 31889137761 10.26.124.8 osm cleaning up

top - 18:56:26 up 62 days, 3:55, 3 users, load average: 1.08, 1.13, 1.18
Tasks: 1503 total, 2 running, 1501 sleeping, 0 stopped, 0 zombie
Cpu(s): 12.9%us, 0.2%sy, 0.0%ni, 86.9%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 16333644k total, 15440672k used, 892972k free, 45652k buffers
Swap: 4153340k total, 0k used, 4153340k free, 1050524k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15669 mysql 20 0 8338m 5.9g 5808 R 100.0 38.1 162:29.18 mysqld
29679 rabbitmq 20 0 4315m 154m 1780 S 1.3 1.0 1162:54 beam.smp
3887 root 20 0 16092 2360 940 R 0.7 0.0 0:00.27 top
426 root 20 0 68020 6136 4244 S 0.3 0.0 0:03.34 AliYunDun
427 root 20 0 68020 6136 4244 S 0.3 0.0 0:02.62 AliYunDun
430 root 20 0 68020 6136 4244 S 0.3 0.0 0:08.37 AliYunDun
432 root 20 0 68020 6136 4244 S 0.3 0.0 0:05.34 AliYunDun
1247 root 20 0 245m 49m 1604 S 0.3 0.3 28:40.31 AliHids
1249 root 20 0 245m 49m 1604 S 0.3 0.3 10:17.96 AliHids
3653 root 20 0 113m 1572 932 S 0.3 0.0 0:00.11 wrapper
12293 root 20 0 9722m 1.3g 5940 S 0.3 8.6 20:10.09 java
16457 root 20 0 8710m 166m 5772 S 0.3 1.0 1:52.67 java
16914 root 20 0 9864m 168m 5808 S 0.3 1.1 19:30.97 java
29680 rabbitmq 20 0 4315m 154m 1780 S 0.3 1.0 578:21.03 beam.smp
1 root 20 0 19356 800 500 S 0.0 0.0 0:02.80 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.03 kthreadd
3 root RT 0 0 0 0 S 0.0 0.0 0:15.65 migration/0
4 root 20 0 0 0 0 S 0.0 0.0 0:32.07 ksoftirqd/0
5 root RT 0 0 0 0 S 0.0 0.0 0:00.00 stopper/0
6 root RT 0 0 0 0 S 0.0 0.0 0:05.98 watchdog/0

這個問題已經發生過接近10來次了，只不過之前除了一兩次是其他的生產系統外，大部分發生在開發環境，一直也沒找到原因，一旦kill這個線程，就導致mysql執行個體被kill並自動重啟了。

因為之前發生過，沒解決，所以剛好那台伺服器的Innodb_monitor開著，但是根據時間往後退算到差不多出問題的那一刻，只看到有一個事務從出問題開始一直持續運行了差不多20多分鐘，如下：

FILE I/O
--
MySQL thread id 14560536, OS thread handle 0x7f122db3c700, query id 31889113153 10.26.124.8 osm cleaning up
---TRANSACTION 604639618, ACTIVE 1248 sec
MySQL thread id 14561064, OS thread handle 0x7f122db3c700, query id 31887588399 125.118.111.42 osm cleaning up
--------
FILE I/O
--
MySQL thread id 14560536, OS thread handle 0x7f122db3c700, query id 31889113154 10.26.124.8 osm cleaning up
---TRANSACTION 604639618, ACTIVE 1268 sec
MySQL thread id 14561064, OS thread handle 0x7f122db3c700, query id 31887588399 125.118.111.42 osm cleaning up
--------
FILE I/O
--
MySQL thread id 14560536, OS thread handle 0x7f122db3c700, query id 31889113373 10.26.124.8 osm cleaning up
---TRANSACTION 604639618, ACTIVE 1288 sec
MySQL thread id 14561064, OS thread handle 0x7f122db3c700, query id 31887588399 125.118.111.42 osm cleaning up

因為所有的系統配置參數、mysql都是統一的，OS版本、核心版本都是一致的，所以應該不是版本和某個參數導致的問題。

跟相關營運確認的時候，只說用gui串連過，但是沒有做運行慢的操作比如直接通過navicat進行匯出等操作。所以這個問題比較像之前遇到的記憶體問題，光靠類比它好像永遠不出來，但某個時間就出來了。

strace和ltrace也沒看出什麼問題，那會兒實在比較鬱悶。。。折騰到後來，mysqld不知怎麼被不小心的killed了。

早上回來，繼續研究，搜了bing半天，最後在mysql buglist發現就是5.5.23之前有個performance_schema的bug，跟我們的現象極為相似，如下：

http://bugs.mysql.com/bug.php?id=64491

http://lists.mysql.com/commits/143350?f=plain

one thread call sched_yield(), but other threads are‘t ready run. so cause cpu 100%.

 但根據開發人員所說這個問題在5.5.23以及5.6.6就已經修複，我們使用的是percona server 5.6.31，理論上應該不會出現這個bug的。

因為現在沒有當時的現場了，只能等下次出現gdb上去看下，那個出問題的線程在執行什麼操作了，還是非c++出身gdb不熟導致的，哎。。。這個負責效能最佳化的gdb/wireshark真得熟悉的滾瓜爛熟，不然有些詭異的現象光通過伺服器本身提供的API和CLI和一些進階工具真不能定位到原因啊。。

mysql one thread cpu 100%