Percona MySQL5.7內存OOM案例導致重啟的memory和thread分析

前言

在一個陽光明媚的下午，電腦右下角傳來一片片郵件提醒，同時伴隨着微信釘釘的震動，打開一看，應用各種出錯，天兔告警，數據庫服務器內存爆紅，Mysql數據庫實例掛掉了。

排查

先交代一下數據庫版本：

mysql> status
--------------
mysql  Ver 14.14 Distrib 5.7.22-22, for Linux (x86_64) using 6.2 Connection id: 59568 Current database: Current user: root@localhost SSL: Not in use Current pager: stdout Using outfile: '' Using delimiter: ; Server version: 5.7.22-22-log Percona Server (GPL), Release 22, Revision f62d93c Protocol version: 10

崩潰故障排除絕不是一項有趣的任務，特別是如果MySQL沒有報告崩潰的原因。例如，當MySQL內存不足時。

數據庫郵件告警提醒發來的消息：

Type: mysql Tags: 生產主庫 Host: 172.16.1.66:3306 Level: critical Item: connect Value: down Message: mysql server down

登錄 Grafana 監控面板，數據庫連接在哪個時間段曾有幅度的增長。

順手檢查一下之前的服務器郵件監控告警記錄，上一個時間點，內存占用率99%，這說明了數據庫連接的幅度增長，可能是壓垮服務器的最后一根稻草。

其實導致OOM的直接原因並不復雜，就是因為服務器內存不足，內核需要回收內存，回收內存就是kill掉服務器上使用內存最多的程序，而MySQL服務可能就是使用內存最多，所以就OOM了。

Type: os Tags: 66數據庫 Host: 172.16.1.66: Level: critical Item: memory Value: 99% Message: too more memory usage

查看系統日志

我們帶着這個疑問來排查一下日志：

# 查看日志 tail -500f /var/log/messages # 以下是 oom-killer Nov 27 14:55:48 itstyledb1 kernel: mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0 Nov 27 14:55:48 itstyledb1 kernel: mysqld cpuset=/ mems_allowed=0-1 Nov 27 14:55:48 itstyledb1 kernel: CPU: 2 PID: 895 Comm: mysqld Kdump: loaded Not tainted 3.10.0-862.3.2.el7.x86_64 #1 Nov 27 14:55:48 itstyledb1 kernel: Hardware name: Huawei RH1288 V3/BC11HGSC0, BIOS 3.22 05/16/2016 Nov 27 14:55:48 itstyledb1 kernel: Call Trace:

小伙伴們繼續往下看：

