记一次生产数据库"意外"重启的经历

前言

在一个阳光明媚的下午，电脑右下角传来一片片邮件提醒，同时伴随着微信钉钉的震动，打开一看，应用各种出错，天兔告警，数据库服务器内存爆红，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