MySQL中一條SQL使磁盤(pán)暴漲并導(dǎo)致MySQL Crash該怎么辦

今天就跟大家聊聊有關(guān)MySQL中一條SQL使磁盤(pán)暴漲并導(dǎo)致MySQL Crash該怎么辦，可能很多人都不太了解，為了讓大家更加了解，小編給大家總結(jié)了以下內(nèi)容，希望大家根據(jù)這篇文章可以有所收獲。

收到一個(gè)MySQL實(shí)例的磁盤(pán)告警，看到監(jiān)控圖，磁盤(pán)使用率增長(zhǎng)速度非常快，在兩個(gè)多小時(shí)的時(shí)間里，已經(jīng)漲了170多G。
檢查到binlog目錄并不大，而datadir已經(jīng)180多G了，發(fā)現(xiàn)ibtmp1非常大，并且持續(xù)增長(zhǎng)。

趕緊上去看processlist，線程不多，檢查到有一個(gè)SELECT case ... when ... 的線程，狀態(tài)是sending data，并且已經(jīng)持續(xù)幾千秒了。
有點(diǎn)懵，沒(méi)有第一時(shí)間kill掉這個(gè)線程，再一次show processlist的時(shí)候……發(fā)現(xiàn)大概已經(jīng)掛了………………

1. mysql> show processlist;
   

2. ERROR 2006 (HY000): MySQL server has gone away
   

3. No connection. Trying to reconnect...
   

4. ERROR 2002 (HY000): Can't connect to local MySQL server through socket '$datadir/mysqld.sock' (2)
   

5. ERROR: Can't connect to the server

那好，既然已經(jīng)掛了，那么開(kāi)始找原因吧…

看一下datadir掛載的磁盤(pán)，已經(jīng)釋放空了，果然已經(jīng)被重啟了。
ext4    197G  4.6G  191G   3% $datadir


檢查一下mysqld進(jìn)程，發(fā)現(xiàn)已經(jīng)被mysqld_safe拉起來(lái)了。

檢查一下error log：
紅字是關(guān)于mysqld crash的信息，很顯然，datadir掛載的磁盤(pán)滿(mǎn)了。
沒(méi)有多余的空間寫(xiě)binlog和ibtmp1臨時(shí)表空間文件（5.7新增）。
而且ibtmp1文件最后達(dá)到了201876045824bytes，將近190G，而掛載的磁盤(pán)總大小才不到200G。

藍(lán)字是關(guān)于sql thread的問(wèn)題，在mysqld起來(lái)之后，sql thread也出現(xiàn)了問(wèn)題。
這個(gè)之后再修復(fù)。

