[奇葩问题] ERROR 2013 (HY000): Lost connection to MySQL server during query
查询一条耗时30s以上语句，实际为2分钟多。
mysql> select version(); +------------+ | version() | +------------+ | 5.6.30-log | +------------+ 1 row in set (0.12 sec) mysql> select * from message_1707 where create_date >'2017-01-01' limit 10; ERROR 2013 (HY000): Lost connection to MySQL server during query mysql> show variables like 'innodb_buffer_pool_size'; +-------------------------+------------+ | Variable_name | Value | +-------------------------+------------+ | innodb_buffer_pool_size | 3221225472 | +-------------------------+------------+ 1 row in set (0.00 sec)
官方给的参考：https://dev.mysql.com/doc/refman/5.7/en/error-lost-connection.html，调整net_read_timeout后问题依旧，此时又发现公司的网络丢包貌似挺严重，远程服务器又由阿里云DNAT改为SLB端口转发，但是问题依旧。
后面又捕捉到一个细节，二次查询提示重连数据库，说明数据库被重启了，期间并没有其他同事远程该台机器操作。
mysql> select * from message_1707 where create_date >'2017-01-01' limit 10; ERROR 2006 (HY000): MySQL server has gone away No connection. Trying to reconnect... Connection id: 16 Current database: bluestore_core_log ERROR 2013 (HY000): Lost connection to MySQL server during query
查看系统日志，mysqld服务确实被重启了，但没有详细错误信息。
[root@HD1_db_archive ~]# tail -f /var/log/mysqld.log 2018-04-26 15:29:54 17062 [Note] InnoDB: 128 rollback segment(s) are active. 2018-04-26 15:29:54 17062 [Note] InnoDB: Waiting for purge to start 2018-04-26 15:29:54 17062 [Note] InnoDB: 5.6.30 started; log sequence number 164799934660 2018-04-26 15:29:54 17062 [Note] Server hostname (bind-address): '*'; port: 3306 2018-04-26 15:29:54 17062 [Note] IPv6 is available. 2018-04-26 15:29:54 17062 [Note] - '::' resolves to '::'; 2018-04-26 15:29:54 17062 [Note] Server socket created on IP: '::'. 2018-04-26 15:29:54 17062 [Note] Event Scheduler: Loaded 0 events 2018-04-26 15:29:54 17062 [Note] /usr/local/mysql/bin/mysqld: ready for connections. Version: '5.6.30-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL) 180426 15:31:53 mysqld_safe Number of processes running now: 0 180426 15:31:53 mysqld_safe mysqld restarted 2018-04-26 15:31:53 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.6.30-log) starting as process 17143 ... 2018-04-26 15:31:53 17143 [Note] Plugin 'FEDERATED' is disabled. 2018-04-26 15:31:53 17143 [Note] InnoDB: Using atomics to ref count buffer pool pages 2018-04-26 15:31:53 17143 [Note] InnoDB: The InnoDB memory heap is disabled 2018-04-26 15:31:53 17143 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2018-04-26 15:31:53 17143 [Note] InnoDB: Memory barrier is not used 2018-04-26 15:31:53 17143 [Note] InnoDB: Compressed tables use zlib 1.2.3 2018-04-26 15:31:53 17143 [Note] InnoDB: Using Linux native AIO 2018-04-26 15:31:53 17143 [Note] InnoDB: Using CPU crc32 instructions 2018-04-26 15:31:53 17143 [Note] InnoDB: Initializing buffer pool, size = 3.0G 2018-04-26 15:31:53 17143 [Note] InnoDB: Completed initialization of buffer pool 2018-04-26 15:31:53 17143 [Note] InnoDB: Highest supported file format is Barracuda. 2018-04-26 15:31:53 17143 [Note] InnoDB: The log sequence numbers 164799934660 and 164799934660 in ibdata files do not match the log sequence number 164799934670 in the ib_logfiles! 2018-04-26 15:31:53 17143 [Note] InnoDB: Database was not shutdown normally! 2018-04-26 15:31:53 17143 [Note] InnoDB: Starting crash recovery. 2018-04-26 15:31:53 17143 [Note] InnoDB: Reading tablespace information from the .ibd files... 2018-04-26 15:31:53 17143 [Note] InnoDB: Restoring possible half-written data pages 2018-04-26 15:31:53 17143 [Note] InnoDB: from the doublewrite buffer... 2018-04-26 15:31:54 17143 [Note] InnoDB: 128 rollback segment(s) are active. 2018-04-26 15:31:54 17143 [Note] InnoDB: Waiting for purge to start 2018-04-26 15:31:54 17143 [Note] InnoDB: 5.6.30 started; log sequence number 164799934670 2018-04-26 15:31:54 17143 [Note] Server hostname (bind-address): '*'; port: 3306 2018-04-26 15:31:54 17143 [Note] IPv6 is available. 2018-04-26 15:31:54 17143 [Note] - '::' resolves to '::'; 2018-04-26 15:31:54 17143 [Note] Server socket created on IP: '::'. 2018-04-26 15:31:54 17143 [Note] Event Scheduler: Loaded 0 events 2018-04-26 15:31:54 17143 [Note] /usr/local/mysql/bin/mysqld: ready for connections. Version: '5.6.30-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
其实一开始查询大表的时候是正常，我调整过innodb_buffer_pool_size = 3G，正常前4G的机器并没有配置此项，按默认值。换成2G后，查询变正常了（解决方案是调低innodb_buffer_pool_size）。
mysql> select * from message_1707 where create_date >'2017-01-01' limit 10; +----------+--------------------+--------------------+---------------------+-----------------+-------------+------------+---------------------------+---------------------+ | id | content | expressNo | receive_date | receiver_mobile | send_result | express_id | error_desc | create_date | +----------+--------------------+--------------------+---------------------+-----------------+-------------+------------+---------------------------+---------------------+ | 32089073 | 取件成功通知 | 280589800000 | 2016-12-31 16:33:01 | 1847633xxxx | 0 | 18897191 | 微信平台-发送成功 | 2017-01-01 00:00:01 | | 32089074 | 取件成功通知 | 667193800000 | 2016-12-31 12:22:04 | 1885927xxxx | 0 | 18878152 | 微信平台-发送成功 | 2017-01-01 00:00:05 | | 32089075 | 取件成功通知 | VIP_NH0100000002 | 2016-12-31 12:24:46 | 1360601xxxx | 0 | 18878542 | 微信平台-发送成功 | 2017-01-01 00:00:11 | | 32089076 | 取件成功通知 | 883942483995100000 | 2016-12-31 13:29:31 | 1385005xxxx | 0 | 18884697 | 微信平台-发送成功 | 2017-01-01 00:00:15 | | 32089077 | 取件成功通知 | 211365200000 | 2016-12-31 12:22:43 | 1332832xxxx | 0 | 18878245 | 微信平台-发送成功 | 2017-01-01 00:00:16 | | 32089078 | 取件成功通知 | 533148560000 | 2016-12-31 10:45:45 | 1598583xxxx | 0 | 18864370 | 微信平台-发送成功 | 2017-01-01 00:00:21 | | 32089079 | 取件成功通知 | 221034880000 | 2016-12-31 10:58:43 | 1563761xxxx | 0 | 18866152 | 微信平台-发送成功 | 2017-01-01 00:00:35 | | 32089080 | 取件成功通知 | 423871440000 | 2016-12-31 20:36:46 | 1571135xxxx | 0 | 18904861 | 微信平台-发送成功 | 2017-01-01 00:00:47 | | 32089081 | 取件成功通知 | 3937050300000 | 2016-12-31 12:16:46 | 1571156xxxx | 0 | 18877449 | 微信平台-发送成功 | 2017-01-01 00:00:50 | | 32089082 | 取件成功通知 | 423922650000 | 2016-12-31 16:36:22 | 1870828xxxx | 0 | 18897502 | 微信平台-发送成功 | 2017-01-01 00:00:55 | +----------+--------------------+--------------------+---------------------+-----------------+-------------+------------+---------------------------+---------------------+ 10 rows in set (2 min 15.37 sec) mysql> show variables like 'innodb_buffer_pool_size'; +-------------------------+------------+ | Variable_name | Value | +-------------------------+------------+ | innodb_buffer_pool_size | 2147483648 | +-------------------------+------------+ 1 row in set (0.00 sec)
再根据网友提供思路查官网innodb_buffer_pool_size选项的介绍：https://dev.mysql.com/doc/refman/5.7/en/innodb-buffer-pool-resize.html
暂未发现5.6有此项的介绍，官网说明innodb_buffer_pool_size必须是innodb_buffer_pool_chunk_size * innodb_buffer_pool_instances的倍数，但是5.6并没有innodb_buffer_pool_chunk_size参数。我在配置文件写3G的时候，通过mysql统计出来也是3G。下一步排查的话可能需要开启debug，没有精力再折腾，就先这样了。
mysql> SELECT @@innodb_buffer_pool_size/1024/1024/1024; +------------------------------------------+ | @@innodb_buffer_pool_size/1024/1024/1024 | +------------------------------------------+ | 3.000000000000 | +------------------------------------------+
问题就是内存溢出导致的，mysqld被重启的具体原因记录在messages文件中，如下。
[root@HD1_db_archive /var/log]# more /var/log/messages Apr 26 15:31:52 HD1_db_archive kernel: AliYunDun invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0 Apr 26 15:31:53 HD1_db_archive kernel: AliYunDun cpuset=/ mems_allowed=0 Apr 26 15:31:53 HD1_db_archive kernel: CPU: 0 PID: 1361 Comm: AliYunDun Not tainted 3.10.0-693.2.2.el7.x86_64 #1 Apr 26 15:31:53 HD1_db_archive kernel: Hardware name: Alibaba Cloud Alibaba Cloud ECS, BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014 ... ... Apr 26 15:31:53 HD1_db_archive kernel: Out of memory: Kill process 17062 (mysqld) score 910 or sacrifice child Apr 26 15:31:53 HD1_db_archive kernel: Killed process 17062 (mysqld) total-vm:4606080kB, anon-rss:3526148kB, file-rss:0kB, shmem-rss:0kB