0 pages HighMem/MovableOnly Nov 27 14:55:48 itstyledb1 kernel: 291281 pages reserved Nov 27 14:55:48 itstyledb1 kernel: [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name Nov 27 14:55:48 itstyledb1 kernel: [ 468] 0 468 28271 4326 62 55 0 systemd-journal Nov 27 14:55:48 itstyledb1 kernel: [ 490] 0 490 11492 2 24 553 -1000 systemd-udevd Nov 27 14:55:48 itstyledb1 kernel: [ 787] 0 787 13877 18 27 96 -1000 auditd Nov 27 14:55:48 itstyledb1 kernel: [ 810] 81 810 14552 81 34 89 -900 dbus-daemon Nov 27 14:55:48 itstyledb1 kernel: [ 815] 0 815 55956 1 60 466 0 abrtd Nov 27 14:55:48 itstyledb1 kernel: [ 816] 0 816 55327 9 64 346 0 abrt-watch-log Nov 27 14:55:48 itstyledb1 kernel: [ 818] 0 818 121607 220 90 495 0 NetworkManager Nov 27 14:55:48 itstyledb1 kernel: [ 822] 0 822 5415 49 16 33 0 irqbalance Nov 27 14:55:48 itstyledb1 kernel: [ 823] 997 823 134634 97 60 1306 0 polkitd Nov 27 14:55:48 itstyledb1 kernel: [ 825] 0 825 6594 42 20 41 0 systemd-logind Nov 27 14:55:48 itstyledb1 kernel: [ 830] 0 830 31578 28 21 139 0 crond Nov 27 14:55:48 itstyledb1 kernel: [ 839] 0 839 27522 2 10 31 0 agetty Nov 27 14:55:48 itstyledb1 kernel: [ 1142] 0 1142 143454 114 97 2672 0 tuned Nov 27 14:55:48 itstyledb1 kernel: [ 1144] 0 1144 28203 11 59 246 -1000 sshd Nov 27 14:55:48 itstyledb1 kernel: [ 1145] 0 1145 97438 694 103 328 0 rsyslogd Nov 27 14:55:48 itstyledb1 kernel: [ 1369] 0 1369 22526 20 44 256 0 master Nov 27 14:55:48 itstyledb1 kernel: [ 1371] 89 1371 22596 32 46 251 0 qmgr Nov 27 14:55:48 itstyledb1 kernel: [ 5140] 0 5140 5102 1617 15 239 0 mysqld_exporter Nov 27 14:55:48 itstyledb1 kernel: [ 9430] 0 9430 55966 378 62 790 0 snmpd Nov 27 14:55:48 itstyledb1 kernel: [30320] 27 30320 22951376 13928375 43437 8163662 0 mysqld Nov 27 14:55:48 itstyledb1 kernel: [ 688] 89 688 22552 271 46 0 0 pickup Nov 27 14:55:48 itstyledb1 kernel: Out of memory: Kill process 30320 (mysqld) score 984 or sacrifice child Nov 27 14:55:48 itstyledb1 kernel: Killed process 30320 (mysqld) total-vm:91805504kB, anon-rss:55713500kB, file-rss:0kB, shmem-rss:0kB Nov 27 14:56:00 itstyledb1 systemd: mysqld.service: main process exited, code=killed, status=9/KILL Nov 27 14:56:00 itstyledb1 systemd: Unit mysqld.service entered failed state. Nov 27 14:56:00 itstyledb1 systemd: mysqld.service failed. Nov 27 14:56:00 itstyledb1 systemd: mysqld.service holdoff time over, scheduling restart. Nov 27 14:56:01 itstyledb1 systemd: Starting MySQL Server...

當out of memory發生時，out_of_memory函數會選擇一個內核認為犯有分配過多內存 “罪行”的進程，並殺死該進程。顯然 Mysql 就是哪個“罪人”。

隨后 MySql 會自動重啟。重啟以后，內存是下來了，但是臨近下班的時候，差不多又又又占滿了。

[root@itstyledb1 ~]# free -m total used free shared buff/cache available Mem: 55803 54976 241 10 585 349 Swap: 32064 25036 7028

找到MySql進程，執行以下top -p pid，內存使用52.4g

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 935 mysql 20 0 79.7g 52.4g 7336 S 0.3 96.1 255:44.76 mysqld

計算內存使用

1)查看MySQL全局占用多少內存

SELECT (@@innodb_buffer_pool_size +@@innodb_log_buffer_size +@@key_buffer_size) / 1024 /1024 AS MEMORY_MB;

查詢結果為：

+----------------+ | MEMORY_MB | +----------------+ | 20512.00000000 | +----------------+

2）查看performance_schema占用多少內存

SELECT SUBSTRING_INDEX(event_name,'/',2) AS code_area, sys.format_bytes(SUM(current_alloc)) AS current_alloc FROM sys.x$memory_global_by_current_bytes GROUP BY SUBSTRING_INDEX(event_name,'/',2) ORDER BY SUM(current_alloc) DESC;

查詢結果為：

+---------------------------+---------------+ | code_area | current_alloc | +---------------------------+---------------+ | memory/performance_schema | 349.80 MiB | +---------------------------+---------------+

3）查看每個線程占用多少內存

SELECT ( ( @@read_buffer_size + @@read_rnd_buffer_size + @@sort_buffer_size + @@join_buffer_size + @@binlog_cache_size + @@thread_stack + @@max_allowed_packet + @@net_buffer_length ) ) / (1024*1024) AS MEMORY_MB;

查詢結果為：

+-----------+ | MEMORY_MB | +-----------+ | 87.5156 | +-----------+

查看當前線程

show full processlist

最終結果為：

+-----------+ | MEMORY_MB | +-----------+ | 87.5156*37| +-----------+

4）查看 memory 存儲引擎占用多少內存

SELECT SUM(max_data_length)/1024/1024 AS MEMORY_MB FROM information_schema.tables WHERE ENGINE='memory';

查詢結果為：

+---------------+ | MEMORY_MB | +---------------+ | 3857.37713909 | +---------------+

以上四項加起來差不多也就27975MB，差不錯28G的樣子，但是 MySql 進程顯示占用了52.4G，那么剩下24.4G去哪了？

