[MDEV-33282] Assertion `(longlong) binlog_space_total >= 0' failed in MYSQL_BIN_LOG::real_purge_logs_by_size Created: 2024-01-19  Updated: 2024-01-27  Resolved: 2024-01-21

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-31404 Implement binlog_space_limit In Testing
Relates
relates to MDEV-33320 Assertion `(longlong) binlog_space_to... Closed

 Description   

Notes:

  • The test case is non-deterministic, run with --repeat=N. It usually fails for me in a few attempts, but it can vary on different machines and builds.
  • The failure is rr-able via MTR --rr, although it may take more attempts.
  • The problem is scalable at least to some extent, it is not limited to the degenerate 4K value. I initially got it on 4M value (which is also low) with a much bigger test case, so there is no reason to think it cannot be increased even further. However, it requires very specific event/binlog sizes.
  • Binlog rotation prior to the flow as well as FLUSH STATUS performed in the while loop apparently doesn't do anything other than fill the binary log space.

--source include/have_binlog_format_mixed.inc
 
--source include/master-slave.inc
 
 
 
RESET MASTER;
 
SET @binlog_space= @@binlog_space_limit;
 
SET GLOBAL BINLOG_SPACE_LIMIT = 4096;
 
 
 
FLUSH BINARY LOGS;
 
FLUSH BINARY LOGS;
 
FLUSH BINARY LOGS;
 
 
 
--let $num= 17
 
while ($num)
 
{
 
  /* 13 chr filler */ FLUSH STATUS;
 
  --dec $num
 
}
 
--send
 
FLUSH STATUS;
 
 
 
--connection master1
 
SET GLOBAL BINLOG_SPACE_LIMIT = 0;
 
FLUSH LOGS;
 
 
 
--connection master
 
--reap
 
 
 
# Cleanup
 
SET GLOBAL BINLOG_SPACE_LIMIT = @binlog_space;
 
--source include/rpl_end.inc

bb-11.4-timestamp 6a706d142be3309de89c28bcb48e91a72e8e8f69

 
mariadbd: /data/bld/bb-11.4-timestamp-preview-asan/sql/log.cc:5293: int MYSQL_BIN_LOG::real_purge_logs_by_size(ulonglong): Assertion `(longlong) binlog_space_total >= 0' failed.
 
240119 15:32:27 [ERROR] mysqld got signal 6 ;
 
 
 
#9  0x00007f92e8053e32 in __GI___assert_fail (assertion=0x55a9f972bda0 "(longlong) binlog_space_total >= 0", file=0x55a9f97248e0 "/data/bld/bb-11.4-timestamp-preview-asan/sql/log.cc", line=5293, function=0x55a9f972bd40 "int MYSQL_BIN_LOG::real_purge_logs_by_size(ulonglong)") at ./assert/assert.c:101
 
#10 0x000055a9f7cdce57 in MYSQL_BIN_LOG::real_purge_logs_by_size (this=0x55a9fb644900 <mysql_bin_log>, binlog_pos=2891) at /data/bld/bb-11.4-timestamp-preview-asan/sql/log.cc:5293
 
#11 0x000055a9f7d0b943 in MYSQL_BIN_LOG::purge_logs_by_size (this=0x55a9fb644900 <mysql_bin_log>, binlog_pos=2891) at /data/bld/bb-11.4-timestamp-preview-asan/sql/log.h:1054
 
#12 0x000055a9f7ceaa0f in MYSQL_BIN_LOG::rotate (this=0x55a9fb644900 <mysql_bin_log>, force_rotate=false, check_purge=0x7f92db58cd50) at /data/bld/bb-11.4-timestamp-preview-asan/sql/log.cc:7458
 
#13 0x000055a9f7ce9567 in MYSQL_BIN_LOG::write (this=0x55a9fb644900 <mysql_bin_log>, event_info=0x7f92db58d3a0, with_annotate=0x0) at /data/bld/bb-11.4-timestamp-preview-asan/sql/log.cc:7190
 
#14 0x000055a9f6f2468c in THD::binlog_query (this=0x62c000120218, qtype=THD::STMT_QUERY_TYPE, query_arg=0x629000299238 "FLUSH STATUS", query_len=12, is_trans=false, direct=false, suppress_use=false, errcode=0) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_class.cc:7807
 
#15 0x000055a9f730fddd in write_bin_log (thd=0x62c000120218, clear_error=false, query=0x629000299238 "FLUSH STATUS", query_length=12, is_trans=false) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_table.cc:1038
 
#16 0x000055a9f705125d in mysql_execute_command (thd=0x62c000120218, is_called_from_prepared_stmt=false) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_parse.cc:5285
 
#17 0x000055a9f70621af in mysql_parse (thd=0x62c000120218, rawbuf=0x629000299238 "FLUSH STATUS", length=12, parser_state=0x7f92db58e9f0) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_parse.cc:7798
 
#18 0x000055a9f7039804 in dispatch_command (command=COM_QUERY, thd=0x62c000120218, packet=0x62900028f219 "FLUSH STATUS", packet_length=12, blocking=true) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_parse.cc:1893
 
#19 0x000055a9f703653c in do_command (thd=0x62c000120218, blocking=true) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_parse.cc:1406
 
#20 0x000055a9f7507cbe in do_handle_one_connection (connect=0x608000002e38, put_in_cache=true) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_connect.cc:1417
 
#21 0x000055a9f750767f in handle_one_connection (arg=0x608000002e38) at /data/bld/bb-11.4-timestamp-preview-asan/sql/sql_connect.cc:1319
 
#22 0x000055a9f8130444 in pfs_spawn_thread (arg=0x617000006d18) at /data/bld/bb-11.4-timestamp-preview-asan/storage/perfschema/pfs.cc:2201
 
#23 0x00007f92e80a8044 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#24 0x00007f92e812861c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81



 Comments   
Comment by Michael Widenius [ 2024-01-20 ]

I had forgot a mutex when setting binlog space to 0. Now fixed.

Comment by Michael Widenius [ 2024-01-21 ]

Fix pushed to bb-11.4-timestamp

Generated at Thu Feb 08 10:37:45 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.