Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.5, 10.6, 10.10(EOL)
Description
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with rr it was not immediately self evident how to replay this bug. However, running continue; multiple times in rr the bug still reproduces with this rr trace on the rr server:
cd /data/611902/369/rr/mysqld-0
|
rr replay "${PWD}"
|
(rr) continue; -> leads to SIGUSR1 in thread 1
|
(rr) continue; -> leads to SIGUSR1 in thread 24
|
(rr) continue; -> leads to SIGUSR1 in thread 25
|
(rr) continue; -> leads to SIGABRT as described in this ticket
|
Leads to (rr based trace):
Thread 1 received signal SIGABRT, Aborted.
|
[Switching to Thread 3673578.3673578]
|
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00001481826b9859 in __GI_abort () at abort.c:79
|
#2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
|
assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449,
|
function=<optimized out>) at assert.c:92
|
#3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0",
|
file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449,
|
function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101
|
#4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>)
|
at /test/10.6_dbg/sql/log.cc:3449
|
#5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962
|
#6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>)
|
at /test/10.6_dbg/sql/mysqld.cc:5728
|
#7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25
|
Leads to (mysqld based trace):
10.6.0 9a08fcbf60567992971262ececee8d8429c20756 |
mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed.
|
10.6.0 9a08fcbf60567992971262ececee8d8429c20756 |
Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'.
|
Program terminated with signal SIGABRT, Aborted.
|
#0 0x0000000070000002 in ?? ()
|
[Current thread is 1 (Thread 0x148182886800 (LWP 3673578))]
|
(gdb) bt
|
#0 0x0000000070000002 in ?? ()
|
#1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120
|
#2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229
|
#3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291
|
#4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855
|
#5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987
|
#6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282
|
#7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417
|
#8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463
|
#9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
|
#10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
|
#11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330
|
#12 <signal handler called>
|
#13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#14 0x00001481826b9859 in __GI_abort () at abort.c:79
|
#15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92
|
#16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101
|
#17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449
|
#18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962
|
#19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728
|
#20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25
|
From the error log
10.6.0 9a08fcbf60567992971262ececee8d8429c20756 |
END OF INNODB MONITOR OUTPUT
|
============================
|
2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown*
|
2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed
|
2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0
|
2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master
|
2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4
|
2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection
|
2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes
|
2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0
|
2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting.
|
2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions
|
mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed.
|
210122 1:11:33 [ERROR] mysqld got signal 6 ;
|
...
|
Server version: 10.6.0-MariaDB-debug-log
|
key_buffer_size=16777216
|
read_buffer_size=131072
|
max_used_connections=11
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
Thread pointer: 0x0
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x0 thread_stack 0x49000
|
/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2]
|
mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599]
|
sigaction.c:0(__restore_rt)[0x40d01c1ab3c0]
|
??:0(gsignal)[0x1481826da18b]
|
??:0(abort)[0x1481826b9859]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729]
|
??:0(__assert_fail)[0x1481826caf36]
|
/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77]
|
sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428]
|
sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f]
|
sql/main.cc:26(main)[0x5627705a0b36]
|
??:0(__libc_start_main)[0x1481826bb0b3]
|
/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e]
|
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /dev/shm/611902/369/data
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size unlimited unlimited bytes
|
Max core file size unlimited unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes unlimited unlimited processes
|
Max open files 1048576 1048576 files
|
Max locked memory unlimited unlimited bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals unlimited unlimited signals
|
Max msgqueue size unlimited unlimited bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
mysqld options that were used in this run:
--no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M
|
A core dump is also available:
cd /data/611902/369
|
gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core
|
...
|
Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'.
|
Program terminated with signal SIGABRT, Aborted.
|
#0 0x0000000070000002 in ?? ()
|
[Current thread is 1 (Thread 0x148182886800 (LWP 3673578))]
|
(gdb) f 15
|
#15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
|
assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449,
|
function=<optimized out>) at assert.c:92
|
(gdb)
|
Other versions may or may not be affected. Optimized builds may or may not be affected.
It could be that this issue is only possible in multi-threaded client setups. May be related to MDEV-742.
Attachments
Issue Links
- relates to
-
MDEV-25611 RESET MASTER still causes the server to hang
-
- Closed
-
Activity
Field | Original Value | New Value |
---|---|---|
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to nail down this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) {nofomat} |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) {nofomat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) {noformat} |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) {noformat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} Other versions may or may not be affected. Optimized builds may or may not be affected. |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} Other versions may or may not be affected. Optimized builds may or may not be affected. |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} Other versions may or may not be affected. Optimized builds may or may not be affected. It could be that this issue is only possible in multi-threaded client setups. |
Description |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} Other versions may or may not be affected. Optimized builds may or may not be affected. It could be that this issue is only possible in multi-threaded client setups. |
I have seen this bug many times in the runs, but have never been able to generate a testcase for it. Even with {{rr}} it was not immediately self evident how to replay this bug. However, running {{continue;}} multiple times in {{rr}} the bug still reproduces with this {{rr}} trace on the {{rr}} server:
{noformat} cd /data/611902/369/rr/mysqld-0 rr replay "${PWD}" (rr) continue; -> leads to SIGUSR1 in thread 1 (rr) continue; -> leads to SIGUSR1 in thread 24 (rr) continue; -> leads to SIGUSR1 in thread 25 (rr) continue; -> leads to SIGABRT as described in this ticket {noformat} Leads to (rr based trace): {noformat} Thread 1 received signal SIGABRT, Aborted. [Switching to Thread 3673578.3673578] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00001481826b9859 in __GI_abort () at abort.c:79 #2 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #3 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #4 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #5 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #6 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #7 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} Leads to (mysqld based trace): {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. {noformat} {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) bt #0 0x0000000070000002 in ?? () #1 0x00001481824513b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120 #2 0x000014818244d2ff in traced_raw_syscall (call=call@entry=0x681fffa0) at ./src/preload/syscallbuf.c:229 #3 0x000014818244e978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291 #4 syscall_hook_internal (call=0x681fffa0) at ./src/preload/syscallbuf.c:2855 #5 syscall_hook (call=0x681fffa0) at ./src/preload/syscallbuf.c:2987 #6 0x000014818244d1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282 #7 0x000014818244d20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417 #8 0x000014818244d263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463 #9 0x000040d01c1a7f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 #10 0x00005627711fdab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424 #11 0x0000562770986856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330 #12 <signal handler called> #13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #14 0x00001481826b9859 in __GI_abort () at abort.c:79 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 #16 0x00001481826caf36 in __GI___assert_fail (assertion=assertion@entry=0x562771519387 "b->xid_count == 0", file=file@entry=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=line@entry=3449, function=function@entry=0x562771519399 "void MYSQL_BIN_LOG::cleanup()") at assert.c:101 #17 0x0000562770aedc77 in MYSQL_BIN_LOG::cleanup (this=0x562771cd43c0 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:3449 #18 0x00005627705a2428 in clean_up (print_message=print_message@entry=true) at /test/10.6_dbg/sql/mysqld.cc:1962 #19 0x00005627705b008f in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/mysqld.cc:5728 #20 0x00005627705a0b36 in main (argc=<optimized out>, argv=<optimized out>) at /test/10.6_dbg/sql/main.cc:25 {noformat} From the error log {noformat:title=10.6.0 9a08fcbf60567992971262ececee8d8429c20756} END OF INNODB MONITOR OUTPUT ============================ 2021-01-22 1:11:33 0 [Note] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld (initiated by: root[root] @ localhost []): *Normal shutdown* 2021-01-22 1:11:33 0 [Note] Event Scheduler: Purging the queue. 0 events 2021-01-22 1:11:33 22 [Note] Error reading relay log event: slave SQL thread was killed 2021-01-22 1:11:33 22 [Note] Slave SQL thread exiting, replication stopped in log 'FIRST' at position 0 2021-01-22 1:11:33 23 [Note] Slave I/O thread killed while connecting to master 2021-01-22 1:11:33 23 [Note] Slave I/O thread exiting, read up to log 'FIRST', position 4 2021-01-22 1:11:33 23 [Note] cannot connect to master to kill slave io_thread's connection 2021-01-22 1:11:33 0 [Note] InnoDB: FTS SYNC for table `test`.`t-26`, deleted count: 0 size: 0 bytes 2021-01-22 1:11:33 0 [Note] InnoDB: SYNC words: 0 2021-01-22 1:11:33 0 [Note] InnoDB: FTS optimize thread exiting. 2021-01-22 1:11:33 0 [Note] InnoDB: to purge 57 transactions mysqld: /test/10.6_dbg/sql/log.cc:3449: void MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed. 210122 1:11:33 [ERROR] mysqld got signal 6 ; ... Server version: 10.6.0-MariaDB-debug-log key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=11 max_threads=153 thread_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 36561 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(my_print_stacktrace+0x2f)[0x5627711fdcc2] mysys/stacktrace.c:212(my_print_stacktrace)[0x562770986599] sigaction.c:0(__restore_rt)[0x40d01c1ab3c0] ??:0(gsignal)[0x1481826da18b] ??:0(abort)[0x1481826b9859] /lib/x86_64-linux-gnu/libc.so.6(+0x25729)[0x1481826b9729] ??:0(__assert_fail)[0x1481826caf36] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_ZN13MYSQL_BIN_LOG7cleanupEv+0x221)[0x562770aedc77] sql/log.cc:3450(MYSQL_BIN_LOG::cleanup())[0x5627705a2428] sql/mysqld.cc:1964(clean_up(bool))[0x5627705b008f] sql/main.cc:26(main)[0x5627705a0b36] ??:0(__libc_start_main)[0x1481826bb0b3] /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld(_start+0x2e)[0x5627705a0a6e] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /dev/shm/611902/369/data Resource Limits: Limit Soft Limit Hard Limit Units Max cpu time unlimited unlimited seconds Max file size unlimited unlimited bytes Max data size unlimited unlimited bytes Max stack size unlimited unlimited bytes Max core file size unlimited unlimited bytes Max resident set unlimited unlimited bytes Max processes unlimited unlimited processes Max open files 1048576 1048576 files Max locked memory unlimited unlimited bytes Max address space unlimited unlimited bytes Max file locks unlimited unlimited locks Max pending signals unlimited unlimited signals Max msgqueue size unlimited unlimited bytes Max nice priority 0 0 Max realtime priority 0 0 Max realtime timeout unlimited unlimited us {noformat} mysqld options that were used in this run: {noformat} --no-defaults --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --innodb_stats_persistent=off --loose-idle_write_transaction_timeout=0 --loose-idle_transaction_timeout=0 --loose-idle_readonly_transaction_timeout=0 --connect_timeout=60 --interactive_timeout=28800 --slave_net_timeout=60 --net_read_timeout=30 --net_write_timeout=60 --loose-table_lock_wait_timeout=50 --wait_timeout=28800 --lock-wait-timeout=86400 --innodb-lock-wait-timeout=50 --log_output=FILE --log-bin --log_bin_trust_function_creators=1 --loose-max-statement-time=30 --loose-debug_assert_on_not_freed_memory=0 --innodb-buffer-pool-size=300M {noformat} A core dump is also available: {noformat} cd /data/611902/369 gdb /test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld ./data/core ... Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'. Program terminated with signal SIGABRT, Aborted. #0 0x0000000070000002 in ?? () [Current thread is 1 (Thread 0x148182886800 (LWP 3673578))] (gdb) f 15 #15 0x00001481826b9729 in __assert_fail_base (fmt=0x14818284f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562771519387 "b->xid_count == 0", file=0x562771518c44 "/test/10.6_dbg/sql/log.cc", line=3449, function=<optimized out>) at assert.c:92 (gdb) {noformat} Other versions may or may not be affected. Optimized builds may or may not be affected. It could be that this issue is only possible in multi-threaded client setups. May be related to |
Assignee | Andrei Elkin [ elkin ] |
Affects Version/s | 10.5 [ 23123 ] |
Fix Version/s | 10.5 [ 23123 ] |
Labels | rr-profile | affects-tests rr-profile |
Assignee | Andrei Elkin [ elkin ] | Roel Van de Paar [ roel ] |
Labels | affects-tests rr-profile | affects-tests need_feedback rr-profile |
Comment | [ Added need_feedback to remind myself to check this regularly against runs. I have disabled the filter. ] |
Labels | affects-tests need_feedback rr-profile | affects-tests rr-profile |
Assignee | Roel Van de Paar [ roel ] | Andrei Elkin [ elkin ] |
Attachment | MDEV-24660.sql [ 58242 ] |
Attachment |
|
Attachment | MDEV-24660.sql [ 58243 ] |
Fix Version/s | 10.6 [ 24028 ] |
Workflow | MariaDB v3 [ 118423 ] | MariaDB v4 [ 142520 ] |
Status | Open [ 1 ] | In Progress [ 3 ] |
Affects Version/s | 10.10 [ 27530 ] |
Link |
This issue relates to |
Summary | MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed in MYSQL_BIN_LOG::cleanup | MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed in MYSQL_BIN_LOG::cleanup on SHUTDOWN |
Labels | affects-tests rr-profile | affects-tests rr-profile-analyzed |
Fix Version/s | 10.7 [ 24805 ] | |
Fix Version/s | 10.8 [ 26121 ] |
Assignee | Andrei Elkin [ elkin ] | Brandon Nesterenko [ JIRAUSER48702 ] |
Status | In Progress [ 3 ] | In Review [ 10002 ] |
Assignee | Brandon Nesterenko [ JIRAUSER48702 ] | Andrei Elkin [ elkin ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Fix Version/s | 10.5.18 [ 28421 ] | |
Fix Version/s | 10.6.10 [ 28407 ] | |
Fix Version/s | 10.7.6 [ 28408 ] | |
Fix Version/s | 10.8.5 [ 28308 ] | |
Fix Version/s | 10.9.3 [ 28409 ] | |
Fix Version/s | 10.5 [ 23123 ] | |
Fix Version/s | 10.6 [ 24028 ] | |
Fix Version/s | 10.7 [ 24805 ] | |
Fix Version/s | 10.8 [ 26121 ] | |
Resolution | Fixed [ 1 ] | |
Status | Stalled [ 10000 ] | Closed [ 6 ] |
Zendesk Related Tickets | 198889 |
Is the issue perhaps simple to understand or deduce? For example; server shutdown -> InnoDB attempted further work -> where such work was unexpected and unhandled by binlog code, or similar?
/*
There should be no pending XIDs at shutdown, and only one entry (for
the active binlog file) in the list.
*/
DBUG_ASSERT(b->xid_count == 0);