Hi, I reproduced the bug and tried to diagnose it. The reason node 1 was blocked is that the ALTER TABLE transaction was waiting for a X-lock on the parent table:
#1 __pthread_cond_wait_common (abstime=0x7ff06c9124a0, clockid=<optimized out>, mutex=0x1f13140 <lock_sys+128>, cond=0x7ff06d11bd10) at pthread_cond_wait.c:520
#2 __pthread_cond_timedwait (cond=0x7ff06d11bd10, mutex=0x1f13140 <lock_sys+128>, abstime=0x7ff06c9124a0) at pthread_cond_wait.c:665
#30x0000000000c17c81 in lock_wait (thr=<optimized out>, thr@entry=0x7ff038067100) at lock/lock0lock.cc:2027
#40x0000000000c822b3 in row_mysql_handle_errors (new_err=new_err@entry=0x7ff06c9126d4, trx=trx@entry=0x7ff06d11bc80, thr=thr@entry=0x7ff038067100, savept=savept@entry=0x0) at row/row0mysql.cc:688
#50x0000000000c1cb7d in lock_table_for_trx (table=0x7ff038060ed0, trx=trx@entry=0x7ff06d11bc80, mode=mode@entry=LOCK_X, no_wait=false) at lock/lock0lock.cc:3965
#60x0000000000c1cf83 in lock_table_children (table=<optimized out>, trx=trx@entry=0x7ff06d11bc80) at lock/lock0lock.cc:4018
#70x0000000000bf569d in ha_innobase::commit_inplace_alter_table (this=0x7ff038045e20, altered_table=<optimized out>, ha_alter_info=0x7ff06c913270, commit=<optimized out>) at handler/handler0alter.cc:11206
#80x00000000007bb80d in mysql_inplace_alter_table (thd=0x7ff038000c58, table_list=0x7ff038010d70, table=0x7ff0380459e8, altered_table=0x7ff06c9129f0, ha_alter_info=0x7ff06c913270, target_mdl_request=<optimized out>,
ddl_log_state=0x7ff06c9128f0, trigger_param=0x7ff06c913f70, alter_ctx=0x7ff06c913330) at sql_table.cc:7545
packet_length=packet_length@entry=39, blocking=false) at sql_parse.cc:1883
#150x0000000000711a7e in do_command (thd=0x7ff038000c58, blocking=true) at sql_parse.cc:1409
#160x000000000081a3ae in do_handle_one_connection (connect=<optimized out>, connect@entry=0x25d3fb8, put_in_cache=<optimized out>) at sql_connect.cc:1415
#170x000000000081a1cd in handle_one_connection (arg=arg@entry=0x25d3fb8) at sql_connect.cc:1317
#180x0000000000b4f0be in pfs_spawn_thread (arg=0x2576d38) at pfs.cc:2201
#190x00007ff0a1b1b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#200x00007ff0a183b353 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
This is because node 2 had an uncommitted transaction that modified the child table. Due to the foreign key constraint between child and parent, both tables were locked on node 2. Since Galera uses synchronous replication, node 1 could not proceed with the ALTER TABLE on parent. We observed that even though the return value of wsrep_is_BF_lock_timeout() is true, the alter transaction continues to execute lock_table_wsrep() to acquire the lock on the table parent. Therefore, there will be multiple "wait long trx" records in error.log.
anonymous2
added a comment - - edited Hi, I reproduced the bug and tried to diagnose it. The reason node 1 was blocked is that the ALTER TABLE transaction was waiting for a X-lock on the parent table:
# 0 futex_abstimed_wait_cancelable ( private =<optimized out>, abstime= 0x7ff06c9124a0 , clockid=<optimized out>, expected= 0 , futex_word= 0x7ff06d11bd38 ) at ../sysdeps/nptl/futex-internal.h: 320
# 1 __pthread_cond_wait_common (abstime= 0x7ff06c9124a0 , clockid=<optimized out>, mutex= 0x1f13140 <lock_sys+ 128 >, cond= 0x7ff06d11bd10 ) at pthread_cond_wait.c: 520
# 2 __pthread_cond_timedwait (cond= 0x7ff06d11bd10 , mutex= 0x1f13140 <lock_sys+ 128 >, abstime= 0x7ff06c9124a0 ) at pthread_cond_wait.c: 665
# 3 0x0000000000c17c81 in lock_wait (thr=<optimized out>, thr @entry = 0x7ff038067100 ) at lock/lock0lock.cc: 2027
# 4 0x0000000000c822b3 in row_mysql_handle_errors (new_err=new_err @entry = 0x7ff06c9126d4 , trx=trx @entry = 0x7ff06d11bc80 , thr=thr @entry = 0x7ff038067100 , savept=savept @entry = 0x0 ) at row/row0mysql.cc: 688
# 5 0x0000000000c1cb7d in lock_table_for_trx (table= 0x7ff038060ed0 , trx=trx @entry = 0x7ff06d11bc80 , mode=mode @entry =LOCK_X, no_wait= false ) at lock/lock0lock.cc: 3965
# 6 0x0000000000c1cf83 in lock_table_children (table=<optimized out>, trx=trx @entry = 0x7ff06d11bc80 ) at lock/lock0lock.cc: 4018
# 7 0x0000000000bf569d in ha_innobase::commit_inplace_alter_table ( this = 0x7ff038045e20 , altered_table=<optimized out>, ha_alter_info= 0x7ff06c913270 , commit=<optimized out>) at handler/handler0alter.cc: 11206
# 8 0x00000000007bb80d in mysql_inplace_alter_table (thd= 0x7ff038000c58 , table_list= 0x7ff038010d70 , table= 0x7ff0380459e8 , altered_table= 0x7ff06c9129f0 , ha_alter_info= 0x7ff06c913270 , target_mdl_request=<optimized out>,
ddl_log_state= 0x7ff06c9128f0 , trigger_param= 0x7ff06c913f70 , alter_ctx= 0x7ff06c913330 ) at sql_table.cc: 7545
# 9 mysql_alter_table (thd=thd @entry = 0x7ff038000c58 , new_db=<optimized out>, new_db @entry = 0x7ff038005720 , new_name=<optimized out>, new_name @entry = 0x7ff038005b88 , create_info=create_info @entry = 0x7ff06c915be0 ,
table_list=table_list @entry = 0x7ff038010d70 , recreate_info=recreate_info @entry = 0x7ff06c915360 , alter_info= 0x7ff06c915a70 , order_num= 0 , order= 0x0 , ignore=<optimized out>, if_exists=<optimized out>) at sql_table.cc: 10522
# 10 0x000000000082005c in Sql_cmd_alter_table::execute ( this =<optimized out>, thd= 0x7ff038000c58 ) at sql_alter.cc: 675
# 11 0x00000000007154c6 in mysql_execute_command (thd=thd @entry = 0x7ff038000c58 , is_called_from_prepared_stmt= false ) at sql_parse.cc: 6091
# 12 0x0000000000711623 in mysql_parse (thd=thd @entry = 0x7ff038000c58 , rawbuf=<optimized out>, rawbuf @entry = 0x7ff038010c80 "ALTER TABLE parent AUTO_INCREMENT = 100" , length=<optimized out>, length @entry = 39 ,
parser_state=<optimized out>, parser_state @entry = 0x7ff06c916610 ) at sql_parse.cc: 8117
# 13 0x00000000007124d2 in wsrep_mysql_parse (thd=thd @entry = 0x7ff038000c58 , rawbuf= 0x7ff038010c80 "ALTER TABLE parent AUTO_INCREMENT = 100" , length= 39 , parser_state=parser_state @entry = 0x7ff06c916610 ) at sql_parse.cc: 7928
# 14 0x000000000070eebd in dispatch_command (command=command @entry =COM_QUERY, thd=thd @entry = 0x7ff038000c58 , packet=packet @entry = 0x7ff038008609 "ALTER TABLE parent AUTO_INCREMENT = 100" ,
packet_length=packet_length @entry = 39 , blocking= false ) at sql_parse.cc: 1883
# 15 0x0000000000711a7e in do_command (thd= 0x7ff038000c58 , blocking= true ) at sql_parse.cc: 1409
# 16 0x000000000081a3ae in do_handle_one_connection (connect=<optimized out>, connect @entry = 0x25d3fb8 , put_in_cache=<optimized out>) at sql_connect.cc: 1415
# 17 0x000000000081a1cd in handle_one_connection (arg=arg @entry = 0x25d3fb8 ) at sql_connect.cc: 1317
# 18 0x0000000000b4f0be in pfs_spawn_thread (arg= 0x2576d38 ) at pfs.cc: 2201
# 19 0x00007ff0a1b1b609 in start_thread (arg=<optimized out>) at pthread_create.c: 477
# 20 0x00007ff0a183b353 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S: 95
This is because node 2 had an uncommitted transaction that modified the child table. Due to the foreign key constraint between child and parent, both tables were locked on node 2. Since Galera uses synchronous replication, node 1 could not proceed with the ALTER TABLE on parent. We observed that even though the return value of wsrep_is_BF_lock_timeout() is true, the alter transaction continues to execute lock_table_wsrep() to acquire the lock on the table parent. Therefore, there will be multiple "wait long trx" records in error.log.
Julius Goryavsky
added a comment - The fix has been merged with the head revision: https://github.com/MariaDB/server/commit/231900e5bb15e5d6d90b8a6daf38a0b21d1a19e7
MDEV-29265 Assertion `mode_ == m_local || transaction_.is_streaming()' during SST
Hi, I reproduced the bug and tried to diagnose it. The reason node 1 was blocked is that the ALTER TABLE transaction was waiting for a X-lock on the parent table:
This is because node 2 had an uncommitted transaction that modified the child table. Due to the foreign key constraint between child and parent, both tables were locked on node 2. Since Galera uses synchronous replication, node 1 could not proceed with the ALTER TABLE on parent. We observed that even though the return value of wsrep_is_BF_lock_timeout() is true, the alter transaction continues to execute lock_table_wsrep() to acquire the lock on the table parent. Therefore, there will be multiple "wait long trx" records in error.log.