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

innodb.innodb-lock-inherit-read_commited fails with timeout

Details

    Description

      According to cross-reference, this test fails rather often on buildbot.

      First occurence, according to cross-reference was 2023-12-07 05:58:09
      Typical 10.5 error - "timeout after 900 seconds", ánd in 10.6 error "debug sync point timeout"

      Example of failing build https://buildbot.mariadb.net/buildbot/builders/kvm-fulltest2-protocols/builds/1305

      Sample output from failure

      innodb.innodb-lock-inherit-read_commited 'innodb' w2 [ fail ]  timeout after 900 seconds
              Test ended at 2023-12-19 15:42:20
       
      Test case timeout after 900 seconds
       
      == /mnt/buildbot/build/mariadb-10.5.24/mysql-test/var/2/log/innodb-lock-inherit-read_commited.log == 
      con1_locks_done WAIT_FOR con1_go';
      SET debug_sync = 'ha_commit_trans_after_acquire_commit_lock SIGNAL
      con1_insert_done WAIT_FOR con1_finish';
      REPLACE INTO t1 VALUES (1,2);
      connect con2,localhost,root,,;
      SET debug_sync = 'now WAIT_FOR con1_locks_done';
      SET debug_sync = 'lock_wait_suspend_thread_enter SIGNAL con2_blocked
      WAIT_FOR con2_go';
      SET debug_sync = 'ha_commit_trans_after_acquire_commit_lock
      WAIT_FOR con2_finish';
      SET debug_sync = 'ib_after_row_insert SIGNAL con2_insert_done';
      REPLACE INTO t1 VALUES (1,3);
      connection default;
      SET debug_sync = 'now WAIT_FOR con2_blocked';
      connection purge_control;
      COMMIT;
      disconnect purge_control;
      connection default;
      InnoDB		0 transactions not purged
      SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done';
       
       
       - saving '/mnt/buildbot/build/mariadb-10.5.24/mysql-test/var/2/log/innodb.innodb-lock-inherit-read_commited-innodb/' to '/mnt/buildbot/build/mariadb-10.5.24/mysql-test/var/log/innodb.innodb-lock-inherit-read_commited-innodb/'
       
      Retrying test innodb.innodb-lock-inherit-read_commited, attempt(2/3)...
      
      

      Attachments

        Activity

          monty Michael Widenius added a comment - - edited

          Here is the stack trace for when this happens. (This happend on my on latest 10.5 branch on amd64-debian-11-debug-ps-embedded):

          [Thread debugging using libthread_db enabled]
          Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
          Core was generated by `/home/buildbot/amd64-debian-11-debug-ps-embedded/build/libmysqld/examples/mysql'.
          Program terminated with signal SIGABRT, Aborted.
          #0  0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
          [Current thread is 1 (Thread 0x7f8c19ce78c0 (LWP 105816))]
          #0  0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
          #1  0x000055c397998bba in my_write_core (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/stacktrace.c:424
          #2  0x000055c39790471a in signal_handler (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9841
          #3  <signal handler called>
          #4  0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          #5  0x000055c3978f36ae in wait_query_thread_done (con=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1005
          #6  0x000055c3978f3899 in do_read_query_result (cn=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1046
          #7  0x000055c397901586 in run_query_normal (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", query_len=63, ds=0x55c3992420a0 <ds_res>, ds_warnings=0x7ffd28ba56d0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:8125
          #8  0x000055c397903d10 in run_query (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9491
          #9  0x000055c3979059ad in main (argc=36, argv=0x7ffd28ba5a98) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:10334
          Thread 9 (Thread 0x7f8c181b6700 (LWP 105922)):
          #0  0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c3978f3391 in connection_thread (arg=0x55c39b3980f8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:952
                  cn = 0x55c39b3980f8
                  __PRETTY_FUNCTION__ = "void* connection_thread(void*)"
          #2  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #3  0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 8 (Thread 0x7f8c1816c700 (LWP 105923)):
          #0  0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c3978f3391 in connection_thread (arg=0x55c39b398208) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:952
                  cn = 0x55c39b398208
                  __PRETTY_FUNCTION__ = "void* connection_thread(void*)"
          #2  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #3  0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 7 (Thread 0x7f8c1824a700 (LWP 105890)):
          #0  0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c397993c84 in safe_cond_timedwait (cond=0x55c3992b9b60 <debug_sync_global+32>, mp=0x55c3992b9b98 <debug_sync_global+88>, abstime=0x7f8c18248af0, file=0x55c3987f70b0 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541
                  error = 0
                  save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105890, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with no waiters, Owner ID = 105890, Robust = No, Shared = No, Protocol = None}, file = 0x55c3987f7870 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc", name = 0x55c3987f78ba "debug_sync_global.ds_mutex", line = 1408, count = 0, create_flags = 0, active_flags = 0, id = 45, thread = 140239677204224, locked_mutex = 0x55c39b6f9118, used_mutex = 0x55c39b6f9190, prev = 0x0, next = 0x0}
          #2  0x000055c397c26513 in inline_mysql_cond_timedwait (that=0x55c3992b9b60 <debug_sync_global+32>, mutex=0x55c3992b9b98 <debug_sync_global+88>, abstime=0x7f8c18248af0, src_file=0x55c3987f7870 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc", src_line=1472) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270
                  result = 0
          #3  0x000055c397c2907e in debug_sync_execute (thd=0x55c39b6f2798, action=0x7f8be8034ca8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1472
                  old_mutex = 0x0
                  old_cond = 0x0
                  abstime = {tv_sec = 1727807282, tv_nsec = 471839000}
                  restore_current_mutex = true
                  error = 0
                  old_proc_info = 0x0
                  __PRETTY_FUNCTION__ = "void debug_sync_execute(THD*, st_debug_sync_action*)"
          #4  0x000055c397c294ff in debug_sync (thd=0x55c39b6f2798, sync_point_name=0x55c3987f7d88 "now", name_len=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1580
                  ds_control = 0x55c39b6fb828
                  action = 0x7f8be8034ca8
                  __PRETTY_FUNCTION__ = "void debug_sync(THD*, const char*, size_t)"
          #5  0x000055c397c27deb in debug_sync_set_action (thd=0x55c39b6f2798, action=0x7f8be8034ca8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:809
                  ds_control = 0x55c39b6fb828
                  is_dsp_now = true
                  __PRETTY_FUNCTION__ = "bool debug_sync_set_action(THD*, st_debug_sync_action*)"
          #6  0x000055c397c28a4a in debug_sync_eval_action (thd=0x55c39b6f2798, action_str=0x55c39b763ae0 "now", action_end=0x55c39b763b0c "") at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1255
                  action = 0x7f8be8034ca8
                  errmsg = 0x55c39b6f7cc8 ""
                  ptr = 0x0
                  token = 0x55c39b763afc "con2_insert_done"
                  token_length = 16
                  __PRETTY_FUNCTION__ = "bool debug_sync_eval_action(THD*, char*, char*)"
          #7  0x000055c397c28b16 in debug_sync_update (thd=0x55c39b6f2798, val_str=0x55c39b763ae0 "now", len=44) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1291
                  __PRETTY_FUNCTION__ = "bool debug_sync_update(THD*, char*, size_t)"
          #8  0x000055c397afbad1 in Sys_var_debug_sync::session_update (this=0x55c3992a5fe0 <Sys_debug_sync>, thd=0x55c39b6f2798, var=0x55c39b763a90) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sys_vars.inl:1778
          No locals.
          #9  0x000055c397d1a828 in sys_var::update (this=0x55c3992a5fe0 <Sys_debug_sync>, thd=0x55c39b6f2798, var=0x55c39b763a90) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:212
                  ret = 60
                  type = SHOW_OPT_SESSION
          #10 0x000055c397d1c696 in set_var::update (this=0x55c39b763a90, thd=0x55c39b6f2798) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:859
          No locals.
          #11 0x000055c397d1c250 in sql_set_variables (thd=0x55c39b6f2798, var_list=0x55c39b6f7710, free=true) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:746
                  error = 0
                  was_error = false
                  it = {<base_list_iterator> = {list = 0x55c39b6f7710, el = 0x55c39b763ad0, prev = 0x0, current = 0x0}, <No data fields>}
                  var = 0x55c39b763a90
          #12 0x000055c397c53ff5 in mysql_execute_command (thd=0x55c39b6f2798) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:5172
                  lex_var_list = 0x55c39b6f7710
                  res = 0
                  up_result = 0
                  lex = 0x55c39b6f66a0
                  select_lex = 0x55c39b6f6fa0
                  first_table = 0x0
                  all_tables = 0x0
                  unit = 0x55c39b6f6768
                  __PRETTY_FUNCTION__ = "int mysql_execute_command(THD*)"
                  ots = {ctx = 0x55c39b6f63a8, traceable = false}
                  trace_command = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x55c398f1b718 <vtable for Json_writer_object+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>}
                  trace_command_steps = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x55c398f1b6f8 <vtable for Json_writer_array+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>}
                  orig_binlog_format = BINLOG_FORMAT_MIXED
                  orig_current_stmt_binlog_format = BINLOG_FORMAT_STMT
          #13 0x000055c397c598c2 in mysql_parse (thd=0x55c39b6f2798, rawbuf=0x55c39b763850 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", length=63, parser_state=0x7f8c18249400, is_com_multi=false, is_next_command=false) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:8237
                  found_semicolon = 0x0
                  error = 21955
                  lex = 0x55c39b6f66a0
                  err = false
                  __PRETTY_FUNCTION__ = "void mysql_parse(THD*, char*, uint, Parser_state*, bool, bool)"
          #14 0x000055c397c4c511 in dispatch_command (command=COM_QUERY, thd=0x55c39b6f2798, packet=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", packet_length=63, is_com_multi=false, is_next_command=false) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:1891
                  packet_end = 0x55c39b76388f ""
                  parser_state = {m_lip = {lookahead_token = -1, lookahead_yylval = 0x0, m_thd = 0x55c39b6f2798, m_ptr = 0x55c39b763890 "\004", m_tok_start = 0x55c39b763890 "\004", m_tok_end = 0x55c39b763890 "\004", m_end_of_query = 0x55c39b76388f "", m_tok_start_prev = 0x55c39b76388f "", m_buf = 0x55c39b763850 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_buf_length = 63, m_echo = true, m_echo_saved = false, m_cpp_buf = 0x55c39b7638e8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_cpp_ptr = 0x55c39b763927 "", m_cpp_tok_start = 0x55c39b763927 "", m_cpp_tok_start_prev = 0x55c39b763927 "", m_cpp_tok_end = 0x55c39b763927 "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x4 <error: Cannot access memory at address 0x4>, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, found_semicolon = 0x0, ignore_space = false, stmt_prepare_mode = false, multi_statements = true, yylineno = 1, m_digest = 0x0, in_comment = NO_COMMENT, in_comment_saved = NO_COMMENT, m_cpp_text_start = 0x55c39b7638fa "now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_cpp_text_end = 0x55c39b763926 "'", m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 12 times>}}, m_lock_type = TL_READ_DEFAULT, m_mdl_type = MDL_SHARED_READ}, m_digest_psi = 0x0}
                  net = 0x55c39b6f2b18
                  error = false
                  do_end_of_statement = true
                  drop_more_results = false
                  __PRETTY_FUNCTION__ = "bool dispatch_command(enum_server_command, THD*, char*, uint, bool, bool)"
                  res = <optimized out>
          #15 0x000055c397927c19 in emb_advanced_command (mysql=0x55c39b79ee38, command=COM_QUERY, header=0x0, header_length=0, arg=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", arg_length=63, skip_check=1 '\001', stmt=0x0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/libmysqld/lib_sql.cc:171
                  result = 1 '\001'
                  thd = 0x55c39b6f2798
                  net = 0x55c39b79ee38
                  stmt_skip = 0 '\000'
          #16 0x000055c397915fee in mysql_send_query (mysql=0x55c39b79ee38, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", length=63) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql-common/client.c:3615
          No locals.
          #17 0x000055c3978f33f9 in connection_thread (arg=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:961
                  cn = 0x55c39b397ed8
                  __PRETTY_FUNCTION__ = "void* connection_thread(void*)"
          #18 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #19 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 6 (Thread 0x7f8be57fa700 (LWP 105919)):
          #0  0x00007f8c19ed0df8 in pthread_cond_clockwait () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c398606cc4 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __atime=@0x7f8be57f9ba8: {__d = {__r = 26726073497303150}}) at /usr/include/c++/10/condition_variable:209
                  __s = {__d = {__r = 26726073}}
                  __ns = {__r = 497303150}
                  __ts = {tv_sec = 26726073, tv_nsec = 497303150}
          #2  0x000055c398605e13 in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __atime=@0x7f8be57f9ba8: {__d = {__r = 26726073497303150}}) at /usr/include/c++/10/condition_variable:119
          No locals.
          #3  0x000055c39860518e in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __rtime=@0x55c39b4b1780: {__r = 60000}) at /usr/include/c++/10/condition_variable:172
                  __reltime = {__r = 60000000000}
          #4  0x000055c398602797 in tpool::thread_pool_generic::wait_for_tasks (this=0x55c39b4b15e0, lk=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, thread_data=0x55c39b4b2170) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:499
                  __PRETTY_FUNCTION__ = "bool tpool::thread_pool_generic::wait_for_tasks(std::unique_lock<std::mutex>&, tpool::worker_data*)"
          #5  0x000055c3986029a3 in tpool::thread_pool_generic::get_task (this=0x55c39b4b15e0, thread_var=0x55c39b4b2170, t=0x7f8be57f9c58) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:552
                  lk = {_M_device = 0x55c39b4b1758, _M_owns = true}
                  __PRETTY_FUNCTION__ = "bool tpool::thread_pool_generic::get_task(tpool::worker_data*, tpool::task**)"
          #6  0x000055c398602c29 in tpool::thread_pool_generic::worker_main (this=0x55c39b4b15e0, thread_var=0x55c39b4b2170) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:597
                  task = 0x55c39b69e3a0
          #7  0x000055c39860a6a0 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7f8bf8001a78: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55c398602bc8 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7f8bf8001a70: 0x55c39b4b15e0) at /usr/include/c++/10/bits/invoke.h:73
          No locals.
          #8  0x000055c39860a590 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7f8bf8001a78: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55c398602bc8 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/10/bits/invoke.h:95
          No locals.
          #9  0x000055c39860a4c3 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7f8bf8001a68) at /usr/include/c++/10/thread:264
          No locals.
          #10 0x000055c39860a460 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7f8bf8001a68) at /usr/include/c++/10/thread:271
          No locals.
          #11 0x000055c39860a444 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7f8bf8001a60) at /usr/include/c++/10/thread:215
          No locals.
          #12 0x00007f8c1a110ed0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
          No symbol table info available.
          #13 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #14 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 5 (Thread 0x7f8c12ffe700 (LWP 105879)):
          #0  0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c3979938c6 in safe_cond_wait (cond=0x55c399235f00 <buf_pool+1088>, mp=0x55c399235e00 <buf_pool+832>, file=0x55c398a7dda8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc", line=2315) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:487
                  error = 21955
                  save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105879, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with no waiters, Owner ID = 105879, Robust = No, Shared = No, Protocol = None}, file = 0x55c398a7dda8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc", name = 0x55c398a88a2b "flush_list_mutex", line = 2364, count = 0, create_flags = 0, active_flags = 0, id = 18, thread = 140239590909696, locked_mutex = 0x55c39b6488c8, used_mutex = 0x55c39b648940, prev = 0x0, next = 0x0}
          #2  0x000055c3982425b3 in buf_flush_page_cleaner () at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc:2315
                  soft_lsn_limit = 0
                  oldest_lsn = 47807
                  dirty_blocks = 32
                  dirty_pct = 6.4000000000000004
                  pct_lwm = 0
                  n_flushed = 0
                  n = 0
                  __PRETTY_FUNCTION__ = "void* buf_flush_page_cleaner(void*)"
                  last_pages = 0
                  abstime = {tv_sec = 1727806384, tv_nsec = 216928000}
                  lsn_limit = 0
                  last_activity_count = 0
          #3  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #4  0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 4 (Thread 0x7f8c1905d700 (LWP 105841)):
          #0  0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c397993c84 in safe_cond_timedwait (cond=0x55c3992c50e0 <COND_checkpoint>, mp=0x55c3992c5020 <LOCK_checkpoint>, abstime=0x7f8c1905cce0, file=0x55c398a031b0 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541
                  error = 32765
                  save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105841, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Normal, Status = Acquired, possibly with no waiters, Owner ID = 105841, Robust = No, Shared = No, Protocol = None}, file = 0x55c398a03208 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c", name = 0x55c398a03260 "control->LOCK_control", line = 99, count = 0, create_flags = 0, active_flags = 0, id = 15, thread = 140239691962112, locked_mutex = 0x7f8c0c000ff8, used_mutex = 0x7f8c0c001070, prev = 0x0, next = 0x0}
          #2  0x000055c398100c33 in inline_mysql_cond_timedwait (that=0x55c3992c50e0 <COND_checkpoint>, mutex=0x55c3992c5020 <LOCK_checkpoint>, abstime=0x7f8c1905cce0, src_file=0x55c398a03208 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c", src_line=115) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270
                  result = 0
          #3  0x000055c398100f02 in my_service_thread_sleep (control=0x55c399227ae0 <checkpoint_control>, sleep_time=30000000000) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c:115
                  abstime = {tv_sec = 1727807311, tv_nsec = 55122000}
                  res = 0 '\000'
          #4  0x000055c397f7c64b in ma_checkpoint_background (arg=0x1e) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_checkpoint.c:725
                  interval = 30
                  sleeps = 900
                  sleep_time = 30
                  log_horizon_at_last_checkpoint = 4295005134
                  pagecache_flushes_at_last_checkpoint = 0
                  pages_bunch_size = 0
                  filter_param = {up_to_lsn = 4295005090, max_pages = 0}
                  dfile = 0x0
                  kfile = 0x0
                  __PRETTY_FUNCTION__ = "ma_checkpoint_background"
          #5  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #6  0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 3 (Thread 0x7f8c19bd6700 (LWP 105833)):
          #0  0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c397993c84 in safe_cond_timedwait (cond=0x55c39928c3c0 <COND_timer>, mp=0x55c39928c300 <LOCK_timer>, abstime=0x7f8c19bd5d60, file=0x55c398656490 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541
                  error = 0
                  save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105833, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with waiters, Owner ID = 105833, Robust = No, Shared = No, Protocol = None}, file = 0x55c398656490 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", name = 0x55c398656532 "LOCK_timer", line = 1270, count = 0, create_flags = 0, active_flags = 0, id = 9, thread = 140239703992064, locked_mutex = 0x7f8c14000ff8, used_mutex = 0x7f8c14001070, prev = 0x0, next = 0x0}
          #2  0x000055c397991e34 in inline_mysql_cond_timedwait (that=0x55c39928c3c0 <COND_timer>, mutex=0x55c39928c300 <LOCK_timer>, abstime=0x7f8c19bd5d60, src_file=0x55c3986564e8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_timer.c", src_line=321) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270
                  result = 32652
          #3  0x000055c397992877 in timer_handler (arg=0x0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_timer.c:321
                  error = 110
                  top_time = 0x55c39b4b1858
                  now = {tv_sec = 1727807282, tv_nsec = 268484000}
                  abstime = {tv_sec = 1727807282, tv_nsec = 497387000}
          #4  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #5  0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 2 (Thread 0x7f8c13fff700 (LWP 105874)):
          #0  0x00007f8c19de0fc9 in syscall () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          #1  0x000055c39860b164 in my_getevents (ctx=0x7f8c1844b000, min_nr=1, nr=256, ev=0x7f8c13ffcc80) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/aio_linux.cc:64
                  saved_errno = 0
                  ret = -1738493207
          #2  0x000055c39860b32c in tpool::aio_linux::getevent_thread_routine (aio=0x55c39b4fa5b0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/aio_linux.cc:108
                  ret = 5
                  MAX_EVENTS = 256
                  events = {{data = 0x0, obj = 0x55c39b51a310, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a3d0, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a490, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a550, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a610, res = 16384, res2 = 0}, {data = 0x0, obj = 0x0, res = 0, res2 = 0} <repeats 249 times>, {data = 0x0, obj = 0x0, res = 0, res2 = 94298612800400}, {data = 0x7f8c13ffec80, obj = 0x55c39860bce9 <std::_Tuple_impl<0ul, void (*)(tpool::aio_linux*), tpool::aio_linux*>::_M_head(std::_Tuple_impl<0ul, void (*)(tpool::aio_linux*), tpool::aio_linux*>&)+28>, res = 0, res2 = 94298612800392}}
          #3  0x000055c39860bc92 in std::__invoke_impl<void, void (*)(tpool::aio_linux*), tpool::aio_linux*> (__f=@0x55c39b519b90: 0x55c39860b2e9 <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>) at /usr/include/c++/10/bits/invoke.h:60
          No locals.
          #4  0x000055c39860bbf9 in std::__invoke<void (*)(tpool::aio_linux*), tpool::aio_linux*> (__fn=@0x55c39b519b90: 0x55c39860b2e9 <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>) at /usr/include/c++/10/bits/invoke.h:95
          No locals.
          #5  0x000055c39860bb69 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::_M_invoke<0ul, 1ul> (this=0x55c39b519b88) at /usr/include/c++/10/thread:264
          No locals.
          #6  0x000055c39860bb22 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::operator() (this=0x55c39b519b88) at /usr/include/c++/10/thread:271
          No locals.
          #7  0x000055c39860bb06 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> > >::_M_run (this=0x55c39b519b80) at /usr/include/c++/10/thread:215
          No locals.
          #8  0x00007f8c1a110ed0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
          No symbol table info available.
          #9  0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #10 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6
          No symbol table info available.
          Thread 1 (Thread 0x7f8c19ce78c0 (LWP 105816)):
          #0  0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #1  0x000055c397998bba in my_write_core (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/stacktrace.c:424
          No locals.
          #2  0x000055c39790471a in signal_handler (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9841
          No locals.
          #3  <signal handler called>
          No symbol table info available.
          #4  0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
          No symbol table info available.
          #5  0x000055c3978f36ae in wait_query_thread_done (con=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1005
                  __PRETTY_FUNCTION__ = "void wait_query_thread_done(st_connection*)"
          #6  0x000055c3978f3899 in do_read_query_result (cn=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1046
                  __PRETTY_FUNCTION__ = "int do_read_query_result(st_connection*)"
          #7  0x000055c397901586 in run_query_normal (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", query_len=63, ds=0x55c3992420a0 <ds_res>, ds_warnings=0x7ffd28ba56d0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:8125
                  res = 0x0
                  mysql = 0x55c39b79ee38
                  err = 0
                  counter = 0
                  __PRETTY_FUNCTION__ = "void run_query_normal(st_connection*, st_command*, int, const char*, size_t, DYNAMIC_STRING*, DYNAMIC_STRING*)"
          #8  0x000055c397903d10 in run_query (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9491
                  mysql = 0x55c39b79ee38
                  rs_output = 0x55c3992420a0 <ds_res>
                  rs_cmp_result = {str = 0x7ffd28ba56f0 " W\272(\375\177", length = 94298550368509, max_length = 94298611144168, alloc_increment = 6903295466}
                  rs_unsorted = {str = 0x7ffd28ba5720 "\240Y\272(\375\177", length = 94298549797658, max_length = 94298615249128, alloc_increment = 94298615249128}
                  rs_sorted_save = 0x0
                  rs_warnings = {str = 0x55c39b7f0c28 '\245' <repeats 200 times>..., length = 0, max_length = 256, alloc_increment = 256}
                  query = 0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'"
                  query_len = 63
                  view_created = 0 '\000'
                  sp_created = 0 '\000'
                  complete_query = 1 '\001'
          #9  0x000055c3979059ad in main (argc=36, argv=0x7ffd28ba5a98) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:10334
                  old_display_result_vertically = 0 '\000'
                  flags = 3
                  ok_to_do = 1 '\001'
                  current_line_inc = 1
                  processed = 1
                  command = 0x55c39b76f8e8
                  q_send_flag = 0 '\000'
                  abort_flag = 0 '\000'
                  command_executed = 28
                  last_command_executed = 28
                  save_file = "\000W\272(\375\177\000\000\245\071\327\227\303U\000\000\000\000\000\000\000\000\000\000\320X\272(\375\177\000\000\214\326\272\230\303U\000\000\340X\272(\375\177\000\000\320W\272(\375\177\000\000]i\327\227\303U\000\000\020X\272(\375\177\000\000\340X\272(\375\177\000\000\360W\272(\375\177\000\000\000\000\000\000\000\000\000\000 X\272(\375\177\000\000\255V\263\227\303U\000\000\020X\272(\375\177", '\000' <repeats 18 times>, "\200X\272(\375\177\000\000\000\000\000\000\000\000\000\000\360X\272(\375\177\000\000`X\272(\375\177\000\000>X\263\227\303U\000\000\240s)\231\303U", '\000' <repeats 18 times>...
                  empty_result = false
                  error = 0
                  con = 0x55c39b397ed8
          

          The test aborts because the "con2_insert_done" debug sync signal is not
          delivered (or delivered too early and missed) to thread 7 executing:
          now SIGNAL con2_go WAIT_FOR con2_insert_done

          However the stack trace shows that there is no thread waiting for con2_go.

          I was able to repeat the hang with:

          while ./mtr --rr=-h --parallel=auto --embedded --ps innodb.innodb-lock-inherit-read_commited{,,,,,,,,,}; do :; done
          

          Here follows a quick analyze regarding this:

          I put a break on debug_sync_execute() to see what sync points was
          executed and in which order. The result are:

          • row_ins_sec_index_entry_dup_locks_created signal con1_locks_done wait for con1_go
          • now wait for con1_locks_done
          • now wait for con2_blocked
          • lock_wait_suspend_thread_enter signal con2_blocked wait for con2_go

          And after that the threads was blocked for a long time (probably waiting for
          a timeout) until I got:

          • ha_commit_trans_after_acquire_commit_lock signal con1_insert_done wait for con1_finish
          • ib_after_row_insert signal con2_insert_done

          And after that no more debug_sync_execute calls.

          I assume this means that there was nothing waiting for con1_insert_done.

          I looked what the threads was waiting for:

          Thread 22: Waiting for con1_finish
          Thread 13: Signaling con2_insert_done (no wait)

          No other threads was waiting for debug syncs!
          I would have expected a thread waiting for con1_go, but could not find it.

          I checked and the thread waiting for the con1_go signal got a timeout in
          debug_sync wait and continued executing. After this things started to
          fall appart.

          At the point of the timeout on con1_go we had the following active threads:

          Thread 1: Waiting on "SET GLOBAL innodb_max_purge_lag_wait= 0"
          Thread 2: timeout
          Thread 10: Waiting on SET GLOBAL innodb_max_purge_lag_wait= 0
          Thread 12: wait for con2_go

          No other threads waiting in debug sync

          The stack trace fore the SET GLOBAL is:

          Thread 1:
          #9  0x0000275b754bc712 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
          #10 0x000000000075b815 in wait_query_thread_done (con=0x2cc5468)
              at /my/maria-10.5/client/mysqltest.cc:1005
          #11 0x000000000075ba84 in do_read_query_result (cn=0x2cc5468)
              at /my/maria-10.5/client/mysqltest.cc:1046
          #12 0x000000000076bdc1 in run_query_normal (cn=0x2cc5468, command=0x3a75dc98118, 
              flags=3, query=0x3a75dcdb688 "SET GLOBAL innodb_max_purge_lag_wait= 0", 
              query_len=39, ds=0x23a6be0 <ds_res>, ds_warnings=0x7fffffff96b0)
           
          Thread 11:
          #0  0x000036437e175121 in clock_nanosleep@GLIBC_2.2.5 () from /lib64/libc.so.6
          #1  0x000036437e17ae43 in nanosleep () from /lib64/libc.so.6
          #2  0x00000000014fa9b5 in os_thread_sleep (tm=100000)
              at /my/maria-10.5/storage/innobase/os/os0thread.cc:122
          #3  0x0000000001136705 in innodb_max_purge_lag_wait_update (thd=0x3a75dc61898, 
              limit=0x57b38036658) at /my/maria-10.5/storage/innobase/handler/ha_innodb.cc:241
          #4  0x0000000000b62cfa in sys_var_pluginvar::global_update (this=0x2dd5230, 
              thd=0x3a75dc61898, var=0x57b38036630) at /my/maria-10.5/sql/sql_plugin.cc:3674
          #5  0x0000000000c6075b in sys_var::update (this=0x2dd5230, thd=0x3a75dc61898, 
              var=0x57b38036630) at /my/maria-10.5/sql/set_var.cc:207
          #6  0x0000000000c625fa in set_var::update (this=0x57b38036630, thd=0x3a75dc61898)
              at /my/maria-10.5/sql/set_var.cc:859
          #7  0x0000000000c6217d in sql_set_variables (thd=0x3a75dc61898, var_list=0x3a75dc66918, 
              free=true) at /my/maria-10.5/sql/set_var.cc:746
          #8  0x0000000000b8521e in mysql_execute_command (thd=0x3a75dc61898)
              at /my/maria-10.5/sql/sql_parse.cc:5172
          #9  0x0000000000b8ab7b in mysql_parse (thd=0x3a75dc61898, 
              rawbuf=0x57b38038af0 "SET GLOBAL innodb_max_purge_lag_wait= 0", length=39, 
              parser_state=0x68ec565952f0, is_com_multi=false, is_next_command=false)
              at /my/maria-10.5/sql/sql_parse.cc:8237
          

          Conclusion is that SET GLOBAL innodb_max_purge_lag_wait= 0 takes more than
          300 seconds and because of that we get a timeout on debug sync.

          One possible reason may be that there are two identical queries running at the same time and causing a conflict.

          monty Michael Widenius added a comment - - edited Here is the stack trace for when this happens. (This happend on my on latest 10.5 branch on amd64-debian-11-debug-ps-embedded): [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by `/home/buildbot/amd64-debian-11-debug-ps-embedded/build/libmysqld/examples/mysql'. Program terminated with signal SIGABRT, Aborted. #0 0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0 [Current thread is 1 (Thread 0x7f8c19ce78c0 (LWP 105816))] #0 0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x000055c397998bba in my_write_core (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/stacktrace.c:424 #2 0x000055c39790471a in signal_handler (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9841 #3 <signal handler called> #4 0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 #5 0x000055c3978f36ae in wait_query_thread_done (con=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1005 #6 0x000055c3978f3899 in do_read_query_result (cn=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1046 #7 0x000055c397901586 in run_query_normal (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", query_len=63, ds=0x55c3992420a0 <ds_res>, ds_warnings=0x7ffd28ba56d0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:8125 #8 0x000055c397903d10 in run_query (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9491 #9 0x000055c3979059ad in main (argc=36, argv=0x7ffd28ba5a98) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:10334 Thread 9 (Thread 0x7f8c181b6700 (LWP 105922)): #0 0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c3978f3391 in connection_thread (arg=0x55c39b3980f8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:952 cn = 0x55c39b3980f8 __PRETTY_FUNCTION__ = "void* connection_thread(void*)" #2 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #3 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 8 (Thread 0x7f8c1816c700 (LWP 105923)): #0 0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c3978f3391 in connection_thread (arg=0x55c39b398208) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:952 cn = 0x55c39b398208 __PRETTY_FUNCTION__ = "void* connection_thread(void*)" #2 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #3 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 7 (Thread 0x7f8c1824a700 (LWP 105890)): #0 0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c397993c84 in safe_cond_timedwait (cond=0x55c3992b9b60 <debug_sync_global+32>, mp=0x55c3992b9b98 <debug_sync_global+88>, abstime=0x7f8c18248af0, file=0x55c3987f70b0 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541 error = 0 save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105890, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with no waiters, Owner ID = 105890, Robust = No, Shared = No, Protocol = None}, file = 0x55c3987f7870 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc", name = 0x55c3987f78ba "debug_sync_global.ds_mutex", line = 1408, count = 0, create_flags = 0, active_flags = 0, id = 45, thread = 140239677204224, locked_mutex = 0x55c39b6f9118, used_mutex = 0x55c39b6f9190, prev = 0x0, next = 0x0} #2 0x000055c397c26513 in inline_mysql_cond_timedwait (that=0x55c3992b9b60 <debug_sync_global+32>, mutex=0x55c3992b9b98 <debug_sync_global+88>, abstime=0x7f8c18248af0, src_file=0x55c3987f7870 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc", src_line=1472) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270 result = 0 #3 0x000055c397c2907e in debug_sync_execute (thd=0x55c39b6f2798, action=0x7f8be8034ca8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1472 old_mutex = 0x0 old_cond = 0x0 abstime = {tv_sec = 1727807282, tv_nsec = 471839000} restore_current_mutex = true error = 0 old_proc_info = 0x0 __PRETTY_FUNCTION__ = "void debug_sync_execute(THD*, st_debug_sync_action*)" #4 0x000055c397c294ff in debug_sync (thd=0x55c39b6f2798, sync_point_name=0x55c3987f7d88 "now", name_len=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1580 ds_control = 0x55c39b6fb828 action = 0x7f8be8034ca8 __PRETTY_FUNCTION__ = "void debug_sync(THD*, const char*, size_t)" #5 0x000055c397c27deb in debug_sync_set_action (thd=0x55c39b6f2798, action=0x7f8be8034ca8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:809 ds_control = 0x55c39b6fb828 is_dsp_now = true __PRETTY_FUNCTION__ = "bool debug_sync_set_action(THD*, st_debug_sync_action*)" #6 0x000055c397c28a4a in debug_sync_eval_action (thd=0x55c39b6f2798, action_str=0x55c39b763ae0 "now", action_end=0x55c39b763b0c "") at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1255 action = 0x7f8be8034ca8 errmsg = 0x55c39b6f7cc8 "" ptr = 0x0 token = 0x55c39b763afc "con2_insert_done" token_length = 16 __PRETTY_FUNCTION__ = "bool debug_sync_eval_action(THD*, char*, char*)" #7 0x000055c397c28b16 in debug_sync_update (thd=0x55c39b6f2798, val_str=0x55c39b763ae0 "now", len=44) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/debug_sync.cc:1291 __PRETTY_FUNCTION__ = "bool debug_sync_update(THD*, char*, size_t)" #8 0x000055c397afbad1 in Sys_var_debug_sync::session_update (this=0x55c3992a5fe0 <Sys_debug_sync>, thd=0x55c39b6f2798, var=0x55c39b763a90) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sys_vars.inl:1778 No locals. #9 0x000055c397d1a828 in sys_var::update (this=0x55c3992a5fe0 <Sys_debug_sync>, thd=0x55c39b6f2798, var=0x55c39b763a90) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:212 ret = 60 type = SHOW_OPT_SESSION #10 0x000055c397d1c696 in set_var::update (this=0x55c39b763a90, thd=0x55c39b6f2798) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:859 No locals. #11 0x000055c397d1c250 in sql_set_variables (thd=0x55c39b6f2798, var_list=0x55c39b6f7710, free=true) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/set_var.cc:746 error = 0 was_error = false it = {<base_list_iterator> = {list = 0x55c39b6f7710, el = 0x55c39b763ad0, prev = 0x0, current = 0x0}, <No data fields>} var = 0x55c39b763a90 #12 0x000055c397c53ff5 in mysql_execute_command (thd=0x55c39b6f2798) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:5172 lex_var_list = 0x55c39b6f7710 res = 0 up_result = 0 lex = 0x55c39b6f66a0 select_lex = 0x55c39b6f6fa0 first_table = 0x0 all_tables = 0x0 unit = 0x55c39b6f6768 __PRETTY_FUNCTION__ = "int mysql_execute_command(THD*)" ots = {ctx = 0x55c39b6f63a8, traceable = false} trace_command = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x55c398f1b718 <vtable for Json_writer_object+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>} trace_command_steps = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x55c398f1b6f8 <vtable for Json_writer_array+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>} orig_binlog_format = BINLOG_FORMAT_MIXED orig_current_stmt_binlog_format = BINLOG_FORMAT_STMT #13 0x000055c397c598c2 in mysql_parse (thd=0x55c39b6f2798, rawbuf=0x55c39b763850 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", length=63, parser_state=0x7f8c18249400, is_com_multi=false, is_next_command=false) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:8237 found_semicolon = 0x0 error = 21955 lex = 0x55c39b6f66a0 err = false __PRETTY_FUNCTION__ = "void mysql_parse(THD*, char*, uint, Parser_state*, bool, bool)" #14 0x000055c397c4c511 in dispatch_command (command=COM_QUERY, thd=0x55c39b6f2798, packet=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", packet_length=63, is_com_multi=false, is_next_command=false) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql/sql_parse.cc:1891 packet_end = 0x55c39b76388f "" parser_state = {m_lip = {lookahead_token = -1, lookahead_yylval = 0x0, m_thd = 0x55c39b6f2798, m_ptr = 0x55c39b763890 "\004", m_tok_start = 0x55c39b763890 "\004", m_tok_end = 0x55c39b763890 "\004", m_end_of_query = 0x55c39b76388f "", m_tok_start_prev = 0x55c39b76388f "", m_buf = 0x55c39b763850 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_buf_length = 63, m_echo = true, m_echo_saved = false, m_cpp_buf = 0x55c39b7638e8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_cpp_ptr = 0x55c39b763927 "", m_cpp_tok_start = 0x55c39b763927 "", m_cpp_tok_start_prev = 0x55c39b763927 "", m_cpp_tok_end = 0x55c39b763927 "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x4 <error: Cannot access memory at address 0x4>, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, found_semicolon = 0x0, ignore_space = false, stmt_prepare_mode = false, multi_statements = true, yylineno = 1, m_digest = 0x0, in_comment = NO_COMMENT, in_comment_saved = NO_COMMENT, m_cpp_text_start = 0x55c39b7638fa "now SIGNAL con2_go WAIT_FOR con2_insert_done'", m_cpp_text_end = 0x55c39b763926 "'", m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 12 times>}}, m_lock_type = TL_READ_DEFAULT, m_mdl_type = MDL_SHARED_READ}, m_digest_psi = 0x0} net = 0x55c39b6f2b18 error = false do_end_of_statement = true drop_more_results = false __PRETTY_FUNCTION__ = "bool dispatch_command(enum_server_command, THD*, char*, uint, bool, bool)" res = <optimized out> #15 0x000055c397927c19 in emb_advanced_command (mysql=0x55c39b79ee38, command=COM_QUERY, header=0x0, header_length=0, arg=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", arg_length=63, skip_check=1 '\001', stmt=0x0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/libmysqld/lib_sql.cc:171 result = 1 '\001' thd = 0x55c39b6f2798 net = 0x55c39b79ee38 stmt_skip = 0 '\000' #16 0x000055c397915fee in mysql_send_query (mysql=0x55c39b79ee38, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", length=63) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/sql-common/client.c:3615 No locals. #17 0x000055c3978f33f9 in connection_thread (arg=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:961 cn = 0x55c39b397ed8 __PRETTY_FUNCTION__ = "void* connection_thread(void*)" #18 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #19 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 6 (Thread 0x7f8be57fa700 (LWP 105919)): #0 0x00007f8c19ed0df8 in pthread_cond_clockwait () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c398606cc4 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __atime=@0x7f8be57f9ba8: {__d = {__r = 26726073497303150}}) at /usr/include/c++/10/condition_variable:209 __s = {__d = {__r = 26726073}} __ns = {__r = 497303150} __ts = {tv_sec = 26726073, tv_nsec = 497303150} #2 0x000055c398605e13 in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __atime=@0x7f8be57f9ba8: {__d = {__r = 26726073497303150}}) at /usr/include/c++/10/condition_variable:119 No locals. #3 0x000055c39860518e in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x55c39b4b2170, __lock=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, __rtime=@0x55c39b4b1780: {__r = 60000}) at /usr/include/c++/10/condition_variable:172 __reltime = {__r = 60000000000} #4 0x000055c398602797 in tpool::thread_pool_generic::wait_for_tasks (this=0x55c39b4b15e0, lk=@0x7f8be57f9c10: {_M_device = 0x55c39b4b1758, _M_owns = true}, thread_data=0x55c39b4b2170) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:499 __PRETTY_FUNCTION__ = "bool tpool::thread_pool_generic::wait_for_tasks(std::unique_lock<std::mutex>&, tpool::worker_data*)" #5 0x000055c3986029a3 in tpool::thread_pool_generic::get_task (this=0x55c39b4b15e0, thread_var=0x55c39b4b2170, t=0x7f8be57f9c58) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:552 lk = {_M_device = 0x55c39b4b1758, _M_owns = true} __PRETTY_FUNCTION__ = "bool tpool::thread_pool_generic::get_task(tpool::worker_data*, tpool::task**)" #6 0x000055c398602c29 in tpool::thread_pool_generic::worker_main (this=0x55c39b4b15e0, thread_var=0x55c39b4b2170) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/tpool_generic.cc:597 task = 0x55c39b69e3a0 #7 0x000055c39860a6a0 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7f8bf8001a78: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55c398602bc8 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7f8bf8001a70: 0x55c39b4b15e0) at /usr/include/c++/10/bits/invoke.h:73 No locals. #8 0x000055c39860a590 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7f8bf8001a78: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55c398602bc8 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/10/bits/invoke.h:95 No locals. #9 0x000055c39860a4c3 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7f8bf8001a68) at /usr/include/c++/10/thread:264 No locals. #10 0x000055c39860a460 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7f8bf8001a68) at /usr/include/c++/10/thread:271 No locals. #11 0x000055c39860a444 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7f8bf8001a60) at /usr/include/c++/10/thread:215 No locals. #12 0x00007f8c1a110ed0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 No symbol table info available. #13 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #14 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 5 (Thread 0x7f8c12ffe700 (LWP 105879)): #0 0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c3979938c6 in safe_cond_wait (cond=0x55c399235f00 <buf_pool+1088>, mp=0x55c399235e00 <buf_pool+832>, file=0x55c398a7dda8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc", line=2315) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:487 error = 21955 save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105879, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with no waiters, Owner ID = 105879, Robust = No, Shared = No, Protocol = None}, file = 0x55c398a7dda8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc", name = 0x55c398a88a2b "flush_list_mutex", line = 2364, count = 0, create_flags = 0, active_flags = 0, id = 18, thread = 140239590909696, locked_mutex = 0x55c39b6488c8, used_mutex = 0x55c39b648940, prev = 0x0, next = 0x0} #2 0x000055c3982425b3 in buf_flush_page_cleaner () at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/innobase/buf/buf0flu.cc:2315 soft_lsn_limit = 0 oldest_lsn = 47807 dirty_blocks = 32 dirty_pct = 6.4000000000000004 pct_lwm = 0 n_flushed = 0 n = 0 __PRETTY_FUNCTION__ = "void* buf_flush_page_cleaner(void*)" last_pages = 0 abstime = {tv_sec = 1727806384, tv_nsec = 216928000} lsn_limit = 0 last_activity_count = 0 #3 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #4 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 4 (Thread 0x7f8c1905d700 (LWP 105841)): #0 0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c397993c84 in safe_cond_timedwait (cond=0x55c3992c50e0 <COND_checkpoint>, mp=0x55c3992c5020 <LOCK_checkpoint>, abstime=0x7f8c1905cce0, file=0x55c398a031b0 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541 error = 32765 save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105841, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Normal, Status = Acquired, possibly with no waiters, Owner ID = 105841, Robust = No, Shared = No, Protocol = None}, file = 0x55c398a03208 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c", name = 0x55c398a03260 "control->LOCK_control", line = 99, count = 0, create_flags = 0, active_flags = 0, id = 15, thread = 140239691962112, locked_mutex = 0x7f8c0c000ff8, used_mutex = 0x7f8c0c001070, prev = 0x0, next = 0x0} #2 0x000055c398100c33 in inline_mysql_cond_timedwait (that=0x55c3992c50e0 <COND_checkpoint>, mutex=0x55c3992c5020 <LOCK_checkpoint>, abstime=0x7f8c1905cce0, src_file=0x55c398a03208 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c", src_line=115) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270 result = 0 #3 0x000055c398100f02 in my_service_thread_sleep (control=0x55c399227ae0 <checkpoint_control>, sleep_time=30000000000) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_servicethread.c:115 abstime = {tv_sec = 1727807311, tv_nsec = 55122000} res = 0 '\000' #4 0x000055c397f7c64b in ma_checkpoint_background (arg=0x1e) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/storage/maria/ma_checkpoint.c:725 interval = 30 sleeps = 900 sleep_time = 30 log_horizon_at_last_checkpoint = 4295005134 pagecache_flushes_at_last_checkpoint = 0 pages_bunch_size = 0 filter_param = {up_to_lsn = 4295005090, max_pages = 0} dfile = 0x0 kfile = 0x0 __PRETTY_FUNCTION__ = "ma_checkpoint_background" #5 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #6 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 3 (Thread 0x7f8c19bd6700 (LWP 105833)): #0 0x00007f8c19ed0ad8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c397993c84 in safe_cond_timedwait (cond=0x55c39928c3c0 <COND_timer>, mp=0x55c39928c300 <LOCK_timer>, abstime=0x7f8c19bd5d60, file=0x55c398656490 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", line=1270) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_mutex.c:541 error = 0 save_state = {global = pthread_mutex_t = {Type = Error check, Status = Acquired, possibly with no waiters, Owner ID = 105833, Robust = No, Shared = No, Protocol = None}, mutex = pthread_mutex_t = {Type = Adaptive, Status = Acquired, possibly with waiters, Owner ID = 105833, Robust = No, Shared = No, Protocol = None}, file = 0x55c398656490 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h", name = 0x55c398656532 "LOCK_timer", line = 1270, count = 0, create_flags = 0, active_flags = 0, id = 9, thread = 140239703992064, locked_mutex = 0x7f8c14000ff8, used_mutex = 0x7f8c14001070, prev = 0x0, next = 0x0} #2 0x000055c397991e34 in inline_mysql_cond_timedwait (that=0x55c39928c3c0 <COND_timer>, mutex=0x55c39928c300 <LOCK_timer>, abstime=0x7f8c19bd5d60, src_file=0x55c3986564e8 "/home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_timer.c", src_line=321) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/include/mysql/psi/mysql_thread.h:1270 result = 32652 #3 0x000055c397992877 in timer_handler (arg=0x0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/thr_timer.c:321 error = 110 top_time = 0x55c39b4b1858 now = {tv_sec = 1727807282, tv_nsec = 268484000} abstime = {tv_sec = 1727807282, tv_nsec = 497387000} #4 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #5 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 2 (Thread 0x7f8c13fff700 (LWP 105874)): #0 0x00007f8c19de0fc9 in syscall () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. #1 0x000055c39860b164 in my_getevents (ctx=0x7f8c1844b000, min_nr=1, nr=256, ev=0x7f8c13ffcc80) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/aio_linux.cc:64 saved_errno = 0 ret = -1738493207 #2 0x000055c39860b32c in tpool::aio_linux::getevent_thread_routine (aio=0x55c39b4fa5b0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/tpool/aio_linux.cc:108 ret = 5 MAX_EVENTS = 256 events = {{data = 0x0, obj = 0x55c39b51a310, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a3d0, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a490, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a550, res = 16384, res2 = 0}, {data = 0x0, obj = 0x55c39b51a610, res = 16384, res2 = 0}, {data = 0x0, obj = 0x0, res = 0, res2 = 0} <repeats 249 times>, {data = 0x0, obj = 0x0, res = 0, res2 = 94298612800400}, {data = 0x7f8c13ffec80, obj = 0x55c39860bce9 <std::_Tuple_impl<0ul, void (*)(tpool::aio_linux*), tpool::aio_linux*>::_M_head(std::_Tuple_impl<0ul, void (*)(tpool::aio_linux*), tpool::aio_linux*>&)+28>, res = 0, res2 = 94298612800392}} #3 0x000055c39860bc92 in std::__invoke_impl<void, void (*)(tpool::aio_linux*), tpool::aio_linux*> (__f=@0x55c39b519b90: 0x55c39860b2e9 <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>) at /usr/include/c++/10/bits/invoke.h:60 No locals. #4 0x000055c39860bbf9 in std::__invoke<void (*)(tpool::aio_linux*), tpool::aio_linux*> (__fn=@0x55c39b519b90: 0x55c39860b2e9 <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>) at /usr/include/c++/10/bits/invoke.h:95 No locals. #5 0x000055c39860bb69 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::_M_invoke<0ul, 1ul> (this=0x55c39b519b88) at /usr/include/c++/10/thread:264 No locals. #6 0x000055c39860bb22 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::operator() (this=0x55c39b519b88) at /usr/include/c++/10/thread:271 No locals. #7 0x000055c39860bb06 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> > >::_M_run (this=0x55c39b519b80) at /usr/include/c++/10/thread:215 No locals. #8 0x00007f8c1a110ed0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 No symbol table info available. #9 0x00007f8c19ec9ea7 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #10 0x00007f8c19de7acf in clone () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. Thread 1 (Thread 0x7f8c19ce78c0 (LWP 105816)): #0 0x00007f8c19ed1f44 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #1 0x000055c397998bba in my_write_core (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/mysys/stacktrace.c:424 No locals. #2 0x000055c39790471a in signal_handler (sig=6) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9841 No locals. #3 <signal handler called> No symbol table info available. #4 0x00007f8c19ed07b2 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 No symbol table info available. #5 0x000055c3978f36ae in wait_query_thread_done (con=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1005 __PRETTY_FUNCTION__ = "void wait_query_thread_done(st_connection*)" #6 0x000055c3978f3899 in do_read_query_result (cn=0x55c39b397ed8) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:1046 __PRETTY_FUNCTION__ = "int do_read_query_result(st_connection*)" #7 0x000055c397901586 in run_query_normal (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3, query=0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'", query_len=63, ds=0x55c3992420a0 <ds_res>, ds_warnings=0x7ffd28ba56d0) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:8125 res = 0x0 mysql = 0x55c39b79ee38 err = 0 counter = 0 __PRETTY_FUNCTION__ = "void run_query_normal(st_connection*, st_command*, int, const char*, size_t, DYNAMIC_STRING*, DYNAMIC_STRING*)" #8 0x000055c397903d10 in run_query (cn=0x55c39b397ed8, command=0x55c39b76f8e8, flags=3) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:9491 mysql = 0x55c39b79ee38 rs_output = 0x55c3992420a0 <ds_res> rs_cmp_result = {str = 0x7ffd28ba56f0 " W\272(\375\177", length = 94298550368509, max_length = 94298611144168, alloc_increment = 6903295466} rs_unsorted = {str = 0x7ffd28ba5720 "\240Y\272(\375\177", length = 94298549797658, max_length = 94298615249128, alloc_increment = 94298615249128} rs_sorted_save = 0x0 rs_warnings = {str = 0x55c39b7f0c28 '\245' <repeats 200 times>..., length = 0, max_length = 256, alloc_increment = 256} query = 0x55c39b77ede8 "SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'" query_len = 63 view_created = 0 '\000' sp_created = 0 '\000' complete_query = 1 '\001' #9 0x000055c3979059ad in main (argc=36, argv=0x7ffd28ba5a98) at /home/buildbot/amd64-debian-11-debug-ps-embedded/build/client/mysqltest.cc:10334 old_display_result_vertically = 0 '\000' flags = 3 ok_to_do = 1 '\001' current_line_inc = 1 processed = 1 command = 0x55c39b76f8e8 q_send_flag = 0 '\000' abort_flag = 0 '\000' command_executed = 28 last_command_executed = 28 save_file = "\000W\272(\375\177\000\000\245\071\327\227\303U\000\000\000\000\000\000\000\000\000\000\320X\272(\375\177\000\000\214\326\272\230\303U\000\000\340X\272(\375\177\000\000\320W\272(\375\177\000\000]i\327\227\303U\000\000\020X\272(\375\177\000\000\340X\272(\375\177\000\000\360W\272(\375\177\000\000\000\000\000\000\000\000\000\000 X\272(\375\177\000\000\255V\263\227\303U\000\000\020X\272(\375\177", '\000' <repeats 18 times>, "\200X\272(\375\177\000\000\000\000\000\000\000\000\000\000\360X\272(\375\177\000\000`X\272(\375\177\000\000>X\263\227\303U\000\000\240s)\231\303U", '\000' <repeats 18 times>... empty_result = false error = 0 con = 0x55c39b397ed8 The test aborts because the "con2_insert_done" debug sync signal is not delivered (or delivered too early and missed) to thread 7 executing: now SIGNAL con2_go WAIT_FOR con2_insert_done However the stack trace shows that there is no thread waiting for con2_go. I was able to repeat the hang with: while . /mtr --rr=-h --parallel=auto --embedded -- ps innodb.innodb-lock-inherit-read_commited{,,,,,,,,,}; do :; done Here follows a quick analyze regarding this: I put a break on debug_sync_execute() to see what sync points was executed and in which order. The result are: row_ins_sec_index_entry_dup_locks_created signal con1_locks_done wait for con1_go now wait for con1_locks_done now wait for con2_blocked lock_wait_suspend_thread_enter signal con2_blocked wait for con2_go And after that the threads was blocked for a long time (probably waiting for a timeout) until I got: ha_commit_trans_after_acquire_commit_lock signal con1_insert_done wait for con1_finish ib_after_row_insert signal con2_insert_done And after that no more debug_sync_execute calls. I assume this means that there was nothing waiting for con1_insert_done. I looked what the threads was waiting for: Thread 22: Waiting for con1_finish Thread 13: Signaling con2_insert_done (no wait) No other threads was waiting for debug syncs! I would have expected a thread waiting for con1_go, but could not find it. I checked and the thread waiting for the con1_go signal got a timeout in debug_sync wait and continued executing. After this things started to fall appart. At the point of the timeout on con1_go we had the following active threads: Thread 1: Waiting on "SET GLOBAL innodb_max_purge_lag_wait= 0" Thread 2: timeout Thread 10: Waiting on SET GLOBAL innodb_max_purge_lag_wait= 0 Thread 12: wait for con2_go No other threads waiting in debug sync The stack trace fore the SET GLOBAL is: Thread 1: #9 0x0000275b754bc712 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #10 0x000000000075b815 in wait_query_thread_done (con=0x2cc5468) at /my/maria-10.5/client/mysqltest.cc:1005 #11 0x000000000075ba84 in do_read_query_result (cn=0x2cc5468) at /my/maria-10.5/client/mysqltest.cc:1046 #12 0x000000000076bdc1 in run_query_normal (cn=0x2cc5468, command=0x3a75dc98118, flags=3, query=0x3a75dcdb688 "SET GLOBAL innodb_max_purge_lag_wait= 0", query_len=39, ds=0x23a6be0 <ds_res>, ds_warnings=0x7fffffff96b0)   Thread 11: #0 0x000036437e175121 in clock_nanosleep@GLIBC_2.2.5 () from /lib64/libc.so.6 #1 0x000036437e17ae43 in nanosleep () from /lib64/libc.so.6 #2 0x00000000014fa9b5 in os_thread_sleep (tm=100000) at /my/maria-10.5/storage/innobase/os/os0thread.cc:122 #3 0x0000000001136705 in innodb_max_purge_lag_wait_update (thd=0x3a75dc61898, limit=0x57b38036658) at /my/maria-10.5/storage/innobase/handler/ha_innodb.cc:241 #4 0x0000000000b62cfa in sys_var_pluginvar::global_update (this=0x2dd5230, thd=0x3a75dc61898, var=0x57b38036630) at /my/maria-10.5/sql/sql_plugin.cc:3674 #5 0x0000000000c6075b in sys_var::update (this=0x2dd5230, thd=0x3a75dc61898, var=0x57b38036630) at /my/maria-10.5/sql/set_var.cc:207 #6 0x0000000000c625fa in set_var::update (this=0x57b38036630, thd=0x3a75dc61898) at /my/maria-10.5/sql/set_var.cc:859 #7 0x0000000000c6217d in sql_set_variables (thd=0x3a75dc61898, var_list=0x3a75dc66918, free=true) at /my/maria-10.5/sql/set_var.cc:746 #8 0x0000000000b8521e in mysql_execute_command (thd=0x3a75dc61898) at /my/maria-10.5/sql/sql_parse.cc:5172 #9 0x0000000000b8ab7b in mysql_parse (thd=0x3a75dc61898, rawbuf=0x57b38038af0 "SET GLOBAL innodb_max_purge_lag_wait= 0", length=39, parser_state=0x68ec565952f0, is_com_multi=false, is_next_command=false) at /my/maria-10.5/sql/sql_parse.cc:8237 Conclusion is that SET GLOBAL innodb_max_purge_lag_wait= 0 takes more than 300 seconds and because of that we get a timeout on debug sync. One possible reason may be that there are two identical queries running at the same time and causing a conflict.

          According to the cross-reference, the last failure of this test for a 10.6 based branch was for this commit, which does not include the fixes of MDEV-34520 or MDEV-34515. That explains why I am unable to reproduce the hang on 10.6. There is also this rather recent failure for a 11.x branch, but it likewise is missing those fixes.

          bb-11.6-hints-v2 c8ce9fbb98b82a3955f235f6b17077be85ad33f4

          innodb.innodb-lock-inherit-read_commited w8 [ fail ]
                  Test ended at 2024-09-06 07:42:16
           
          CURRENT_TEST: innodb.innodb-lock-inherit-read_commited
          mysqltest: At line 94: query 'reap' failed with wrong errno ER_LOCK_DEADLOCK (1213): 'Deadlock found when trying to get lock; try restarting transaction', instead of  (0)...
          

          I will try to reproduce this in 10.5. Whether this is practical to be fixed in that version, I should find out soon.

          marko Marko Mäkelä added a comment - According to the cross-reference, the last failure of this test for a 10.6 based branch was for this commit , which does not include the fixes of MDEV-34520 or MDEV-34515 . That explains why I am unable to reproduce the hang on 10.6. There is also this rather recent failure for a 11.x branch, but it likewise is missing those fixes. bb-11.6-hints-v2 c8ce9fbb98b82a3955f235f6b17077be85ad33f4 innodb.innodb-lock-inherit-read_commited w8 [ fail ] Test ended at 2024-09-06 07:42:16   CURRENT_TEST: innodb.innodb-lock-inherit-read_commited mysqltest: At line 94: query 'reap' failed with wrong errno ER_LOCK_DEADLOCK (1213): 'Deadlock found when trying to get lock; try restarting transaction', instead of (0)... I will try to reproduce this in 10.5. Whether this is practical to be fixed in that version, I should find out soon.

          I was able to reproduce this with

          while ./mtr --rr=-h --ps-protocol --parallel=6 innodb.innodb-lock-inherit-read_commited{,,,,,}
          do :
          done
          

          and waiting a little for it to hang (a test would normally take about 6 seconds) and then killall -ABRT mariadbd:

          10.5 23820f1d79f6aa30930a96ac182899e737ee3590

          CURRENT_TEST: innodb.innodb-lock-inherit-read_commited
          mysqltest: In included file "/mariadb/10.5/mysql-test/suite/innodb/t/../../innodb/include/wait_all_purged.inc": 
          included from /mariadb/10.5/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test at line 83:
          At line 7: query 'SET GLOBAL innodb_max_purge_lag_wait= 0' failed: 2013: Lost connection to MySQL server during query
          

          In the rr replay I set watch trx_sys.rseg_history_len.m_counter._M_i to see what is going on. First, trx_lists_init_at_db_start() would increment the counter to 12. Then, some transactions would be created, and then purge would decrement the count to 2 but not below that. At the time purge is decrementing the count to 2, one thread with trx->id=34 (which is in purge_sys.view, blocking purge) is waiting for DEBUG_SYNC in a lock wait:

          10.5 23820f1d79f6aa30930a96ac182899e737ee3590

          #18 debug_sync (thd=0x222318002d08, sync_point_name=<optimized out>, name_len=<optimized out>) at /mariadb/10.5/sql/debug_sync.cc:1580
          #19 0x0000564e9670ba47 in lock_wait_suspend_thread (thr=0x222318023cc8) at /mariadb/10.5/storage/innobase/lock/lock0wait.cc:233
          #20 0x0000564e967a2f2d in row_mysql_handle_errors (new_err=new_err@entry=0x3692580708f4, trx=trx@entry=0x1aea30881738, thr=thr@entry=0x222318023cc8, savept=savept@entry=0x3692580708f8) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:713
          #21 0x0000564e967a3cc7 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x2223180224e8 "\377\001", prebuilt=0x222318023520, ins_mode=ROW_INS_NORMAL) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:1382
          #22 0x0000564e9667ea74 in ha_innobase::write_row (this=0x2223180228e0, record=0x2223180224e8 "\377\001") at /mariadb/10.5/storage/innobase/handler/ha_innodb.cc:7724
          #23 0x0000564e96409f2a in handler::ha_write_row (this=0x2223180228e0, buf=0x2223180224e8 "\377\001") at /mariadb/10.5/sql/handler.cc:7373
          #24 0x0000564e961a57cb in write_record (thd=thd@entry=0x222318002d08, table=table@entry=0x222318009b78, info=info@entry=0x369258070d20, sink=sink@entry=0x0) at /mariadb/10.5/sql/sql_insert.cc:1867
          #25 0x0000564e961acd35 in mysql_insert (thd=thd@entry=0x222318002d08, table_list=<optimized out>, fields=@0x222318007c08: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c08, elements = 0x0}, <No data fields>}, values_list=@0x222318007c50: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x222318018c50, last = 0x222318018c50, elements = 0x1}, <No data fields>}, update_fields=@0x222318007c38: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c38, elements = 0x0}, <No data fields>}, update_values=@0x222318007c20: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c20, elements = 0x0}, <No data fields>}, duplic=DUP_REPLACE, ignore=<optimized out>, result=0x0) at /mariadb/10.5/sql/sql_insert.cc:1139
          #26 0x0000564e961e0143 in mysql_execute_command (thd=thd@entry=0x222318002d08) at /mariadb/10.5/sql/sql_parse.cc:4651
          #27 0x0000564e961e407c in mysql_parse (thd=thd@entry=0x222318002d08, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x369258071540, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:8236
          #28 0x0000564e961e60ae in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x222318002d08, packet=packet@entry=0x22231800f5e9 "REPLACE INTO t1 VALUES (1,3)", packet_length=packet_length@entry=0x1c, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:1892
          

          Another thread, with trx->id==33, which is the other transaction that appears in purge_sys.view, is blocked outside a lock wait:

          10.5 23820f1d79f6aa30930a96ac182899e737ee3590

          #18 debug_sync (thd=0x501004002c68, sync_point_name=<optimized out>, name_len=<optimized out>) at /mariadb/10.5/sql/debug_sync.cc:1580
          #19 0x0000564e96788272 in row_ins_sec_index_entry_low (flags=flags@entry=0x0, mode=mode@entry=0x2, index=index@entry=0x3aa538192f30, offsets_heap=<optimized out>, offsets_heap@entry=0x50100402e100, heap=heap@entry=0x50100402e5d0, entry=entry@entry=0x50100402a838, trx_id=0x0, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3119
          #20 0x0000564e9678b782 in row_ins_sec_index_entry (index=index@entry=0x3aa538192f30, entry=entry@entry=0x50100402a838, thr=thr@entry=0x501004027b18, check_foreign=check_foreign@entry=0x1) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3353
          #21 0x0000564e9678c10a in row_ins_index_entry (index=0x3aa538192f30, entry=0x50100402a838, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3401
          #22 row_ins_index_entry_step (node=<optimized out>, thr=<optimized out>) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3567
          #23 row_ins (node=<optimized out>, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3704
          #24 row_ins_step (thr=thr@entry=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3847
          #25 0x0000564e967a3a0f in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x501004026338 "\377\001", prebuilt=0x501004027370, ins_mode=ROW_INS_NORMAL) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:1369
          #26 0x0000564e9667ea74 in ha_innobase::write_row (this=0x501004026730, record=0x501004026338 "\377\001") at /mariadb/10.5/storage/innobase/handler/ha_innodb.cc:7724
          #27 0x0000564e96409f2a in handler::ha_write_row (this=0x501004026730, buf=0x501004026338 "\377\001") at /mariadb/10.5/sql/handler.cc:7373
          #28 0x0000564e961a57cb in write_record (thd=thd@entry=0x501004002c68, table=table@entry=0x501004025f08, info=info@entry=0x46e74febed20, sink=sink@entry=0x0) at /mariadb/10.5/sql/sql_insert.cc:1867
          #29 0x0000564e961acd35 in mysql_insert (thd=thd@entry=0x501004002c68, table_list=<optimized out>, fields=@0x501004007b68: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b68, elements = 0x0}, <No data fields>}, values_list=@0x501004007bb0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x501004016940, last = 0x501004016940, elements = 0x1}, <No data fields>}, update_fields=@0x501004007b98: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b98, elements = 0x0}, <No data fields>}, update_values=@0x501004007b80: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b80, elements = 0x0}, <No data fields>}, duplic=DUP_REPLACE, ignore=<optimized out>, result=0x0) at /mariadb/10.5/sql/sql_insert.cc:1139
          #30 0x0000564e961e0143 in mysql_execute_command (thd=thd@entry=0x501004002c68) at /mariadb/10.5/sql/sql_parse.cc:4651
          #31 0x0000564e961e407c in mysql_parse (thd=thd@entry=0x501004002c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x46e74febf540, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:8236
          #32 0x0000564e961e60ae in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x501004002c68, packet=packet@entry=0x50100400d2a9 "REPLACE INTO t1 VALUES (1,2)", packet_length=packet_length@entry=0x1c, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:1892
          

          These would correspond to con1 and con2 in the test file. Apparently the two connections are expected to be blocked on a different lock. The following fix seems to stabilize the test:

          diff --git a/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test b/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test
          index d9c933fa9b5..b89aead5afa 100644
          --- a/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test
          +++ b/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test
          @@ -79,7 +79,7 @@ disconnect purge_control;
           connection default;
           
           # Wait for purge to delete the delete-marked record
          ---source ../../innodb/include/wait_all_purged.inc
          +SET GLOBAL innodb_max_purge_lag_wait=2;
           
           SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done';
           SET debug_sync = 'now SIGNAL con1_go WAIT_FOR con1_insert_done';
          

          This hacky fix must be null-merged to 10.6 and later major versions.

          marko Marko Mäkelä added a comment - I was able to reproduce this with while . /mtr --rr=-h -- ps -protocol --parallel=6 innodb.innodb-lock-inherit-read_commited{,,,,,} do : done and waiting a little for it to hang (a test would normally take about 6 seconds) and then killall -ABRT mariadbd : 10.5 23820f1d79f6aa30930a96ac182899e737ee3590 CURRENT_TEST: innodb.innodb-lock-inherit-read_commited mysqltest: In included file "/mariadb/10.5/mysql-test/suite/innodb/t/../../innodb/include/wait_all_purged.inc": included from /mariadb/10.5/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test at line 83: At line 7: query 'SET GLOBAL innodb_max_purge_lag_wait= 0' failed: 2013: Lost connection to MySQL server during query In the rr replay I set watch trx_sys.rseg_history_len.m_counter._M_i to see what is going on. First, trx_lists_init_at_db_start() would increment the counter to 12. Then, some transactions would be created, and then purge would decrement the count to 2 but not below that. At the time purge is decrementing the count to 2, one thread with trx->id=34 (which is in purge_sys.view , blocking purge) is waiting for DEBUG_SYNC in a lock wait: 10.5 23820f1d79f6aa30930a96ac182899e737ee3590 #18 debug_sync (thd=0x222318002d08, sync_point_name=<optimized out>, name_len=<optimized out>) at /mariadb/10.5/sql/debug_sync.cc:1580 #19 0x0000564e9670ba47 in lock_wait_suspend_thread (thr=0x222318023cc8) at /mariadb/10.5/storage/innobase/lock/lock0wait.cc:233 #20 0x0000564e967a2f2d in row_mysql_handle_errors (new_err=new_err@entry=0x3692580708f4, trx=trx@entry=0x1aea30881738, thr=thr@entry=0x222318023cc8, savept=savept@entry=0x3692580708f8) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:713 #21 0x0000564e967a3cc7 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x2223180224e8 "\377\001", prebuilt=0x222318023520, ins_mode=ROW_INS_NORMAL) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:1382 #22 0x0000564e9667ea74 in ha_innobase::write_row (this=0x2223180228e0, record=0x2223180224e8 "\377\001") at /mariadb/10.5/storage/innobase/handler/ha_innodb.cc:7724 #23 0x0000564e96409f2a in handler::ha_write_row (this=0x2223180228e0, buf=0x2223180224e8 "\377\001") at /mariadb/10.5/sql/handler.cc:7373 #24 0x0000564e961a57cb in write_record (thd=thd@entry=0x222318002d08, table=table@entry=0x222318009b78, info=info@entry=0x369258070d20, sink=sink@entry=0x0) at /mariadb/10.5/sql/sql_insert.cc:1867 #25 0x0000564e961acd35 in mysql_insert (thd=thd@entry=0x222318002d08, table_list=<optimized out>, fields=@0x222318007c08: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c08, elements = 0x0}, <No data fields>}, values_list=@0x222318007c50: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x222318018c50, last = 0x222318018c50, elements = 0x1}, <No data fields>}, update_fields=@0x222318007c38: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c38, elements = 0x0}, <No data fields>}, update_values=@0x222318007c20: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x222318007c20, elements = 0x0}, <No data fields>}, duplic=DUP_REPLACE, ignore=<optimized out>, result=0x0) at /mariadb/10.5/sql/sql_insert.cc:1139 #26 0x0000564e961e0143 in mysql_execute_command (thd=thd@entry=0x222318002d08) at /mariadb/10.5/sql/sql_parse.cc:4651 #27 0x0000564e961e407c in mysql_parse (thd=thd@entry=0x222318002d08, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x369258071540, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:8236 #28 0x0000564e961e60ae in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x222318002d08, packet=packet@entry=0x22231800f5e9 "REPLACE INTO t1 VALUES (1,3)", packet_length=packet_length@entry=0x1c, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:1892 Another thread, with trx->id==33 , which is the other transaction that appears in purge_sys.view , is blocked outside a lock wait: 10.5 23820f1d79f6aa30930a96ac182899e737ee3590 #18 debug_sync (thd=0x501004002c68, sync_point_name=<optimized out>, name_len=<optimized out>) at /mariadb/10.5/sql/debug_sync.cc:1580 #19 0x0000564e96788272 in row_ins_sec_index_entry_low (flags=flags@entry=0x0, mode=mode@entry=0x2, index=index@entry=0x3aa538192f30, offsets_heap=<optimized out>, offsets_heap@entry=0x50100402e100, heap=heap@entry=0x50100402e5d0, entry=entry@entry=0x50100402a838, trx_id=0x0, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3119 #20 0x0000564e9678b782 in row_ins_sec_index_entry (index=index@entry=0x3aa538192f30, entry=entry@entry=0x50100402a838, thr=thr@entry=0x501004027b18, check_foreign=check_foreign@entry=0x1) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3353 #21 0x0000564e9678c10a in row_ins_index_entry (index=0x3aa538192f30, entry=0x50100402a838, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3401 #22 row_ins_index_entry_step (node=<optimized out>, thr=<optimized out>) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3567 #23 row_ins (node=<optimized out>, thr=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3704 #24 row_ins_step (thr=thr@entry=0x501004027b18) at /mariadb/10.5/storage/innobase/row/row0ins.cc:3847 #25 0x0000564e967a3a0f in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x501004026338 "\377\001", prebuilt=0x501004027370, ins_mode=ROW_INS_NORMAL) at /mariadb/10.5/storage/innobase/row/row0mysql.cc:1369 #26 0x0000564e9667ea74 in ha_innobase::write_row (this=0x501004026730, record=0x501004026338 "\377\001") at /mariadb/10.5/storage/innobase/handler/ha_innodb.cc:7724 #27 0x0000564e96409f2a in handler::ha_write_row (this=0x501004026730, buf=0x501004026338 "\377\001") at /mariadb/10.5/sql/handler.cc:7373 #28 0x0000564e961a57cb in write_record (thd=thd@entry=0x501004002c68, table=table@entry=0x501004025f08, info=info@entry=0x46e74febed20, sink=sink@entry=0x0) at /mariadb/10.5/sql/sql_insert.cc:1867 #29 0x0000564e961acd35 in mysql_insert (thd=thd@entry=0x501004002c68, table_list=<optimized out>, fields=@0x501004007b68: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b68, elements = 0x0}, <No data fields>}, values_list=@0x501004007bb0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x501004016940, last = 0x501004016940, elements = 0x1}, <No data fields>}, update_fields=@0x501004007b98: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b98, elements = 0x0}, <No data fields>}, update_values=@0x501004007b80: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x564e973eae70 <end_of_list>, last = 0x501004007b80, elements = 0x0}, <No data fields>}, duplic=DUP_REPLACE, ignore=<optimized out>, result=0x0) at /mariadb/10.5/sql/sql_insert.cc:1139 #30 0x0000564e961e0143 in mysql_execute_command (thd=thd@entry=0x501004002c68) at /mariadb/10.5/sql/sql_parse.cc:4651 #31 0x0000564e961e407c in mysql_parse (thd=thd@entry=0x501004002c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x46e74febf540, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:8236 #32 0x0000564e961e60ae in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x501004002c68, packet=packet@entry=0x50100400d2a9 "REPLACE INTO t1 VALUES (1,2)", packet_length=packet_length@entry=0x1c, is_com_multi=is_com_multi@entry=0x0, is_next_command=is_next_command@entry=0x0) at /mariadb/10.5/sql/sql_parse.cc:1892 These would correspond to con1 and con2 in the test file. Apparently the two connections are expected to be blocked on a different lock. The following fix seems to stabilize the test: diff --git a/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test b/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test index d9c933fa9b5..b89aead5afa 100644 --- a/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test +++ b/mysql-test/suite/innodb/t/innodb-lock-inherit-read_commited.test @@ -79,7 +79,7 @@ disconnect purge_control; connection default; # Wait for purge to delete the delete-marked record ---source ../../innodb/include/wait_all_purged.inc +SET GLOBAL innodb_max_purge_lag_wait=2; SET debug_sync = 'now SIGNAL con2_go WAIT_FOR con2_insert_done'; SET debug_sync = 'now SIGNAL con1_go WAIT_FOR con1_insert_done'; This hacky fix must be null-merged to 10.6 and later major versions.
          marko Marko Mäkelä added a comment - Pushed to 10.5 and null-merged to 10.6 .

          People

            marko Marko Mäkelä
            wlad Vladislav Vaintroub
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.