1, Problem phenomenon

MySQL Crash occurs in a project. The related error log logs are as follows. From the logs, it can be seen that the problem is caused by binlog error, but the specific reason can not be confirmed. Most of the data on the Internet are said to be caused by the full space. Later, the information that the / partition space is full is found in the system log (/ var/log/message), so the binlog error can be basically confirmed Because the disk space is full, MySQL Crash is caused.

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

2, Questions and doubts

For this problem, there are a few doubts at the beginning, which need to be tested and source tracking verified.

1. binlog error is caused by / partition space is full. Why MySQL Crash?
2. /There are more than ten G remaining spaces in the zone. Why are they full? What file is full? Why is the space automatically released after the event? Here we first guess the problem process based on the known knowledge. If it is correct, it needs to be tested and verified. The internal mechanism may need to check the source code.

About the process above, the / tmp on the project is the temporary file directory of MySQL by default, and its partition is generally / partition (root partition), while the MySQL data directory is stored in / data/mysql_data as another separate partition (/ data partition), which is generally the case on the project.

#bin package default
datadir = /data/mysql_data
tmpdir = /tmp

When / tmp space is insufficient, that is, when / partition is full, binlog flush cannot proceed. An exception of binlog error is thrown, resulting in MySQL crash '!

3, Data access

In response to this problem, after consulting a large number of materials on the Internet, the relevant knowledge points are summarized as follows:

The two most important MySQL parameters related to this problem.

#bin package default
binlog_cache_size=32768
binlog_error_action = ABORT_SERVER

Binlog cache size: when a transaction starts, MySQL allocates a binlog cache size buffer (32K by default) to the session for storing binary logs. If the transaction is larger than binlog? Cache? Size (default 32K), the thread will open a temporary file to store the transaction (default / tmp). When the thread ends, the temporary file will be deleted automatically.

Binlog error action: the default value is abort server, which will cause MySQL to directly exit (Crash action) when writing binlog in case of serious errors, such as full disk, non writable file system, etc. Under the abort [server] option, binlog and slave databases are both secure, which is why the default value is officially selected.

Now we can answer the premise question~

1. binlog error is caused by / partition space is full. Why MySQL Crash?

• Because the default value of binlog error action parameter is abort server, when binlog writes an error, it will choose to exit directly to ensure binlog security.

1. /The partition clearly has more than ten G of remaining space, why it is full, what files are full, and why the space is automatically released after the event.

• It is speculated that because the transaction is large and exceeds the binlog ﹣ cache ﹣ size, temporary files will be generated under / TMP (i.e. / partition), resulting in insufficient / partition space. After MySQL Crash, the space will be released automatically, so it is normal to see / partition space afterwards.

4, Test simulation

Local environment (slightly different from the above partition for testing purposes):

Filesystem           Size  Used Avail Use% Mounted on
/dev/mapper/cl-root   96G   57G   39G  60% /               <-------- datadir = /data/mysql_data
/dev/mapper/cl-tmp   3.8G   33M  3.8G   1% /data/tmp	   <-------- tmpdir  = /data/tmp

Simulate a large transaction composed of multiple SQL, display the open transaction in the stored procedure, insert 1kw data circularly, and observe the usage of tmpdir directory

You can't see the temporary files directly under / data/tmp. Only through lsof command can you see that the temporary files are generated in tmpdir directory, and they are growing all the time, taking up a lot of space in tmpdir directory.

No space left on device is reported when the stored procedure finally executes, that is, the temporary directory space is insufficient, but MySQL does not Crash at this time, and no error is reported in the errorlog!!!

After testing and verification, when an error is reported, if you execute a commit or open another transaction in the same session, the binlog error action will be triggered immediately, which will cause MySQL to crash immediately, and binlog error will be reported in the errorlog, which is consistent with the phenomenon on the project.

PS: when MySQL interpreter encounters start transaction, it will trigger commit !!!

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.

5, Source tracking

In order to see which step of the source code the above test process first reported an error, two DBUG logs were compared. The left figure is the error reporting trace log, and the right figure is the error free trace log.

You can see that the error reporting trace log finally throws an error in the my write function, while the log without error reporting normally executes the my write function.

