MySQL中一条SQL使磁盘暴涨并导致MySQL Crash该怎么办

今天就跟大家聊聊有关MySQL中一条SQL使磁盘暴涨并导致MySQL Crash该怎么办，可能很多人都不太了解，为了让大家更加了解，小编给大家总结了以下内容，希望大家根据这篇文章可以有所收获。收到一个MySQL实例的磁盘告警，看到监控图，磁盘使用率增长速度非常快，在两个多小时的时间里，已经涨了170多G。
检查到binlog目录并不大，而datadir已经180多G了，发现ibtmp1非常大，并且持续增长。

赶紧上去看processlist，线程不多，检查到有一个SELECT case … when … 的线程，状态是sending data，并且已经持续几千秒了。
有点懵，没有第一时间kill掉这个线程，再一次show processlist的时候……发现大概已经挂了………………

mysql> show processlist;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect…
ERROR 2002 (HY000): Can’t connect to local MySQL server through socket ‘$datadir/mysqld.sock’ (2)
ERROR: Can’t connect to the server

那好，既然已经挂了，那么开始找原因吧…

看一下datadir挂载的磁盘，已经释放空了，果然已经被重启了。
ext4 197G 4.6G 191G 3% $datadir

检查一下mysqld进程，发现已经被mysqld_safe拉起来了。

检查一下error log：
红字是关于mysqld crash的信息，很显然，datadir挂载的磁盘满了。
没有多余的空间写binlog和ibtmp1临时表空间文件（5.7新增）。
而且ibtmp1文件最后达到了201876045824bytes，将近190G，而挂载的磁盘总大小才不到200G。

蓝字是关于sql thread的问题，在mysqld起来之后，sql thread也出现了问题。
这个之后再修复。

[ERROR] InnoDB: posix_fallocate(): Failed to preallocate data for file $datadir/ibtmp1, desired size 67108864 bytes. Operating system error number 28. Check that the disk is not full or a disk quota exceeded. Make sure the file system supports this function. Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/ operating-system-error-codes.html[ERROR] Disk is full writing ‘$datadir/mysql-bin.000004’ (Errcode: 15870576 – No space left on device). Waiting for someone to free space…[ERROR] Retry in 60 secs. Message reprinted in 600 secs[Warning] InnoDB: 1048576 bytes should have been written. Only 647168 bytes written. Retrying for the remaining bytes.[Warning] InnoDB: Retry attempts for writing partial data failed.[ERROR] InnoDB: Write to file $datadir/ibtmp1 failed at offset 201911697408, 1048576 bytes should have been written, only 647168 were written. Operating system error number 28. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.[ERROR] InnoDB: Error number 28 means ‘No space left on device'[Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html[Warning] InnoDB: Error while writing 67108864 zeroes to $datadir/ibtmp1 starting at offset 201876045824[ERROR] $basedir/bin/mysqld: The table ‘$tmpdir/#sql_37c5_0’ is full[ERROR] InnoDB: posix_fallocate(): Failed to preallocate data for file ./thread_quartz/QRTZ_FIRED_TRIGGERS.ibd, desired size 32768 bytes. Operating system error number 28. Check that the disk is not full or a disk quota exceeded. Make sure the file system supports this function. Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/ operating-system-error-codes.html[Warning] InnoDB: Retry attempts for writing partial data failed.[Warning] InnoDB: Error while writing 32768 zeroes to ./thread_quartz/QRTZ_FIRED_TRIGGERS.ibd starting at offset 442362017-07-06T11:49:21.893377Z mysqld_safe Number of processes running now: 0mysqld_safe mysqld restarted……………………………………………………………………………………………………………………[Note] InnoDB: Last MySQL binlog file position 0 690908428, file name mysql-bin.000004[Note] InnoDB: Starting in background the rollback of uncommitted transactions[Note] InnoDB: Rollback of non-prepared transactions completed[Note] InnoDB: Removed temporary tablespace data file: “ibtmp1″[Note] InnoDB: Creating shared tablespace for temporary tables[Note] InnoDB: Setting file ‘$datadir/ibtmp1’ size to 12 MB. Physically writing the file full; Please wait …[Note] InnoDB: File ‘$datadir/ibtmp1’ size is now 12 MB.[Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.[Note] InnoDB: 32 non-redo rollback segment(s) are active.[Note] InnoDB: Waiting for purge to start[Note] InnoDB: 5.7.12 started; log sequence number 4828513952[Note] InnoDB: page_cleaner: 1000ms intended loop took 7748ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)[Note] InnoDB: Loading buffer pool(s) from $datadir/ib_buffer_pool[Note] Plugin ‘FEDERATED’ is disabled.[Note] InnoDB: Buffer pool(s) load completed at 170706 19:49:30[Note] Recovering after a crash using $basedir/mysql-bin[ERROR] Error in Log_event::read_log_event(): ‘read error’, data_len: 579, event_type: 2[Note] Starting crash recovery…[Note] InnoDB: Starting recovery for XA transactions…[Note] InnoDB: Transaction 6729603 in prepared state after recovery[Note] InnoDB: Transaction contains changes to 1 rows[Note] InnoDB: 1 transactions in prepared state after recovery[Note] Found 1 prepared transaction(s) in InnoDB[Note] Crash recovery finished.[Note] Crashed binlog file $basedir/mysql-bin.000004 size is 690909184, but recovered up to 690908428. Binlog trimmed to 690908428 bytes.[Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key……………………………………………………………………………………………………………………[ERROR] Error in Log_event::read_log_event(): ‘read error’, data_len: 835, event_type: 2[Warning] Error reading GTIDs from relaylog: -1[Note] Slave I/O thread: Start asynchronous replication to master ‘*****’ in log ‘mysql-bin.000014’ at position 286486095[Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the ‘START SLAVE Syntax’ in the MySQL Manual for more information.[Note] Slave I/O thread for channel ”: connected to master ‘*****’,replication started in log ‘mysql-bin.000014’ at position 286486095[Warning] Slave SQL for channel ”: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0[Note] Slave SQL thread for channel ” initialized, starting replication in log ‘mysql-bin.000014’ at position 286485153, relay log ‘$datadir/mysql-relay.000013’ position: 286485326[ERROR] Error in Log_event::read_log_event(): ‘开发云主机域名read error’, data_len: 835, event_type: 2[ERROR] Error reading relay log event for channel ”: slave SQL thread aborted because of I/O error[ERROR] Slave SQL for channel ”: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master’s binary log is corrupted (you can check this by running ‘mysqlbinlog’ on the binary log), the slave’s relay log is corrupted (you can check this by running ‘mysqlbinlog’ on the relay log), a network problem, or a bug in the master’s or slave’s MySQL code. If you want to check the master’s binary log or slave’s relay log, you will be able to know their names by issuing ‘SHOW SLAVE STATUS’ on this slave. Error_code: 1594[ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with “SLAVE START”. We stopped at log ‘mysql-bin.000014’ position 286485153[Note] Event Scheduler: Loaded 0 events[Note] $basedir/mysqld: ready for connections.Version: ‘5.7.12’ socket: ‘$datadir/mysqld.sock’ port: 3306 Source distribution

