Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
N/A
-
None
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
|
Attachments
Issue Links
- is caused by
-
MDEV-31404 Implement binlog_space_limit
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
| Field | Original Value | New Value |
|---|---|---|
| Link |
This issue is caused by |
| 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 {{\-\-r]}, although it may take somewhat 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is ran in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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 somewhat 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is ran in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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 somewhat 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is ran in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is ran in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is ran in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread and seems important. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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 apparently takes very specific event/binlog sizes. - {{FLUSH STATUS}} performed in the {{while}} loop apparently doesn't do anything other than fill the binary log. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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 apparently takes 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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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 apparently takes 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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| 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. The last {{FLUSH STATUS}} outside the loop is run in parallel with the other thread. {code:sql} --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 {code} {noformat:title=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 {noformat} |
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. {code:sql} --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 {code} {noformat:title=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 {noformat} |
| Status | Open [ 1 ] | In Progress [ 3 ] |
| Status | In Progress [ 3 ] | Stalled [ 10000 ] |
| issue.field.resolutiondate | 2024-01-21 12:40:51.0 | 2024-01-21 12:40:51.379 |
| Fix Version/s | N/A [ 14700 ] | |
| Fix Version/s | 11.4 [ 29301 ] | |
| Resolution | Fixed [ 1 ] | |
| Status | Stalled [ 10000 ] | Closed [ 6 ] |
| Link |
This issue relates to |
I had forgot a mutex when setting binlog space to 0. Now fixed.