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

Assertion `pending == log_requests.start.load(std::memory_order_relaxed)' failed in log_flush_notify_and_unlock or crash in MYSQL_BIN_LOG::mark_xid_done

    XMLWordPrintable

    Details

      Description

      Note: LOOP in the test case has no special significance for the outcome, it is here just to provide concurrency.

      --source include/have_innodb.inc
      --source include/have_log_bin.inc
       
      --connect (con1,localhost,root,,)
      --let $conid= `select connection_id()`
      --delimiter $
      --send
      LOOP
        FLUSH LOGS;
      END LOOP $
      --delimiter ;
       
      --connection default
      --let $run= 10000
      --disable_query_log
      while ($run)
      {
        CREATE OR REPLACE TABLE t ENGINE=InnoDB AS SELECT 1 AS a;
        --dec $run
        if (!`SELECT MOD($run,1000)`)
        {
          --echo # $run loops left
        }
      }
       
      # Cleanup
      --enable_query_log
      --eval KILL $conid
      DROP TABLE IF EXISTS t;
      

      10.5 76d2846a

      mariadbd: /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4467: void log_flush_notify_and_unlock(log_flush_request*, lsn_t): Assertion `pending == log_requests.start.load(std::memory_order_relaxed)' failed.
      210401  1:31:00 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007ff62bccaf36 in __GI___assert_fail (assertion=0x55d10e406a78 "pending == log_requests.start.load(std::memory_order_relaxed)", file=0x55d10e403708 "/data/src/10.5/storage/innobase/handler/ha_innodb.cc", line=4467, function=0x55d10e4069b8 "void log_flush_notify_and_unlock(log_flush_request*, lsn_t)") at assert.c:101
      #8  0x000055d10db14833 in log_flush_notify_and_unlock (pending=0x7ff5f4025d48, lsn=3465869) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4467
      #9  0x000055d10db14969 in log_flush_notify (flush_lsn=3465869) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4509
      #10 0x000055d10dbf07ba in log_write_up_to (lsn=3465869, flush_to_disk=true, rotate_key=false) at /data/src/10.5/storage/innobase/log/log0log.cc:832
      #11 0x000055d10debccc4 in fil_delete_tablespace (id=1921, if_exists=false, detached_handles=0x7ff625024310) at /data/src/10.5/storage/innobase/fil/fil0fil.cc:1827
      #12 0x000055d10dcdff0a in row_drop_table_for_mysql (name=0x7ff625024990 "test/t", trx=0x7ff62631f360, sqlcom=SQLCOM_CREATE_TABLE, create_failed=false, nonatomic=true) at /data/src/10.5/storage/innobase/row/row0mysql.cc:3767
      #13 0x000055d10db4274f in ha_innobase::delete_table (this=0x7ff5f00174b8, name=0x7ff625025c50 "./test/t", sqlcom=SQLCOM_CREATE_TABLE) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:13304
      #14 0x000055d10db29990 in ha_innobase::delete_table (this=0x7ff5f00174b8, name=0x7ff625025c50 "./test/t") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:13431
      #15 0x000055d10d698509 in hton_drop_table (hton=0x55d10fc84488, path=0x7ff625025c50 "./test/t") at /data/src/10.5/sql/handler.cc:564
      #16 0x000055d10d69dcdd in ha_delete_table (thd=0x7ff5f0000db8, hton=0x55d10fc84488, path=0x7ff625025c50 "./test/t", db=0x7ff625025ad0, alias=0x7ff625025ae0, generate_warning=false) at /data/src/10.5/sql/handler.cc:2770
      #17 0x000055d10d41e899 in mysql_rm_table_no_locks (thd=0x7ff5f0000db8, tables=0x7ff625026190, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=true, dont_free_locks=true) at /data/src/10.5/sql/sql_table.cc:2508
      #18 0x000055d10d426fcb in create_table_impl (thd=0x7ff5f0000db8, orig_db=..., orig_table_name=..., db=..., table_name=..., path=0x7ff625026940 "./test/t", options=..., create_info=0x7ff625027b80, alter_info=0x7ff625027ab0, create_table_mode=1, is_trans=0x0, key_info=0x7ff625026920, key_count=0x7ff625026914, frm=0x7ff625026930) at /data/src/10.5/sql/sql_table.cc:5260
      #19 0x000055d10d4279bd in mysql_create_table_no_lock (thd=0x7ff5f0000db8, db=0x7ff5f0015558, table_name=0x7ff5f0015568, create_info=0x7ff625027b80, alter_info=0x7ff625027ab0, is_trans=0x0, create_table_mode=1, table_list=0x7ff5f0015540) at /data/src/10.5/sql/sql_table.cc:5460
      #20 0x000055d10d2e62aa in select_create::create_table_from_items (this=0x7ff5f0016b70, thd=0x7ff5f0000db8, items=0x7ff625027640, lock=0x7ff625027630, hooks=0x7ff625027680) at /data/src/10.5/sql/sql_insert.cc:4462
      #21 0x000055d10d2e6b03 in select_create::prepare (this=0x7ff5f0016b70, _values=..., u=0x7ff5f0004f68) at /data/src/10.5/sql/sql_insert.cc:4659
      #22 0x000055d10d3786d3 in JOIN::prepare (this=0x7ff5f0016c70, tables_init=0x0, conds_init=0x0, og_num=0, order_init=0x0, skip_order_by=false, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0x7ff5f0015c20, unit_arg=0x7ff5f0004f68) at /data/src/10.5/sql/sql_select.cc:1506
      #23 0x000055d10d3841cc in mysql_select (thd=0x7ff5f0000db8, tables=0x0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2201171004160, result=0x7ff5f0016b70, unit=0x7ff5f0004f68, select_lex=0x7ff5f0015c20) at /data/src/10.5/sql/sql_select.cc:4701
      #24 0x000055d10d373d0b in handle_select (thd=0x7ff5f0000db8, lex=0x7ff5f0004ea0, result=0x7ff5f0016b70, setup_tables_done_option=0) at /data/src/10.5/sql/sql_select.cc:419
      #25 0x000055d10d43b8f8 in Sql_cmd_create_table_like::execute (this=0x7ff5f00154e0, thd=0x7ff5f0000db8) at /data/src/10.5/sql/sql_table.cc:12100
      #26 0x000055d10d335270 in mysql_execute_command (thd=0x7ff5f0000db8) at /data/src/10.5/sql/sql_parse.cc:6049
      #27 0x000055d10d33b494 in mysql_parse (thd=0x7ff5f0000db8, rawbuf=0x7ff5f0015410 "CREATE OR REPLACE TABLE t ENGINE=InnoDB AS SELECT 1 AS a", length=56, parser_state=0x7ff625028510, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8093
      #28 0x000055d10d32735f in dispatch_command (command=COM_QUERY, thd=0x7ff5f0000db8, packet=0x7ff5f000b6c9 "CREATE OR REPLACE TABLE t ENGINE=InnoDB AS SELECT 1 AS a", packet_length=56, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1889
      #29 0x000055d10d325b53 in do_command (thd=0x7ff5f0000db8) at /data/src/10.5/sql/sql_parse.cc:1370
      #30 0x000055d10d4d43b7 in do_handle_one_connection (connect=0x55d1102a1638, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1410
      #31 0x000055d10d4d411a in handle_one_connection (arg=0x55d1102637d8) at /data/src/10.5/sql/sql_connect.cc:1312
      #32 0x000055d10da36217 in pfs_spawn_thread (arg=0x55d1101e55c8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #33 0x00007ff62c1e2609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #34 0x00007ff62bdb6293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      It fails for me fairly quickly – either before the first progress printout, or soon after; but it can vary on different machines and builds.
      If the failure is not reproducible locally, coredumps are available.
      As predicted, it is hard to reproduce with rr. There are rr profiles available, two from the MTR test above and one from a random test, but they take quite long to replay (> 5 min).

      Thiru/Marko pointed (and the tests confirmed) that the failure appeared in 10.5 after this commit:

      commit 8c2e3259c13d1d0a494fb3f9c1e5fb780a193ab1
      Author: Marko Mäkelä
      Date:   Tue Mar 30 09:58:24 2021 +0300
       
          MDEV-24302 follow-up: RESET MASTER hangs
      

      Non-debug build crashes on the same test:

      10.5 76d2846a

      #3  <signal handler called>
      #4  0x0000558c9c457070 in MYSQL_BIN_LOG::mark_xid_done (this=0x558c9d2bcca0 <mysql_bin_log>, binlog_id=2661, write_checkpoint=<optimized out>) at /data/src/10.5/include/mysql/psi/mysql_thread.h:759
      #5  0x0000558c9c4576f5 in binlog_background_thread (arg=arg@entry=0x0) at /data/src/10.5/sql/log.cc:10381
      #6  0x0000558c9c5d2ca6 in pfs_spawn_thread (arg=0x558c9e87a698) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #7  0x00007fa37023e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #8  0x00007fa36fe2d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      Foreground threads:

      Thread 26 (Thread 0x7fa369085700 (LWP 742707)):
      #0  __lll_lock_wait (futex=futex@entry=0x558c9d2bccb0 <mysql_bin_log+16>, private=0) at lowlevellock.c:52
      #1  0x00007fa3702410a3 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x558c9d2bccb0 <mysql_bin_log+16>) at ../nptl/pthread_mutex_lock.c:80
      #2  0x0000558c9c447e33 in inline_mysql_mutex_lock (that=that@entry=0x558c9d2bccb0 <mysql_bin_log+16>, src_line=src_line@entry=6608, src_file=0x558c9cbd825c "/data/src/10.5/sql/log.cc") at /data/src/10.5/include/mysql/psi/mysql_thread.h:752
      #3  0x0000558c9c4609b1 in MYSQL_BIN_LOG::write (this=0x558c9d2bcca0 <mysql_bin_log>, event_info=event_info@entry=0x7fa3690837f0, with_annotate=with_annotate@entry=0x0) at /data/src/10.5/sql/log.cc:6608
      #4  0x0000558c9c0f1d68 in THD::binlog_query (this=0x7fa32c000c58, qtype=qtype@entry=THD::ROW_QUERY_TYPE, query_arg=0x7fa32c010580 "CREATE OR REPLACE TABLE t ENGINE=InnoDB AS SELECT 1 AS a", query_len=56, is_trans=<optimized out>, is_trans@entry=true, direct=<optimized out>, direct@entry=false, suppress_use=false, errcode=0) at /data/src/10.5/sql/sql_class.cc:7475
      #5  0x0000558c9c109717 in select_insert::prepare_eof (this=this@entry=0x7fa32c011ce0) at /data/src/10.5/sql/sql_class.h:1270
      #6  0x0000558c9c109b36 in select_create::send_eof (this=0x7fa32c011ce0) at /data/src/10.5/sql/sql_insert.cc:4897
      #7  0x0000558c9c1acbf2 in JOIN::exec_inner (this=0x7fa32c011de0) at /data/src/10.5/sql/sql_select.cc:4348
      #8  0x0000558c9c1ad209 in JOIN::exec (this=this@entry=0x7fa32c011de0) at /data/src/10.5/sql/sql_select.cc:4249
      #9  0x0000558c9c1ab19a in mysql_select (thd=0x7fa32c000c58, tables=0x0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=<optimized out>, result=0x7fa32c011ce0, unit=0x7fa32c004c48, select_lex=0x7fa32c010d90) at /data/src/10.5/sql/sql_select.cc:4725
      #10 0x0000558c9c1abb77 in handle_select (thd=thd@entry=0x7fa32c000c58, lex=lex@entry=0x7fa32c004b80, result=result@entry=0x7fa32c011ce0, setup_tables_done_option=setup_tables_done_option@entry=0) at /data/src/10.5/sql/sql_select.cc:419
      #11 0x0000558c9c1e988a in Sql_cmd_create_table_like::execute (this=<optimized out>, thd=0x7fa32c000c58) at /data/src/10.5/sql/sql_table.cc:12100
      #12 0x0000558c9c1456f6 in mysql_execute_command (thd=0x7fa32c000c58) at /data/src/10.5/sql/sql_parse.cc:6049
      #13 0x0000558c9c1350ef in mysql_parse (thd=0x7fa32c000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.5/sql/sql_parse.cc:8093
      #14 0x0000558c9c14194f in dispatch_command (command=COM_QUERY, thd=0x7fa32c000c58, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.5/sql/sql_class.h:1270
      #15 0x0000558c9c143d27 in do_command (thd=0x7fa32c000c58) at /data/src/10.5/sql/sql_parse.cc:1370
      #16 0x0000558c9c248f01 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x558c9eb9cf48, put_in_cache=put_in_cache@entry=true) at /data/src/10.5/sql/sql_connect.cc:1410
      #17 0x0000558c9c24937d in handle_one_connection (arg=arg@entry=0x558c9eb9cf48) at /data/src/10.5/sql/sql_connect.cc:1312
      #18 0x0000558c9c5d2ca6 in pfs_spawn_thread (arg=0x558c9eb33ba8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #19 0x00007fa37023e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #20 0x00007fa36fe2d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 9 (Thread 0x7fa36903a700 (LWP 742710)):
      #0  __lll_lock_wait (futex=futex@entry=0x558c9d2bd150 <mysql_bin_log+1200>, private=0) at lowlevellock.c:52
      #1  0x00007fa370241235 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x558c9d2bd150 <mysql_bin_log+1200>) at ../nptl/pthread_mutex_lock.c:135
      #2  0x0000558c9c456ec3 in inline_mysql_mutex_lock (src_file=0x558c9cbd825c "/data/src/10.5/sql/log.cc", src_line=10058, that=0x558c9d2bd150 <mysql_bin_log+1200>) at /data/src/10.5/include/mysql/psi/mysql_thread.h:752
      #3  MYSQL_BIN_LOG::mark_xids_active (this=this@entry=0x558c9d2bcca0 <mysql_bin_log>, binlog_id=binlog_id@entry=2662, xid_count=xid_count@entry=1) at /data/src/10.5/sql/log.cc:10058
      #4  0x0000558c9c45ad98 in MYSQL_BIN_LOG::rotate (force_rotate=<optimized out>, check_purge=0x7fa369037b4f, this=0x558c9d2bcca0 <mysql_bin_log>) at /data/src/10.5/sql/log.cc:6998
      #5  MYSQL_BIN_LOG::rotate (this=0x558c9d2bcca0 <mysql_bin_log>, force_rotate=<optimized out>, check_purge=0x7fa369037b4f) at /data/src/10.5/sql/log.cc:6961
      #6  0x0000558c9c45f590 in MYSQL_BIN_LOG::rotate_and_purge (this=this@entry=0x558c9d2bcca0 <mysql_bin_log>, force_rotate=force_rotate@entry=true, domain_drop_lex=0x0) at /data/src/10.5/sql/log.cc:7196
      #7  0x0000558c9c266b20 in reload_acl_and_cache (thd=thd@entry=0x7fa330000c58, options=16130, tables=tables@entry=0x0, write_to_binlog=write_to_binlog@entry=0x7fa369037dc0) at /data/src/10.5/sql/sql_reload.cc:154
      #8  0x0000558c9c146293 in mysql_execute_command (thd=0x7fa330000c58) at /data/src/10.5/sql/sql_parse.cc:5515
      #9  0x0000558c9c09a209 in sp_instr_stmt::exec_core (this=0x7fa330018120, thd=<optimized out>, nextp=0x7fa3690385c4) at /data/src/10.5/sql/sp_head.cc:3768
      #10 0x0000558c9c0a3135 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fa330018168, thd=0x7fa330000c58, nextp=0x7fa3690385c4, open_tables=<optimized out>, instr=0x7fa330018120) at /data/src/10.5/sql/sp_head.cc:3495
      #11 0x0000558c9c0a3b51 in sp_instr_stmt::execute (this=0x7fa330018120, thd=0x7fa330000c58, nextp=0x7fa3690385c4) at /data/src/10.5/sql/sp_head.cc:3674
      #12 0x0000558c9c09da9c in sp_head::execute (this=0x7fa3300175a0, thd=0x7fa330000c58, merge_da_on_success=true) at /data/src/10.5/sql/sp_head.cc:1437
      #13 0x0000558c9c09f16a in sp_head::execute_procedure (this=0x7fa3300175a0, thd=thd@entry=0x7fa330000c58, args=0x7fa330005b28) at /data/src/10.5/sql/sp_head.cc:2449
      #14 0x0000558c9c13a4c7 in do_execute_sp (thd=thd@entry=0x7fa330000c58, sp=<optimized out>) at /data/src/10.5/sql/sql_parse.cc:3088
      #15 0x0000558c9c146c6d in mysql_execute_command (thd=0x7fa330000c58) at /data/src/10.5/sql/sql_parse.cc:5774
      #16 0x0000558c9c1350ef in mysql_parse (thd=0x7fa330000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.5/sql/sql_parse.cc:8093
      #17 0x0000558c9c14194f in dispatch_command (command=COM_QUERY, thd=0x7fa330000c58, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.5/sql/sql_class.h:1270
      #18 0x0000558c9c143d27 in do_command (thd=0x7fa330000c58) at /data/src/10.5/sql/sql_parse.cc:1370
      #19 0x0000558c9c248f01 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x558c9eba4ff8, put_in_cache=put_in_cache@entry=true) at /data/src/10.5/sql/sql_connect.cc:1410
      #20 0x0000558c9c24937d in handle_one_connection (arg=arg@entry=0x558c9eba4ff8) at /data/src/10.5/sql/sql_connect.cc:1312
      #21 0x0000558c9c5d2ca6 in pfs_spawn_thread (arg=0x558c9eb33ef8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #22 0x00007fa37023e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #23 0x00007fa36fe2d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: