Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24660

MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed in MYSQL_BIN_LOG::cleanup

    XMLWordPrintable

    Details

      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

          Activity

            People

            Assignee:
            Elkin Andrei Elkin
            Reporter:
            Roel Roel Van de Paar
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated: