Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Critical
-
Resolution: Unresolved
-
10.6, 10.11, 11.4, 11.8, 12.3
-
Related to performance
Description
I noticed that test innodb.xa_recovery is consuming innodb_lock_wait_timeout=50 seconds extra time starting with the 10.11 branch.
I narrowed down the reason to the only send statement in the test. The test waits the execution of that statement to be blocked. Subsequently, it expects a DROP TABLE t2 to fail with ER_LOCK_WAIT_TIMEOUT:
|
bf686bb987766bce4ca842d12178d0c08710cab8:mysql-test/suite/innodb/t/xa_recovery.test |
|
43
|
SET innodb_lock_wait_timeout=1; |
44
|
--error ER_LOCK_WAIT_TIMEOUT
|
45
|
DROP TABLE t2; |
46
|
|
47
|
disconnect con1;
|
48
|
|
49
|
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED; |
50
|
--disable_ps2_protocol
|
51
|
SELECT * FROM t1; |
52
|
--enable_ps2_protocol
|
53
|
XA ROLLBACK 'x'; |
I debugged this as follows:
mysql-test/mtr --rr innodb.xa_recovery
|
rr replay mysql-test/var/log/mysqld.1.rr/mariadbd-1
|
I set a breakpoint to the only my_cond_timedwait() call in lock0lock.cc, as well as on innobase_close_connection and innobase_kill_query. It turns out that these functions were not called in response to the disconnect con1. The lock wait would keep blocked until it times out or is coincidentally interrupted by something else. In 10.6, the test completes faster because the above XA ROLLBACK 'x' happens to abort the wait:
|
10.6 bf686bb987766bce4ca842d12178d0c08710cab8 |
#0 ___pthread_cond_signal (cond=0x7fe481201210) at ./nptl/pthread_cond_signal.c:36
|
#1 0x000055ab95428465 in lock_wait_end<false> (trx=<optimized out>) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2292
|
#2 lock_grant (lock=lock@entry=0x7fe481201280) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2315
|
#3 0x000055ab9542dee8 in lock_rec_dequeue_from_page (in_lock=<optimized out>, owns_wait_mutex=0x1) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2407
|
#4 0x000055ab94e70875 in lock_release_try (trx=trx@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4355
|
#5 0x000055ab9542ecbb in lock_release (trx=trx@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4402
|
#6 0x000055ab94e74088 in trx_t::release_locks (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:485
|
#7 trx_t::commit_in_memory (this=0x7fe4811ffb80, mtr=0x7fe4804816b0) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1431
|
#8 trx_t::commit_low (this=this@entry=0x7fe4811ffb80, mtr=0x7fe4804816b0) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1573
|
#9 0x000055ab954c5972 in trx_t::commit_persist (this=this@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1587
|
#10 0x000055ab954c59b8 in trx_t::commit (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1596
|
#11 0x000055ab954bf8bd in trx_t::rollback_finish (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:64
|
#12 0x000055ab954c0228 in trx_t::rollback_low (this=0x7fe4811ffb80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:125
|
#13 0x000055ab954c043a in trx_rollback_for_mysql (trx=<optimized out>) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:249
|
#14 0x000055ab953e069c in innobase_rollback_by_xid (xid=<optimized out>) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:3015
|
#15 0x000055ab95178510 in xarollback_handlerton (unused1=<optimized out>, plugin=<optimized out>, arg=0x7fe480481c40) at /mariadb/10.6/sql/handler.cc:2432
|
#16 0x000055ab94f57f37 in plugin_foreach_with_mask (thd=thd@entry=0x0, func=0x55ab951784f0 <xarollback_handlerton(THD*, plugin_ref, void*)>, type=type@entry=0x1, state_mask=state_mask@entry=0x8,
|
arg=arg@entry=0x7fe480481c40) at /mariadb/10.6/sql/sql_plugin.cc:2559
|
#17 0x000055ab9517d9a9 in ha_commit_or_rollback_by_xid (xid=<optimized out>, commit=commit@entry=0x0) at /mariadb/10.6/sql/handler.cc:2454
|
#18 0x000055ab951089b1 in trans_xa_rollback (thd=thd@entry=0x7fe45c000cd8) at /mariadb/10.6/sql/xa.cc:843
|
#19 0x000055ab94f4d9fc in mysql_execute_command (thd=thd@entry=0x7fe45c000cd8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=0x0) at /mariadb/10.6/sql/sql_parse.cc:6045
|
#20 0x000055ab94f50209 in mysql_parse (thd=0x7fe45c000cd8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /mariadb/10.6/sql/sql_parse.cc:8201
|
#21 0x000055ab94f51da8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fe45c000cd8, packet=packet@entry=0x7fe45c016c09 "XA ROLLBACK 'x'", packet_length=packet_length@entry=0xf,
|
blocking=blocking@entry=0x1) at /mariadb/10.6/sql/sql_parse.cc:1911
|
In 10.11 or later the thread that is associated with the disconnected client will remain blocked for innodb_lock_wait_timeout seconds, adding to the test execution time. I will file a separate bug for the changed behaviour of the XA ROLLBACK 'x' between 10.6 and 10.11, once I have diagnosed it.