線程池

此線程池非彼連接池，其實兩者是有很大區別的，連接池一般在客戶端設置，而線程池是在DB服務器上配置；另外連接池可以取到避免了連接頻繁創建和銷毀，但是無法取到控制MySQL活動線程數的目標，在高並發場景下，無法取到保護DB的作用。比較好的方式是將連接池和線程池結合起來使用。

關於線程池的一些參數：

mysql> show variables like 'thread%'; +-------------------------------+---------------------------+ | Variable_name | Value | +-------------------------------+---------------------------+ | thread_handling | one-thread-per-connection | | thread_pool_high_prio_mode | transactions | | thread_pool_high_prio_tickets | 4294967295 | | thread_pool_idle_timeout | 60 | | thread_pool_max_threads | 100000 | | thread_pool_oversubscribe | 3 | | thread_pool_size | 12 | | thread_pool_stall_limit | 500 | +-------------------------------+---------------------------+

thread_handling：

該參數是配置線程模型，默認情況是one-thread-per-connection，也就是不啟用線程池。將該參數設置為pool-of-threads即啟用了線程池。

thread_pool_size：

該參數是設置線程池的Group的數量，默認為系統CPU的個數，充分利用CPU資源。

thread_pool_oversubscribe：

該參數設置group中的最大線程數，每個group的最大線程數為thread_pool_oversubscribe+1，注意listener線程不包含在內。

thread_pool_high_prio_mode：

高優先級隊列的控制參數，有三個值（transactions/statements/none），默認是transactions，三個值的含義如下：

• transactions：對於已經啟動事務的語句放到高優先級隊列中，不過還取決於后面的thread_pool_high_prio_tickets參數

• statements：這個模式所有的語句都會放到高優先級隊列中，不會使用到低優先級隊列

• none：這個模式不使用高優先級隊列

thread_pool_high_prio_tickets：

該參數控制每個連接最多語序多少次被放入高優先級隊列中，默認為4294967295，注意這個參數只有在thread_pool_high_prio_mode為transactions的時候才有效果。

thread_pool_idle_timeout：

worker線程最大空閑時間，默認為60秒，超過限制后會退出。

thread_pool_max_threads：

該參數用來限制線程池最大的線程數，超過該限制后將無法再創建更多的線程，默認為100000。

thread_pool_stall_limit：

該參數設置timer線程的檢測group是否異常的時間間隔，默認為500ms。

最終配置如下：

#thread pool thread_handling=pool-of-threads #Group的數量，默認為系統CPU的個數，充分利用CPU資源 thread_pool_size=24 #每個group的最大線程數為thread_pool_oversubscribe+1 thread_pool_oversubscribe=3 performance_schema=off #extra connection，防止線程池滿的情況下無法登錄MySQL extra_max_connections = 8 extra_port = 33333

備注：線程池在Percona,MariaDB,Oracle MySQL企業版中提供，Oracle MySQL社區版並不提供。

線程池貌似並不會直接導致內存不回收，網上有說同時開啟Thread pool和PS會出現內存泄露，但是
目前Percona server 5.7.21-20+版本已經修復了這個問題，顯然是不存在的。

慢查詢

由於是生產環境，這個問題拖得時間有點長，那么慢查詢會不會影響內存使用問題呢？帶着這個問題，查看了慢查詢后台列表，在數據庫奔潰的前一個時間段，的確有不少慢查詢語句。但是這並不能在一定程度上說明問題，由於服務器的 MySql 服務在殺死之前，內存已經見底，此時連接數並不多，也就三四十來個左右，大多處於休眠狀態，並且此時已經占用了大部分的Swap空間。也就是說，在資源有限的情況下必定會出現不少慢查詢語句。

小結

其實這個"意外"一點也不意外，其實已經發生了多次了。但是還是做個小結吧，因為最終沒有確認問題出現在哪里，所以還是發布了吧，萬一有專業的DBA遇到類似的問題還可以小小的解惑一下。

參考

https://bugs.mysql.com/bug.php?id=91861

https://bugs.mysql.com/bug.php?id=91710

https://dev.mysql.com/doc/refman/5.7/en/memory-use.html

https://www.percona.com/blog/2018/06/28/what-to-do-when-mysql-runs-out-of-memory-troubleshooting-guide/

https://dev.mysql.com/doc/refman/5.7/en/thread-pool-tuning.html