記一次生產數據庫"意外"重啓的經歷

時間  2020-02-04
標籤 一次 生產 數據庫 意外 重啓 經歷 欄目 SQL 简体版
原文   原文鏈接

記一次生產數據庫"意外"重啓的經歷

前言

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

排查

先交代一下數據庫版本：html

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內存不足時。mysql

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

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:

小夥伴們繼續往下看：ssh

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 就是哪一個「罪人」。ide

隨後 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://blog.52itstyle.vip/archives/3554/

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

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程