[奇葩问题] ERROR 2013 (HY000): Lost connection to MySQL server during query

时间:2021-01-29 09:05:49

查询一条耗时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