1. [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

2. [ERROR] Disk is full writing '$datadir/mysql-bin.000004' (Errcode: 15870576 - No space left on device). Waiting for someone to free space...

3. [ERROR] Retry in 60 secs. Message reprinted in 600 secs

4. [Warning] InnoDB: 1048576 bytes should have been written. Only 647168 bytes written. Retrying for the remaining bytes.

5. [Warning] InnoDB: Retry attempts for writing partial data failed.

6. [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.

7. [ERROR] InnoDB: Error number 28 means 'No space left on device'

8. [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html

9. [Warning] InnoDB: Error while writing 67108864 zeroes to $datadir/ibtmp1 starting at offset 201876045824

10. [ERROR] $basedir/bin/mysqld: The table '$tmpdir/#sql_37c5_0' is full

11. [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

12. [Warning] InnoDB: Retry attempts for writing partial data failed.

13. [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: 0

14. mysqld_safe mysqld restarted

15. ……………………………………………………………………………………………………………………

16. [Note] InnoDB: Last MySQL binlog file position 0 690908428, file name mysql-bin.000004

17. [Note] InnoDB: Starting in background the rollback of uncommitted transactions

18. [Note] InnoDB: Rollback of non-prepared transactions completed

19. [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

20. [Note] InnoDB: Creating shared tablespace for temporary tables

21. [Note] InnoDB: Setting file '$datadir/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

22. [Note] InnoDB: File '$datadir/ibtmp1' size is now 12 MB.

23. [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.

24. [Note] InnoDB: 32 non-redo rollback segment(s) are active.

25. [Note] InnoDB: Waiting for purge to start

26. [Note] InnoDB: 5.7.12 started; log sequence number 4828513952

27. [Note] InnoDB: page_cleaner: 1000ms intended loop took 7748ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

28. [Note] InnoDB: Loading buffer pool(s) from $datadir/ib_buffer_pool

29. [Note] Plugin 'FEDERATED' is disabled.

30. [Note] InnoDB: Buffer pool(s) load completed at 170706 19:49:30

31. [Note] Recovering after a crash using $basedir/mysql-bin

32. [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 579, event_type: 2

33. [Note] Starting crash recovery...

34. [Note] InnoDB: Starting recovery for XA transactions...

35. [Note] InnoDB: Transaction 6729603 in prepared state after recovery

36. [Note] InnoDB: Transaction contains changes to 1 rows

37. [Note] InnoDB: 1 transactions in prepared state after recovery

38. [Note] Found 1 prepared transaction(s) in InnoDB

39. [Note] Crash recovery finished.

40. [Note] Crashed binlog file $basedir/mysql-bin.000004 size is 690909184, but recovered up to 690908428. Binlog trimmed to 690908428 bytes.

41. [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key

42. ……………………………………………………………………………………………………………………

43. [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 835, event_type: 2

44. [Warning] Error reading GTIDs from relaylog: -1

45. [Note] Slave I/O thread: Start asynchronous replication to master '*****' in log 'mysql-bin.000014' at position 286486095

46. [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.

47. [Note] Slave I/O thread for channel '': connected to master '*****',replication started in log 'mysql-bin.000014' at position 286486095

48. [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

49. [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

50. [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 835, event_type: 2

51. [ERROR] Error reading relay log event for channel '': slave SQL thread aborted because of I/O error

52. [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

53. [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

54. [Note] Event Scheduler: Loaded 0 events

55. [Note] $basedir/mysqld: ready for connections.

56. Version: '5.7.12'  socket: '$datadir/mysqld.sock'  port: 3306  Source distribution

因?yàn)橐呀?jīng)掛了，而且沒(méi)有來(lái)得及將當(dāng)時(shí)執(zhí)行的sql完整記錄下來(lái)，只能看到show processlist前面的一小部分。

聯(lián)系到業(yè)務(wù)，業(yè)務(wù)說(shuō)這一臺(tái)是slave，無(wú)讀的業(yè)務(wù)，但偶爾會(huì)手動(dòng)執(zhí)行報(bào)表相關(guān)的SELECT操作。

那么檢查一下crash前的兩個(gè)小時(shí)的slow log：
發(fā)現(xiàn)反復(fù)有這么幾條SQL：

1. ……………………

2. 00:00:11.392881 select * from tb ……………………

3. 00:00:04.779748 select (case when ……………………
   

4. 00:00:04.779748 select ( case when t2.col1 ……………………
   

5. 00:00:03.328248 select ( case when t2.col1 ……………………
   

6. 00:00:04.276773 select count(t1.id) from tb1 

7. 00:00:05.039027 select (case when t2.col ……………………

8. 00:00:10.263063 select (case when t2.col ……………………

9. 00:00:03.131713 select t2.* from tb1 t1 ……………………

10. 00:00:15.909456 select t2.* from tb1 t1 ……………………

11. 00:00:14.367047 select * from tb ……………………
    

12. ……………………

雖然沒(méi)有一條超過(guò)20秒的，但不要忘了，在磁盤(pán)被打爆之前的一秒，有一條執(zhí)行了幾千秒的SQL。
并且case when只有一個(gè)order by。
出于取出其中一條，檢查一下執(zhí)行計(jì)劃：

1. +--------+---------------+---------+---------+---------------------+--------+----------+----------------------------------------------+
   

2. | type   | possible_keys | key     | key_len | ref                 | rows   | filtered | Extra                                        |
   

3. +--------+---------------+---------+---------+---------------------+--------+----------+----------------------------------------------+
   

4. | ALL    | NULL          | NULL    | NULL    | NULL                | 472765 | 20.99    | Using where; Using temporary; Using filesort |
   

5. | eq_ref | PRIMARY       | PRIMARY | 8       | $tb1.col1           | 1      | 10.00    | Using where                                  |
   

6. +--------+---------------+---------+---------+---------------------+--------+----------+----------------------------------------------+

看起來(lái)不是很好，但是也不至于用到190G臨時(shí)表。
雖然臨時(shí)表是長(zhǎng)期積累下來(lái)的，但看監(jiān)控，磁盤(pán)使用率確實(shí)是在這一個(gè)多小時(shí)迅速積攢起來(lái)的。

首先這個(gè)從庫(kù)是沒(méi)有業(yè)務(wù)的，而是通過(guò)客戶(hù)那邊可能手動(dòng)連接過(guò)來(lái)做一些查詢(xún)服務(wù)的。
知道這個(gè)信息之后，繼續(xù)對(duì)照slow log，發(fā)現(xiàn)slow log關(guān)于case when的這一條sql并不完全一樣……
這可能意味著客戶(hù)仍然在不停地調(diào)試這條SQL…
而那條執(zhí)行了幾千秒的case when可能寫(xiě)得十分爛。

可惜的是，在mysqld crash的最后一瞬間，該sql仍然沒(méi)有執(zhí)行完成，導(dǎo)致沒(méi)有被記錄到slow log。
那條sql估計(jì)也永遠(yuǎn)無(wú)法再?gòu)?fù)現(xiàn)。

那么究竟是多爛的SQL，或者多大的表，可以用到這么多基于磁盤(pán)的臨時(shí)表或文件排序呢？？
趕緊檢查一下庫(kù)表的情況：

    ① 表1：100w，表2：40w，也沒(méi)有blob，text等字段。
    ② 重啟后的datadir只有3、4G的數(shù)據(jù)量

所以我有個(gè)大但的想法：
可能客戶(hù)在調(diào)試的過(guò)程中，產(chǎn)生了一條類(lèi)似這樣的SQL：
我對(duì)照了已經(jīng)記錄在slow log的幾條sql，脫敏，格式化之后還原如下：

1. SELECT ( CASE
   

2.     WHEN t2.col='$info_000' THEN '$a'
   

3.     WHEN t2.col='$info_001' THEN '$b'
   

4.     WHEN t2.col='$info_002' THEN '$c'
   

5.     WHEN t2.col='$info_003' THEN '$d'
   

6.     WHEN t2.col='$info_004' THEN '$e'
   

7.     WHEN t2.col='$info_005' THEN '$f'
   

8.     WHEN t2.col='$info_006' THEN '$g'
   

9.     ELSE t2.col
   

10.     END ) AS 來(lái)源XX,
    

11.     ( CASE
    

12.     WHEN t2.clo2='$info_000' THEN '$a'
    

13.     WHEN t2.clo2='$info_001' THEN '$b'
    

14.     WHEN t2.clo2='$info_002' THEN '$c'
    

15.     WHEN t2.clo2='$info_003' THEN '$d'
    

16.     WHEN t2.clo2='$info_004' THEN '$e'
    

17.     WHEN t2.clo2='$info_005' THEN '$f'
    

18.     WHEN t2.clo2='$info_006' THEN '$g'
    

19.     ELSE t2.col 

20.     END ) AS 目標(biāo)XX,
    

21.     t2.col4 AS XX時(shí)間,
    

22.     t2.col5 AS 金額
    

23. FROM $tb1 t1 JOIN $tb2 t2
    

24. WHERE t1.col3 = 4 AND (t2.col LIKE '$info%' OR t2.clo2 LIKE '$info%')
    

25. ORDER BY t1.col4 DESC;

對(duì)，這兩張表做了一個(gè)JOIN，但是沒(méi)有條件。
產(chǎn)生了一個(gè)很大很大很大的笛卡爾積。

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

再測(cè)試一下：
將兩張表dump成sql文件，看了一下大?。?30MB，并不大。
導(dǎo)入自己的實(shí)驗(yàn)環(huán)境，再將上述產(chǎn)生笛卡爾積的SQL跑一下。

經(jīng)過(guò)一段時(shí)間等待：


已經(jīng)執(zhí)行了半個(gè)小時(shí)多了。并且該SQL仍然在執(zhí)行：
說(shuō)出來(lái)你們可能不信，此時(shí)的ibtmp1大小：

1. # du -sh *
   

2. 4.0K    auto.cnf
   

3. 4.0K    ib_buffer_pool
   

4. 2.9G    ibdata1
   

5. 48M     ib_logfile0
   

6. 48M     ib_logfile1
   

7. 54G     ibtmp1
   

8. 12M     mysql
   

9. 1.1M    performance_schema
   

10. 676K    sys
    

11. 633M    test
    

12. 47M     test_2

大概也好解釋?zhuān)瑸槭裁磧蓮埐⒉皇呛艽蟮谋?，在?zhí)行某些查詢(xún)之后會(huì)產(chǎn)生這么大的臨時(shí)表了…

當(dāng)然，在做實(shí)驗(yàn)的等待時(shí)間里，已經(jīng)將復(fù)制的ERROR給修復(fù)了。
當(dāng)時(shí)復(fù)制的報(bào)錯(cuò)：

1. ……

2. Slave_IO_Running: Yes

3. Slave_SQL_Running: No

4. ……

5. Seconds_Behind_Master: NULL

6. Master_SSL_Verify_Server_Cert: No

7. Last_IO_Errno: 0

8. Last_IO_Error:

9. Last_SQL_Errno: 1594

10. Last_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.

結(jié)合之前貼的error log可以看到更多信息，推斷是relay log有損壞。


那么就好解決了：

1. STOP SLAVE;
   

2. 
   

3. -- master_log_file和master_log_pos為報(bào)錯(cuò)時(shí)所記錄的位置。
   

4. CHANGE MASTER master_log_file='xxx', master_log_pos=xxx;
   

5. 
   

6. START SLAVE;

此處不再贅述。


到目前為止，我實(shí)驗(yàn)環(huán)境的datadir已經(jīng)滿(mǎn)了，但是和此處正式環(huán)境有區(qū)別的是。
在磁盤(pán)寫(xiě)滿(mǎn)之時(shí)，并沒(méi)有馬上導(dǎo)致mysql crash，而是輸出了：

1. [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.
   

2. [ERROR] InnoDB: Error number 28 means 'No space left on device'
   

3. [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
   

4. [Warning] InnoDB: Error while writing 67108864 zeroes to ./ibtmp1 starting at offset 83563118592
   

5. [ERROR] /data/mysql-base/mysql57/bin/mysqld: The table '#sql_b26_0' is full
   

6. [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...
   

7. [ERROR] Retry in 60 secs. Message reprinted in 600 secs

實(shí)際上正常情況下，mysql在磁盤(pán)滿(mǎn)了的情況下，會(huì)每隔1分鐘做一次檢查，每隔10分鐘將檢查信息輸出到錯(cuò)誤日志。

既然mysqld沒(méi)有被干掉，我再次執(zhí)行了一下那條可怕的sql呢？……

當(dāng)然……error log如愿輸出被kill的消息……
并且mysqld進(jìn)程被殺掉，此時(shí)：

1. [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.
   

2. 14:42:48 UTC - mysqld got signal 6 ;
   

3. This could be because you hit a bug. It is also possible that this binary
   

4. or one of the libraries it was linked against is corrupt, improperly built,
   

5. or misconfigured. This error can also be caused by malfunctioning hardware.
   

6. Attempting to collect some information that could help diagnose the problem.
   

7. As this is a crash and something is definitely wrong, the informati

有趣的是，“information”這個(gè)單詞都沒(méi)有輸出完，大概是真的一個(gè)字符都寫(xiě)不下了吧。


試圖用vim在error log里添加幾個(gè)字符并保存，也報(bào)錯(cuò)。

總結(jié)一下：
〇 在線上環(huán)境執(zhí)行的sql，建議進(jìn)行審核，報(bào)表等OLAP需求也需要正式一些。
〇 考慮是否可以限制ibtmp1的大小，也就是設(shè)定innodb_temp_data_file_path的最大值。
〇 可能需要定期重啟mysqld來(lái)收縮臨時(shí)表空間。
〇 做好監(jiān)控和及時(shí)響應(yīng)，這次就是響應(yīng)時(shí)間過(guò)長(zhǎng)，達(dá)到閾值，然后到機(jī)子上檢查時(shí)，已經(jīng)晚了，眼睜睜地看到mysqld在我眼前crash。

看完上述內(nèi)容，你們對(duì)MySQL中一條SQL使磁盤(pán)暴漲并導(dǎo)致MySQL Crash該怎么辦有進(jìn)一步的了解嗎？如果還想了解更多知識(shí)或者相關(guān)內(nèi)容，請(qǐng)關(guān)注億速云行業(yè)資訊頻道，感謝大家的支持。