//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); //Writenbytes is the number of bytes actually written
		//...
		if (writtenbytes == Count)  //Determine whether the number of bytes actually written matches the number of bytes required to be written
		{
		  //If the write is normal, it will directly break out of the loop and end normally
	      sum_written+= writtenbytes;
	      break;
	    }
		//...
	}
	//...
	if (MyFlags & (MY_NABP | MY_FNABP))
	{
	    if (sum_written == initial_count)  //Write to go through the logic normally, and return 0 for success
	      DBUG_RETURN(0);   
	    if (MyFlags & (MY_WME | MY_FAE | MY_FNABP)) //The write process reports an error
	    {
	      char errbuf[MYSYS_STRERROR_SIZE];
	      my_error(EE_WRITE, MYF(0), my_filename(Filedes),
               my_errno(), my_strerror(errbuf, sizeof(errbuf), my_errno())); //Print error messages
	    }
	    DBUG_RETURN(MY_FILE_ERROR); //Return error
    }
    //...
}

/*
As for the source code, MySQL will finally use the Linux kernel method write (files, buffer, count) to refresh the binlog buffer to the disk file.
1. Filedes Is the file number (corresponding to the file number under / proc/mysqld_pid/fd)
2. Buffer Is a pointer to the required write buffer.
3. Count Is the number of bytes to write.

my: fd: 51  Buffer: 0x7f24c49e9e30  Count: 27

Because the / data/tmp disk is full, it is unable to write the number of bytes required by Count, resulting in writenbytes! = Count, and then a series of subsequent code errors, finally inducing binlog error ﹣ action - > MySQL crash   
*/

The MySQL source code implementation Commit error reporting process is simplified as follows:

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_message_sql 2281
T@12: | | | | | | | | | | | | <my_error 211
T@12: | | | | | | | | | | | <my_write 122
T@12: | | | | | | | | | | <my_b_flush_io_cache 1583
T@12: | | | | | | | | | <reinit_io_cache 367
T@12: | | | | | | | | <MYSQL_BIN_LOG::do_write_cache 7679
T@12: | | | | | | | <MYSQL_BIN_LOG::write_cache(THD *, binlog_cache_data *, bool) 8031
T@12: | | | | | | <binlog_cache_data::flush 1740
T@12: | | | | | <MYSQL_BIN_LOG::process_flush_stage_queue 8848
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: | | | | | | | | | <print_buffer_to_file 2109
T@12: | | | | | | | | <error_log_print 2134
T@12: | | | | | | | <sql_print_error 2148
T@12: | | | | | | <my_message_sql 2281
T@12: | | | | | <my_error 211

6, Extended content

The error report in the figure below is actually a daily example of this problem. Many children's shoes may encounter this problem when restoring MySQL through navicate. In essence, when restoring the database through navicate, transactions will be taken by default. When the table database is large, the transaction size is larger than the binlog ﹐ cache ﹐ size, the transaction data will be recorded with the temporary table. When tmdir If the directory disk is insufficient, an error will be reported. However, this situation will not cause MySQL Crash, because the navigator will not continue to execute the commit or another transaction after the error is restored, but directly disconnect.

Seven, summary

At present, this problem is rarely encountered in the project. This time, it is also used for learning and discussion out of curiosity. Here is a summary of the scene of this problem:

1. There are large transactions in the code, which are larger than binlog ﹣ cache ﹣ size, and generate a large number of temporary files, occupying tmpdir. 2. The code encountered the tmpdir disk full error during the transaction execution. If the error is not handled, the rollback will be executed and the subsequent Commit will be executed. 3. The code encountered the tmpdir disk full error during the transaction execution process. If it did not handle the exception, it rolled back. If it continued to execute, it encountered the nested transaction, causing Commit.

Maybe a lot of children's shoes think that they can increase binlog cache size to reduce the generation of temporary files, but this will increase memory consumption. Imagine the following: if binlog cache size increases to 32MB, when there are 300 database connections, each connection will allocate 32MB binlog cache (no matter how much you use), then it is nearly 10G, which is easy to cause memory overflow, and the system will OOM.

Therefore, binlog cache size cannot be increased a lot. The fundamental solution is to reduce the transaction size, avoid generating a large number of temporary files at the same time of high concurrent delivery, and fill tmpdir; in addition, it can increase the size of the partition where tmpdir is located.

Remaining problems:

The CentOS Linux release 7.3.1611 problem reappears successfully, and commit will lead to Crash. The CentOS Linux release 7.6.1810 problem cannot be repeated, and the commit does not report an error, but it will cause the binlog event part to write.

Appendix:

https://blog.51cto.com/lee90/1939469 https://dev.mysql.com/doc/refman/5.7/en/replication-options-binary-log.html https://stackoverflow.com/questions/37813819/mysql-max-binlog-cache-size-vs-binlog-cache-size