Bug #51282 insert delayed thread asserts when binlog is closed due to reset master!
Submitted: 18 Feb 2010 14:02 Modified: 20 Jan 2011 18:17
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S1 (Critical)
Version:5.1.34-debug, 5.1.44-debug, 5.1.45-debug, 5.5.1-m2-debug OS:Any
Assigned to: Luis Manuel Oliveira Soares CPU Architecture:Any
Tags: assertion, insert delayed

[18 Feb 2010 14:02] Shane Bester
Description:
insert delayed thread hits this assertion:

Assertion failed: current_stmt_binlog_row_based && mysql_bin_log.is_open(), file .\sql_class.cc, line 3637

mysqld.exe!my_sigabrt_handler()[mysqld.cc:2047]
mysqld.exe!raise()[winsig.c:590]
mysqld.exe!abort()[abort.c:71]
mysqld.exe!_wassert()[assert.c:212]
mysqld.exe!THD::binlog_write_row()[sql_class.cc:3637]
mysqld.exe!Write_rows_log_event::binlog_row_logging_function()[log_event.h:3674]
mysqld.exe!binlog_log_row()[handler.cc:4590]
mysqld.exe!handler::ha_write_row()[handler.cc:4652]
mysqld.exe!write_record()[sql_insert.cc:1606]
mysqld.exe!Delayed_insert::handle_inserts()[sql_insert.cc:2704]
mysqld.exe!handle_delayed_insert_impl()[sql_insert.cc:2448]
mysqld.exe!handle_delayed_insert()[sql_insert.cc:2534]
mysqld.exe!pthread_start()[my_winthread.c:85]
mysqld.exe!_callthreadstart()[thread.c:293]
mysqld.exe!_threadstart()[thread.c:277]

How to repeat:
start debug server with --log-bin --binlog-format=row --sync-binlog=0
in one thread, insert delayed into a table.
in another thread, reset master.

Suggested fix:
figure out what should insert delayed thread do if binlog is closed...?
[18 Feb 2010 14:15] MySQL Verification Team
testcase, run against a fast machine.

Attachment: bug51282.c (text/plain), 6.06 KiB.

[18 Feb 2010 16:59] Valeriy Kravchuk
I was not able to get any assertion failure with 5.1.45-debug on Mac OS X:

...
queries: 000016067
queries: 000016070
queries: 000016075
queries: 000016078
waiting for worker threads to finish...

Maybe this MacBook is not powerful enough with its 2 cores only.
[18 Feb 2010 18:43] MySQL Verification Team
I wasn't unable to repeat too:

queries: 000029081
queries: 000029088
queries: 000029089
queries: 000029097
queries: 000029104
waiting for worker threads to finish...

on AMD Phenom Quad-Core 2.30 Ghz RAM 8 GB
[18 Feb 2010 23:07] MySQL Verification Team
i repeated it on blade12 with 16 threads in the testcase.

