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
-
-
- Closed
-