因为已经挂了，而且没有来得及将当时执行的sql完整记录下来，只能看到show processlist前面的一小部分。

联系到业务，业务说这一台是slave，无读的业务，但偶尔会手动执行报表相关的SELECT操作。

首先这个从库是没有业务的，而是通过客户那边可能手动连接过来做一些查询服务的。
知道这个信息之后，继续对照slow log，发现slow log关于case when的这一条sql并不完全一样……
这可能意味着客户仍然在不停地调试这条SQL…
而那条执行了几千秒的case when可能写得十分烂。

可惜的是，在mysqld crash的最后一瞬间，该sql仍然没有执行完成，导致没有被记录到slow log。
那条sql估计也永远无法再复现。

那么究竟是多烂的SQL，或者多大的表，可以用到这么多基于磁盘的临时表或文件排序呢？？
赶紧检查一下库表的情况：

① 表1：100w，表2：40w，也没有blob，text等字段。
② 重启后的datadir只有3、4G的数据量

所以我有个大但的想法：
可能客户在调试的过程中，产生了一条类似这样的SQL：
我对照了已经记录在slow log的几条sql，脱敏，格式化之后还原如下：
SELECT ( CASE
WHEN t2.col=’$info_000′ THEN ‘$a’
WHEN t2.col=’$info_001′ THEN ‘$b’
WHEN t2.col=’$info_002′ THEN ‘$c’
WHEN t2.col=’$info_003′ THEN ‘$d’
WHEN t2.col=’$info_004′ THEN ‘$e’
WHEN t2.col=’$info_005′ THEN ‘$f’
WHEN t2.col=’$info_006′ THEN ‘$g’
ELSEt2.col
END) AS 来源XX,
( CASE
WHEN t2.clo2=’$info_000′ THEN ‘$a’
WHEN t2.clo2=’$info_001′ THEN ‘$b’
WHEN t2.clo2=’$info_002′ THEN ‘$c’
WHEN t2.clo2=’$info_003′ THEN ‘$d’
WHEN t2.clo2=’$info_004′ THEN ‘$e’
WHEN t2.clo2=’$info_005′ THEN ‘$f’
WHEN t2.clo2=’$info_006′ THEN ‘$g’
ELSE t2.colEND ) AS 目标XX,
t2.col4 AS XX时间,
t2.col5 AS 金额
FROM $tb1 t1 JOIN $tb2 t2
WHERE t1.col3 = 4 AND (t2.col LIKE ‘$info%’ OR t2.clo2 LIKE ‘$info%’)
ORDER BY t1.col4 DESC;
对，这两张表做了一个JOIN，但是没有条件。
产生了一个很大很大很大的笛卡尔积。

