首页 > 数据库 > MySQL

故障分析 | binlog flush 失败导致的 Crash

来源：SegmentFault

时间：2023-02-16 15:30:01 435浏览收藏

数据库小白一枚，正在不断学习积累知识，现将学习到的知识记录一下，也是将我的所得分享给大家！而今天这篇文章《故障分析 | binlog flush 失败导致的 Crash》带大家来了解一下故障分析 | binlog flush 失败导致的 Crash，希望对大家的知识积累有所帮助，从而弥补自己的不足，助力实战开发！

作者：xuty
开个坑，记录自己平时由于解决问题需要或是兴趣研究进行的 MySQL 源码跟踪学习过程。

一、问题现象

某项目上出现

2019-09-24T14:17:47.786460+08:00 527621 [ERROR] /usr/local/mysql/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.
06:17:47 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 information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=16777216
max_used_connections=79
max_threads=2500
thread_count=35
connection_count=34
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 122921649 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fbc3400ef40
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fbcd01d9ea8 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf4fbe5]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x7d1f54]
/lib64/libpthread.so.0(+0xf370)[0x7fc5897fe370]
/lib64/libc.so.6(gsignal+0x37)[0x7fc5881f21d7]
/lib64/libc.so.6(abort+0x148)[0x7fc5881f38c8]
/usr/local/mysql/bin/mysqld[0xee626a]
/usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG33handle_binlog_flush_or_sync_errorEP3THDb+0x17b)[0xef289b]
/usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG14ordered_commitEP3THDbb+0x3ca)[0xef480a]
/usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0x51d)[0xef4f7d]
/usr/local/mysql/bin/mysqld(_Z15ha_commit_transP3THDbb+0x174)[0x823434]
/usr/local/mysql/bin/mysqld(_Z12trans_commitP3THD+0x49)[0xdd38f9]
/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x2c89)[0xd1a1a9]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x40d)[0xd1c86d]
/usr/local/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x11a5)[0xd1da95]
/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0x194)[0xd1e944]
/usr/local/mysql/bin/mysqld(handle_connection+0x2b4)[0xdeffa4]
/usr/local/mysql/bin/mysqld(pfs_spawn_thread+0x174)[0xfc8f64]
/lib64/libpthread.so.0(+0x7dc5)[0x7f097d411dc5]
/lib64/libc.so.6(clone+0x6d)[0x7f097becf73d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f00a80008f0): is an invalid pointer
Connection ID (thread ID): 98525
Status: NOT_KILLED

二、问题疑惑

对于这个问题，一开始存在几点疑惑，需要实验和源码追踪验证。

binlog error 是由于 / 分区空间已满造成的，为什么会造成 MySQL Crash？
/ 分区明明有十几个 G 的剩余空间，为什么会满？是什么文件撑满的？为啥事后空间却自动释放了？

这里就已知的知识先猜测下问题过程，是否正确则需要测试验证，内部机制可能就需要去查看源码。

大概过程如上，项目上

#bin包默认值
datadir = /data/mysql_data
tmpdir = /tmp

当

Filesystem           Size  Used Avail Use% Mounted on
/dev/mapper/cl-root   96G   57G   39G  60% /

模拟

mysql> call test_insert();
ERROR 1026 (HY000): Error writing file '/data/tmp/ML1aShmH' (errno: 28 - No space left on device)
mysql> commit;
ERROR 1598 (HY000): 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.

mysql> call test_insert(); ERROR 1026 (HY000): Error writing file '/data/tmp/ML5b0Mj6' (errno: 28 - No space left on device) mysql> start transaction; ERROR 1598 (HY000): 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.

五、源码跟踪

跟踪 MySQL 源码验证上述猜想及测试，不感兴趣的童鞋可以直接跳过~

为了查看上述测试过程到底是在源码的哪一步最先报了错误，所以对比了 2 份 DBUG 日志，
//Write a chunk of bytes to a file size_t my_write(File Filedes, const uchar *Buffer, size_t Count, myf MyFlags) { size_t writtenbytes; size_t sum_written= 0; const size_t initial_count= Count; for (;;) { //... #ifdef _WIN32 writtenbytes= my_win_write(Filedes, Buffer, Count); #else writtenbytes= write(Filedes, Buffer, Count); //writtenbytes为实际写入的字节数 //... if (writtenbytes == Count) //判断实际写入的字节数与要求写入的字节数是否相符 { //写入正常则直接break跳出循环,正常结束. sum_written+= writtenbytes; break; } //... } //... if (MyFlags & (MY_NABP | MY_FNABP)) { if (sum_written == initial_count) //写入正常走这个逻辑，返回0代表成功 DBUG_RETURN(0); if (MyFlags & (MY_WME | MY_FAE | MY_FNABP)) //写入过程报错走这个逻辑 { char errbuf[MYSYS_STRERROR_SIZE]; my_error(EE_WRITE, MYF(0), my_filename(Filedes), my_errno(), my_strerror(errbuf, sizeof(errbuf), my_errno())); //打印错误信息 } DBUG_RETURN(MY_FILE_ERROR); //返回错误 } //... } /* 源码如上，MySQL最终会走Linux内核方法 write(Filedes, Buffer, Count)来刷新binlog缓冲至磁盘文件中。 1. Filedes 为文件号（对应/proc/mysqld_pid/fd下的文件编号） 2. Buffer 为指向所需写入缓冲的指针。 3. Count 为所需要写入的字节数。 my: fd: 51 Buffer: 0x7f24c49e9e30 Count: 27 由于 /data/tmp 磁盘已满，无法写入 Count 所需的字节数，导致 writtenbytes!=Count，然后引起了后续一系列的代码报错，最终诱发 binlog_error_action->MySQL Crash. */

MySQL 源码执行 Commit 报错过程精简如下：

T@12: | >trans_commit
T@12: | | >ha_commit_trans
T@12: | | | >MYSQL_BIN_LOG::commit
T@12: | | | | >MYSQL_BIN_LOG::ordered_commit
T@12: | | | | | >MYSQL_BIN_LOG::process_flush_stage_queue
T@12: | | | | | | >binlog_cache_data::flush
T@12: | | | | | | | >MYSQL_BIN_LOG::write_cache(THD *, binlog_cache_data *, bool)
T@12: | | | | | | | | >MYSQL_BIN_LOG::do_write_cache
T@12: | | | | | | | | | >reinit_io_cache
T@12: | | | | | | | | | | >my_b_flush_io_cache
T@12: | | | | | | | | | | | >my_write
T@12: | | | | | | | | | | | | my: fd: 52  Buffer: 0x7f9ccc050db0  Count: 27  MyFlags: 20
T@12: | | | | | | | | | | | | error: Write only -1 bytes, error: 28
T@12: | | | | | | | | | | | | >my_error
T@12: | | | | | | | | | | | | | >my_message_sql
T@12: | | | | | | | | | | | | | | error: error: 3  message: 'Error writing file '/data/tmp/MLJRp8sa' (Errcode: 28 - No space left on device)'
T@12: | | | | | | | | | | | | | my_error
T@12: | | | | | | >my_message_sql
T@12: | | | | | | | error: error: 1598  message: '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.'
T@12: | | | | | | | >sql_print_error
T@12: | | | | | | | | >error_log_print
T@12: | | | | | | | | | >print_buffer_to_file
T@12: | | | | | | | | | | enter: buffer: /opt/mysql-5.7.24-linux-glibc2.12-x86_64/bin/mysqld-debug: 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.
2019-11-11T11:54:45.434783+08:00 12 [ERROR] /opt/mysql-5.7.24-linux-glibc2.12-x86_64/bin/mysqld-debug: 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.
T@12: | | | | | | | | |

六、扩展内容

下图这个报错其实就是本次问题的一个日常例子，很多童鞋通过 navicate 还原 MySQL 的时候可能就会碰到这个问题，本质就是 navicate 还原数据库的时候默认会走

事务

，当表数据库较大时，事务大小超过

binlog_cache_size

，就会用临时表记录事务数据，当 tmdir 目录磁盘不足就会报错，但是这种情况并不会造成 MySQL Crash，因为 navicate 在还原报错后并不会继续去执行

commit

或

另开一个事务

，而是直接断开连接。

七、总结

这个问题目前在项目上很少碰到，这次也是出于好奇拿来学习探讨，下面总结下这个问题出现的场景：

1.代码中存在较大事务，超过 binlog_cache_size，高并发下生成大量临时文件，占满 tmpdir。
2.代码在事务执行过程中碰到 tmpdir 磁盘已满错误，未处理异常执行回滚，后续执行 Commit 导致。
3.代码在事务执行过程中碰到 tmpdir 磁盘已满错误，未处理异常执行回滚，继续执行碰到嵌套事务，引发 Commit 导致。

也许很多童鞋想到可以