The following analysis is based on the code revision number c250ec9791ed6c7695ae6a191397a3b65db2e994: Analysis #1. 1) The assertion takes place on debug build here: (gdb) bt #0 0x00007ffff67c6cc9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007ffff67ca0d8 in __GI_abort () at abort.c:89 #2 0x00007ffff67bfb86 in __assert_fail_base (fmt=0x7ffff6910830 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x10886c9 "is_binlog_empty()", file=file@entry=0x1088548 "./sql/binlog.cc", line=line@entry=433, function=function@entry=0x108cdc0 "virtual void binlog_cache_data::reset()") at assert.c:92 #3 0x00007ffff67bfc32 in GI_assert_fail (assertion=0x10886c9 "is_binlog_empty()", file=0x1088548 "./sql/binlog.cc", line=433, function=0x108cdc0 "virtual void binlog_cache_data::reset()") at assert.c:101 #4 0x0000000000a47967 in binlog_cache_data::reset (this=0x7fff98024fe0) at ./sql/binlog.cc:433 #5 0x0000000000a47d2c in binlog_trx_cache_data::reset (this=0x7fff98024fe0) at ./sql/binlog.cc:648 #6 0x0000000000a32a7e in binlog_cache_data::flush (this=0x7fff98024fe0, thd=0x20adb10, bytes_written=0x7fffdc0d14b8, wrote_xid=0x7fffdc0d14eb) at ./sql/binlog.cc:1270 #7 0x0000000000a4827a in binlog_cache_mngr::flush (this=0x7fff98024e70, thd=0x20adb10, bytes_written=0x7fffdc0d14f0, wrote_xid=0x7fffdc0d14eb) at ./sql/binlog.cc:778 #8 0x0000000000a40b63 in MYSQL_BIN_LOG::flush_thread_caches (this=0x1859dc0 , thd=0x20adb10) at ./sql/binlog.cc:6779 #9 0x0000000000a40cfc in MYSQL_BIN_LOG::process_flush_stage_queue (this=0x1859dc0 , total_bytes_var=0x7fffdc0d15f0, rotate_var=0x7fffdc0d15de, out_queue_var=0x7fffdc0d15f8) at ./sql/binlog.cc:6835 #21 0x00007ffff737d182 in start_thread (arg=0x7fffdc0d5700) at pthread_create.c:312 #22 0x00007ffff688a47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 binlog_cache_data::is_binlog_empty() returns false because binlog_cache_data::cache_log.pos_in_file have some suspicious value (10344644715844964239). 2) binlog_cache_data::cache_log.pos_in_file is set from here: Old value = 368 New value = 10344644715844964239 reinit_io_cache (info=0x7fff9404db48, type=WRITE_CACHE, seek_offset=10344644715844964239, use_async_io=0 '\000', clear_cache=0 '\000') at ./mysys/mf_iocache.c:387 387 info->seek_not_done=1; (gdb) bt #0 reinit_io_cache (info=0x7fff9404db48, type=WRITE_CACHE, seek_offset=10344644715844964239, use_async_io=0 '\000', clear_cache=0 '\000') at ./mysys/mf_iocache.c:387 #1 0x0000000000a47aaa in binlog_cache_data::truncate (this=0x7fff9404db40, pos=10344644715844964239) at ./sql/binlog.cc:486 #2 0x0000000000a48011 in binlog_trx_cache_data::restore_savepoint (this=0x7fff9404db40, pos=10344644715844964239) at ./sql/binlog.cc:691 #3 0x0000000000a34368 in binlog_savepoint_rollback (hton=0x188ca40, thd=0x20b38c0, sv=0x7fff94007040) at ./sql/binlog.cc:1900 #4 0x00000000006391c7 in ha_rollback_to_savepoint (thd=0x20b38c0, sv=0x7fff94007010) at ./sql/handler.cc:2132 #5 0x00000000008aac33 in trans_rollback_to_savepoint (thd=0x20b38c0, name=...) at ./sql/transaction.cc:661 #6 0x00000000007dab7d in mysql_execute_command (thd=0x20b38c0) at ./sql/sql_parse.cc:4843 #7 0x000000000098eea0 in sp_instr_stmt::exec_core (this=0x7fff940b94b8, thd=0x20b38c0, nextp=0x7fffdc0d0560) at ./sql/sp_instr.cc:937 #8 0x000000000098dc47 in sp_lex_instr::reset_lex_and_exec_core (this=0x7fff940b94b8, thd=0x20b38c0, nextp=0x7fffdc0d0560, open_tables=false) at ./sql/sp_instr.cc:391 #9 0x000000000098e5f8 in sp_lex_instr::validate_lex_and_execute_core (this=0x7fff940b94b8, thd=0x20b38c0, nextp=0x7fffdc0d0560, open_tables=false) at ./sql/sp_instr.cc:642 #10 0x000000000098eb36 in sp_instr_stmt::execute (this=0x7fff940b94b8, thd=0x20b38c0, nextp=0x7fffdc0d0560) at ./sql/sp_instr.cc:825 #11 0x000000000072d099 in sp_head::execute (this=0x7fff940bf9d0, thd=0x20b38c0, merge_da_on_success=true) at ./sql/sp_head.cc:648 #12 0x000000000072eef7 in sp_head::execute_procedure (this=0x7fff940bf9d0, thd=0x20b38c0, args=0x7fff940773d8) at ./sql/sp_head.cc:1321 #13 0x00000000007db505 in mysql_execute_command (thd=0x20b38c0) at ./sql/sql_parse.cc:5105 #14 0x000000000098eea0 in sp_instr_stmt::exec_core (this=0x7fff9407c990, thd=0x20b38c0, nextp=0x7fffdc0d1fe0) at ./sql/sp_instr.cc:937 #15 0x000000000098dc47 in sp_lex_instr::reset_lex_and_exec_core (this=0x7fff9407c990, thd=0x20b38c0, nextp=0x7fffdc0d1fe0, open_tables=false) at ./sql/sp_instr.cc:391 #16 0x000000000098e5f8 in sp_lex_instr::validate_lex_and_execute_core (this=0x7fff9407c990, thd=0x20b38c0, nextp=0x7fffdc0d1fe0, open_tables=false) at ./sql/sp_instr.cc:642 #17 0x000000000098eb36 in sp_instr_stmt::execute (this=0x7fff9407c990, thd=0x20b38c0, nextp=0x7fffdc0d1fe0) at ./sql/sp_instr.cc:825 #18 0x000000000072d099 in sp_head::execute (this=0x7fff94075b10, thd=0x20b38c0, merge_da_on_success=false) at ./sql/sp_head.cc:648 #19 0x000000000072db03 in sp_head::execute_trigger (this=0x7fff94075b10, thd=0x20b38c0, db_name=0x7fff94062d10, table_name=0x7fff94062d20, grant_info=0x7fff9405ff88) at ./sql/sp_head.cc:895 #20 0x0000000000865ce3 in Table_triggers_list::process_triggers (this=0x7fff9405fe30, thd=0x20b38c0, event=TRG_EVENT_UPDATE, time_type=TRG_ACTION_AFTER, old_row_is_record1=true) at ./sql/sql_trigger.cc:2184 #21 0x000000000086e9b5 in mysql_update (thd=0x20b38c0, table_list=0x7fff94005128, fields=..., values=..., conds=0x7fff9409c268, order_num=0, order=0x0, limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fffdc0d2cd0, updated_return=0x7fffdc0d2d90) at ./sql/sql_update.cc:848 #22 0x00000000007d75da in mysql_execute_command (thd=0x20b38c0) at ./sql/sql_parse.cc:3758 #23 0x00000000007dfe00 in mysql_parse (thd=0x20b38c0, rawbuf=0x7fff94004ff0 "update messages set last_updated_user_id=582 where id = 1", length=57, parser_state=0x7fffdc0d41d0) at ./sql/sql_parse.cc:6955 #24 0x00000000007d1da0 in dispatch_command (command=COM_QUERY, thd=0x20b38c0, packet=0x2197e41 "update messages set last_updated_user_id=582 where id = 1", packet_length=57) at ./sql/sql_parse.cc:1442 #25 0x00000000007d0c55 in do_command (thd=0x20b38c0) at ./sql/sql_parse.cc:1054 #26 0x000000000079a5d8 in do_handle_one_connection (thd_arg=0x20b38c0) at ./sql/sql_connect.cc:1532 #27 0x000000000079a0ef in handle_one_connection (arg=0x20b38c0) at ./sql/sql_connect.cc:1443 #28 0x0000000000da1942 in pfs_spawn_thread (arg=0x210c000) at ./storage/perfschema/pfs.cc:1860 #29 0x00007ffff737d182 in start_thread (arg=0x7fffdc0d5700) at pthread_create.c:312 #30 0x00007ffff688a47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 trans_rollback_to_savepoint() gets SAVEPOINT instance from thd->transaction.savepoints linked list. 3) thd->transaction.savepoints linked list is filled from trans_savepoint(): else if ((newsv= (SAVEPOINT *) alloc_root(&thd->transaction.mem_root, savepoint_alloc_size)) == NULL) { my_error(ER_OUT_OF_RESOURCES, MYF(0)); DBUG_RETURN(TRUE); } 4) Where savepoint_alloc_size is set from? See ha_init(): savepoint_alloc_size+= sizeof(SAVEPOINT); and ha_initialize_handlerton(): tmp= hton->savepoint_offset; hton->savepoint_offset= savepoint_alloc_size; savepoint_alloc_size+= tmp; i.e. each handlerton has savepoint_offset, the amount if information which handlerton wants to store in savepoint. struct handlerton { ... /* to store per-savepoint data storage engine is provided with an area of a requested size (0 is ok here). savepoint_offset must be initialized statically to the size of the needed memory to store per-savepoint information. After xxx_init it is changed to be an offset to savepoint storage area and need not be used by storage engine. see binlog_hton and binlog_savepoint_set/rollback for an example. */ uint savepoint_offset; ... }; So there is some extra memory allocated just after SAVEPOINT instance which contains some per-engine information. 5) At what moment per-engine savepoint information for binlog, i.e. position in binlog file, is overwritten with suspicious data? Hardware watchpoint 3: *(uint64_t *)0x7fff94007040 Old value = 0 New value = 10344644715844964239 memset () at ../sysdeps/x86_64/memset.S:86 86 ../sysdeps/x86_64/memset.S: No such file or directory. (gdb) bt #0 memset () at ../sysdeps/x86_64/memset.S:86 #1 0x0000000000aa2cb6 in free_root (root=0x20b5280, MyFlags=1) at ./mysys/my_alloc.c:391 #2 0x0000000000648e3a in THD::st_transactions::cleanup (this=0x20b5190) at ./sql/sql_class.h:2719 #3 0x0000000000637dcd in ha_commit_low (thd=0x20b38c0, all=true, run_after_commit=false) at ./sql/handler.cc:1592 #4 0x0000000000a40f99 in MYSQL_BIN_LOG::process_commit_stage_queue (this=0x1859dc0 , thd=0x20b38c0, first=0x20b38c0) at ./sql/binlog.cc:6920 #5 0x0000000000a41c30 in MYSQL_BIN_LOG::ordered_commit (this=0x1859dc0 , thd=0x20b38c0, all=true, skip_commit=false) at ./sql/binlog.cc:7340 #6 0x0000000000a409c6 in MYSQL_BIN_LOG::commit (this=0x1859dc0 , thd=0x20b38c0, all=true) at ./sql/binlog.cc:6738 #7 0x0000000000637b29 in ha_commit_trans (thd=0x20b38c0, all=true, ignore_global_read_lock=false) at ./sql/handler.cc:1513 #8 0x00000000008a9aeb in trans_commit (thd=0x20b38c0) at ./sql/transaction.cc:230 #9 0x00000000007da8a8 in mysql_execute_command (thd=0x20b38c0) at ./sql/sql_parse.cc:4785 #10 0x00000000007dfe00 in mysql_parse (thd=0x20b38c0, rawbuf=0x7fff94004ff0 "COMMIT", length=6, parser_state=0x7fffdc0d41d0) at ./sql/sql_parse.cc:6955 #11 0x00000000007d1da0 in dispatch_command (command=COM_QUERY, thd=0x20b38c0, packet=0x2197e41 "COMMIT", packet_length=6) at ./sql/sql_parse.cc:1442 #12 0x00000000007d0c55 in do_command (thd=0x20b38c0) at ./sql/sql_parse.cc:1054 #13 0x000000000079a5d8 in do_handle_one_connection (thd_arg=0x20b38c0) at ./sql/sql_connect.cc:1532 #14 0x000000000079a0ef in handle_one_connection (arg=0x20b38c0) at ./sql/sql_connect.cc:1443 #15 0x0000000000da1942 in pfs_spawn_thread (arg=0x210c000) at ./storage/perfschema/pfs.cc:1860 #16 0x00007ffff737d182 in start_thread (arg=0x7fffdc0d5700) at pthread_create.c:312 #17 0x00007ffff688a47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 I.e. it happens when the memory for SAVEPOINT objects is deallocated at transaction end. 6) When the memory for SAVEPOINT instance and per-engine savepoint information is allocated next time in trans_savepoint() the ha_savepoint() does not initialize extra savepoint memory for binary log, and binlog_cache_data::cache_log.pos_in_file is initialized with this undefined value (see (2)). 7) How does binlog hadlerton must store per-engine information in savepoint instance? See ha_savepoint(): if ((err= ht->savepoint_set(ht, thd, (uchar *)(sv+1)+ht->savepoint_offset))) { // cannot happen my_error(ER_GET_ERRNO, MYF(0), err); error=1; } binlog_savepoint_set(): /* We cannot record the position before writing the statement because a rollback to a savepoint (.e.g. consider it "S") would prevent the savepoint statement (i.e. "SAVEPOINT S") from being written to the binary log despite the fact that the server could still issue other rollback statements to the same savepoint (i.e. "S"). Given that the savepoint is valid until the server releases it, ie, until the transaction commits or it is released explicitly, we need to log it anyway so that we don't have "ROLLBACK TO S" or "RELEASE S" without the preceding "SAVEPOINT S" in the binary log. */ if (!(error= mysql_bin_log.write_event(&qinfo))) binlog_trans_log_savepos(thd, (my_off_t*) sv); binlog_trans_log_savepos(): static void binlog_trans_log_savepos(THD *thd, my_off_t *pos) { DBUG_ENTER("binlog_trans_log_savepos"); DBUG_ASSERT(pos != NULL); binlog_cache_mngr *const cache_mngr= thd_get_cache_mngr(thd); DBUG_ASSERT(mysql_bin_log.is_open()); *pos= cache_mngr->trx_cache.get_byte_position(); DBUG_PRINT("return", ("position: %lu", (ulong) *pos)); DBUG_VOID_RETURN; } Summary: binlog_cache_data::cache_log.pos_in_file is initialized with undefined value in reinit_io_cache() because per-engine savepoint information which is situated just after SAVEPOINT instance is not initialized for binary log. binlog_cache_data::cache_log.pos_in_file is used for flushing binlog cache in my_b_flush_io_cache(), it can be the reason of writing binlog data in wrong file position which can lead to damaged binlog file.