那么算一下：
列：13 + 19 = 32
行： 1088181*440650=479,506,957,650rows

再测试一下：
将两张表dump成sql文件，看了一下大小：330MB，并不大。
导入自己的实验环境，再将上述产生笛卡尔积的SQL跑一下。

经过一段时间等待：

已经执行了半个小时多了。并且该SQL仍然在执行：
说出来你们可能不信，此时的ibtmp1大小：
# du -sh *
4.0K auto.cnf
4.0K ib_buffer_pool
2.9G ibdata1
48M ib_logfile0
48M ib_logfile1
54G ibtmp1
12M mysql
1.1M performance_schema
676K sys
633M test
47M test_2
大概也好解释，为什么两张并不是很大的表，在执行某些查询之后会产生这么大的临时表了…

当然，在做实验的等待时间里，已经将复制的ERROR给修复了。
当时复制的报错：

……Slave_IO_Running: YesSlave_SQL_Running: No……Seconds_Behind_Master: NULLMaster_SSL_Verify_Server_Cert: NoLast_IO_Errno: 0Last_IO_Error:Last_SQL_Errno: 1594Last_SQL_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master’s binary log is corrupted (you can check this by running ‘mysqlbinlog’ on the binary log), the slave’s relay log is corrupted (you can check this by running ‘mysqlbinlog’ on the relay log), a network problem, or a bug in the master’s or slave’s MySQL code. If you want to check the master’s binary log or slave’s relay log, you will be able to know their names by issuing ‘SHOW SLAVE STATUS’ on this slave.结合之前贴的error log可以看到更多信息，推断是relay log有损坏。

那么就好解决了：
STOP SLAVE;

— master_log_file和master_log_pos为报错时所记录的位置。
CHANGE MASTER master_log_file=‘xxx’, master_log_pos=xxx;

START SLAVE;此处不再赘述。

到目前为止，我实验环境的datadir已经满了，但是和此处正式环境有区别的是。
在磁盘写满之时，并没有马上导致mysql crash，而是输出了：
[ERROR] InnoDB: Write to file ./ibtmp1failed at offset 83579895808, 1048576 bytes should have been written, only 958464 were written. Operating system error number 28. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
[ERROR] InnoDB: Error number 28 means ‘No space left on device’
[Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
[Warning] InnoDB: Error while writing 67108864 zeroes to ./ibtmp1 starting at offset 83563118592
[ERROR] /data/mysql-base/mysql57/bin/mysqld: The table ‘#sql_b26_0’ is full
[ERROR] Disk is full writing ‘/data/mysql-data/mysql57-3357/binlog/mysql-bin.000015’ (Errcode: 15868064 – No space left on device). Waiting for someone to free space…
[ERROR] Retry in 60 secs. Message reprinted in 600 secs实际上正常情况下，mysql在磁盘满了的情况下，会每隔1分钟做一次检查，每隔10分钟将检查信息输出到错误日志。

既然mysqld没有被干掉，我再次执行了一下那条可怕的sql呢？……

当然……error log如愿输出被kill的消息……
并且mysqld进程被杀掉，此时：

[ERROR] /data/mysql-base/mysql57/bin/mysqld: Binary logging not possible. Message: An error occurred during flush stage of the commit. ‘binlog_error_action’ is set to ‘ABORT_SERVER’. Hence aborting the server.
14:42:48 UTC – mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the informati有趣的是，“information”这个单词都没有输出完，大概是真的一个字符都写不下了吧。

试图用vim在error log里添加几个字符并保存，也报错。

总结一下：
〇在线上环境执行的sql，建议进行审核，报表等OLAP需求也需要正式一些。
〇考虑是否可以限制ibtmp1的大小，也就是设定innodb_temp_data_file_path的最大值。
〇可能需要定期重启mysqld来收缩临时表空间。
〇做好监控和及时响应，这次就是响应时间过长，达到阈值，然后到机子上检查时，已经晚了，眼睁睁地看到mysqld在我眼前crash。
看完上述内容，你们对MySQL中一条SQL使磁盘暴涨并导致MySQL Crash该怎么办有进一步的了解吗？如果还想了解更多知识或者相关内容，请关注开发云行业资讯频道，感谢大家的支持。

相关推荐: zabbix下载percona插件实现监控MySQL步骤

本篇文章给大家主要讲的是关于zabbix下载percona插件实现监控MySQL步骤的内容，感兴趣的话就一起来看看这篇文章吧，相信看完zabbix下载percona插件实现监控MySQL步骤对大家多少有点参考价值吧。现有环境已经安装了zabbix server…