100218 23:14:57 [Note] /users/sbester/tmp/mysql-advanced-gpl-5.1.44-linux-x86_64-glibc23/bin/mysqld-debug: ready for connections.
Version: '5.1.44-enterprise-gpl-advanced-debug-log'  socket: 'sock'  port: 3333  MySQL Enterprise Server - Advanced Edition Debug (GPL)
mysqld-debug: sql_class.cc:3637: int THD::binlog_write_row(TABLE*, bool, const MY_BITMAP*, size_t, const uchar*): Assertion `current_stmt_binlog_row_based && mysql_bin_log.is_open()' failed.
100218 23:56:48 - mysqld got signal 6 ;
[19 Feb 2010 10:52] Valeriy Kravchuk
Verified just as described (almost immediately) on (fast) Linux with recent 5.1.45-debug from bzr.
[22 Dec 2010 13:26] MySQL Verification Team
5.5.8-debug and 5.5.7-debug and 5.1.54-debug official binaries crash on windows:
Version: '5.5.8-debug-log'  socket: ''  port: 3306  MySQL Community Server - Debug (GPL)
Assertion failed: is_current_stmt_binlog_format_row() && mysql_bin_log.is_open(), file ..\..\mysql-5.5.8\sql\sql_class.cc, line 4295
 my_sigabrt_handler()[my_thr_init.c:521]
 raise()[winsig.c:597]
 abort()[abort.c:78]
 _wassert()[assert.c:163]
 THD::binlog_write_row()[sql_class.cc:4295]
 Write_rows_log_event::binlog_row_logging_function()[log_event.h:3785]
 binlog_log_row()[handler.cc:4656]
 handler::ha_write_row()[handler.cc:4762]
 write_record()[sql_insert.cc:1738]
 Delayed_insert::handle_inserts()[sql_insert.cc:2973]
 handle_delayed_insert()[sql_insert.cc:2772]
 pthread_start()[my_winthread.c:62]
 _callthreadstartex()[threadex.c:348]
 _threadstartex()[threadex.c:331]
 BaseThreadStart()

5.5.7-debug on my linux and 5.5.9-debug on linux didn't crash for me.
I have no idea why.   So, somebody needs to test 5.5.9-bzr on windows (i cant build 5.5 on windows :( )
[14 Jan 2011 7:34] MySQL Verification Team
on 5.5.8-debug i also got:

Version: '5.5.8-debug-log'  socket: ''  port: 3306  MySQL Community Server - Debug (GPL)
Assertion failed: mysql_bin_log.is_open(), file ..\..\mysql-5.5.8\sql\log.cc, line 1436
mysqld-debug.exe!my_sigabrt_handler()[my_thr_init.c:521]
mysqld-debug.exe!raise()[winsig.c:590]
mysqld-debug.exe!abort()[abort.c:71]
mysqld-debug.exe!_wassert()[assert.c:163]
mysqld-debug.exe!binlog_trans_log_savepos()[log.cc:1436]
mysqld-debug.exe!THD::binlog_set_stmt_begin()[log.cc:4456]
mysqld-debug.exe!THD::binlog_start_trans_and_stmt()[log.cc:4428]
mysqld-debug.exe!THD::binlog_write_table_map()[log.cc:4493]
mysqld-debug.exe!write_locked_table_maps()[handler.cc:4596]
mysqld-debug.exe!binlog_log_row()[handler.cc:4643]
mysqld-debug.exe!handler::ha_write_row()[handler.cc:4762]
mysqld-debug.exe!write_record()[sql_insert.cc:1738]
mysqld-debug.exe!Delayed_insert::handle_inserts()[sql_insert.cc:2973]
mysqld-debug.exe!handle_delayed_insert()[sql_insert.cc:2772]
mysqld-debug.exe!pthread_start()[my_winthread.c:61]
mysqld-debug.exe!_callthreadstartex()[threadex.c:348]
mysqld-debug.exe!_threadstartex()[threadex.c:331]
[17 Jan 2011 0:18] Santo Leto
I was not able to verify this on Windows 7 64 bit (Dell Studio 1550 Intel Core 2 Duo 2.40GHz, 4 GB RAM):

- MySQL 5.5.10-debug-32-bit (revision 3254 compiled from bzr source):

* 8 threads:

mysqld.exe --defaults-file="d:\Santo_Local\mysql-builds\bug51282\mysql-5.5.10-win32\mysql-5.5.10-win32\my-small.ini" --log -P55101 --log-bin=mysql-bin --binlog-format=row --sync-binlog=0 --log-error="10_8_1500.err" 

queries: 000006281
queries: 000006283
queries: 000006286
queries: 000006288
waiting for worker threads to finish...

* 16 threads:

mysqld.exe --defaults-file="d:\Santo_Local\mysql-builds\bug51282\mysql-5.5.10-win32\mysql-5.5.10-win32\my-small.ini" --log -P55101 --log-bin=mysql-bin --binlog-format=row --sync-binlog=0 --log-error="10_16_1500.err" 

queries: 000007159
queries: 000007161
queries: 000007162
queries: 000007163
waiting for worker threads to finish...

- MySQL 5.5.8-debug-64-bit (official release):

* 16 threads:

mysqld-debug.exe --defaults-file="D:\Santo_Local\mysql-official-releases\mysql-5.5.8-winx64\mysql-5.5.8-winx64\my-small.ini" --log -P55081 --log-bin=mysql-bin --binlog-format=row --sync-binlog=0 --log-error="8_16_1500.err" 

queries: 000006535
queries: 000006536
queries: 000006539
queries: 000006542
waiting for worker threads to finish...

The following, instead, are the results of some other tests I did with mysql 5.5.8-debug (official release) and mysql-5.5.9-debug (revision 3238 compiled from bzr source) on a Dell Vostro 200, Windows Vista 32-bit, Intel Pentium Dual E2180 2.00 GHz, 4GB RAM:

- When running testcase with a number of threads equals to 8, 12, 16 on 5.5.8-debug and with a number of threads equals to 8 on 5.5.9-debug, I got something like:

    Assertion failed: ! is_set(), file ..\..\mysql-5.5.8\sql\sql_error.cc, line 359

	0058A423    mysqld-debug.exe!my_sigabrt_handler()[my_thr_init.c:521]
	00654E2B    mysqld-debug.exe!raise()[winsig.c:590]
	0065DCD5    mysqld-debug.exe!abort()[abort.c:71]
	006570D7    mysqld-debug.exe!_wassert()[assert.c:346]
	0025A661    mysqld-debug.exe!Diagnostics_area::set_ok_status()[sql_error.cc:359]
	0011EB49    mysqld-debug.exe!my_ok()[sql_class.h:2857]
	0024405B    mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:3547]
	00248E64    mysqld-debug.exe!mysql_parse()[sql_parse.cc:5496]
	0023EBCF    mysqld-debug.exe!dispatch_command()[sql_parse.cc:1032]
	0023E619    mysqld-debug.exe!do_command()[sql_parse.cc:772]
	00153C0F    mysqld-debug.exe!do_handle_one_connection()[sql_connect.cc:745]
	001539BC    mysqld-debug.exe!handle_one_connection()[sql_connect.cc:684]
	00589388    mysqld-debug.exe!pthread_start()[my_winthread.c:61]
	00664B03    mysqld-debug.exe!_callthreadstartex()[threadex.c:348]
	00664AA4    mysqld-debug.exe!_threadstartex()[threadex.c:331]
	769AD0E9    kernel32.dll!BaseThreadInitThunk()
	773819BB    ntdll.dll!RtlInitializeExceptionChain()
	7738198E    ntdll.dll!RtlInitializeExceptionChain()
	

- With 5.5.9-debug, when running testcase with a number of threads equals to 12, 16, I got something like:

	0177871E    mysqld.exe!_output_s_l()[output.c:1643]
	01766EE6    mysqld.exe!_vsnprintf_helper()[vsprintf.c:140]
	01767410    mysqld.exe!_vsnprintf_s_l()[vsprintf.c:288]
	01767680    mysqld.exe!_vsnprintf_s()[vsprintf.c:340]
	01746CDE    mysqld.exe!_VCrtDbgReportA()[dbgrptt.c:298]
	01766212    mysqld.exe!_CrtDbgReportV()[dbgrpt.c:241]
	017661DB    mysqld.exe!_CrtDbgReport()[dbgrpt.c:258]
	017502AB    mysqld.exe!_free_dbg_nolock()[dbgheap.c:1345]
	01750060    mysqld.exe!_free_dbg()[dbgheap.c:1265]
	0174D8A0    mysqld.exe!free()[dbgfree.c:49]
	014949A2    mysqld.exe!my_free()[my_malloc.c:128]
	014911BA    mysqld.exe!free_root()[my_alloc.c:365]
	012EC789    mysqld.exe!Warning_info::~Warning_info()[sql_error.cc:476]
	012187BF    mysqld.exe!THD::~THD()[sql_class.cc:1122]
	013B4F99    mysqld.exe!Delayed_insert::~Delayed_insert()[sql_insert.cc:1948]
	013B4DE6    mysqld.exe!Delayed_insert::`scalar deleting destructor'()
	013B0B74    mysqld.exe!handle_delayed_insert()[sql_insert.cc:2800]
	014916E8    mysqld.exe!pthread_start()[my_winthread.c:61]
	0174EAC3    mysqld.exe!_callthreadstartex()[threadex.c:314]
	0174EA64    mysqld.exe!_threadstartex()[threadex.c:297]
	769AD0E9    kernel32.dll!BaseThreadInitThunk()
	773819BB    ntdll.dll!RtlInitializeExceptionChain()
	7738198E    ntdll.dll!RtlInitializeExceptionChain()
	
- I never saw "Assertion failed: current_stmt_binlog_row_based && mysql_bin_log.is_open(), file .\sql_class.cc, line 3637", so on my machines I was not able to verify bug as reported by Shane.

  
Some other info on performed tests:
- I've used a modified version of Shane's testcase (some changes were needed to make the testcase compatible with windows). I can post it.

- In the testcase I've typically used - as value of the variable TESTTIME - 600 sec, but when performing tests with 8 threads only, I increased the number of seconds to 900, otherwise it was more difficult to get the crash on mysql 5.5.8 and on mysql 5.5.9.

- mysql-5.5.9-debug and mysql-5.5.10-debug have been compiled in the following way:
	cd bug51282
	cmake ..\..\mysql-source\mysql-5.5 -G "Visual Studio 10" -DWITH_DEBUG=1 -DWITH_INNOBASE_STORAGE_ENGINE=1 -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 
	vcexpress MySql.sln /build Debug /project package /out compilation_output.txt
[17 Jan 2011 19:19] Luis Manuel Oliveira Soares
Filed bug reports BUG#59565 and BUG#59566 so that newly (and 
apparently unrelated) found issues can be tracked and fixed.