[MDEV-10692] InnoDB: Failing assertion: lock->trx->lock.wait_lock == lock Created: 2016-08-27  Updated: 2016-11-09  Resolved: 2016-11-09

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.1.20, 10.2.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-10544 Galera: Failing assertion: (lock->tr... Closed

 Description   

If it's not supposed to work yet, please feel free to close. The failure fires in my buildbot tests, so I am filing it just in case.

2016-08-28 00:47:28 0x7fcec3f6f300  InnoDB: Assertion failure in thread 140526027731712 in file lock0lock.cc line 755
 
InnoDB: Failing assertion: lock->trx->lock.wait_lock == lock


# 2016-08-28T00:47:43 [13578] #5  0x00007fcec1cd5448 in __GI_abort () at abort.c:89
 
# 2016-08-28T00:47:43 [13578] #6  0x00007fcec4ba6894 in ut_dbg_assertion_failed (expr=0x7fcec5067120 "lock->trx->lock.wait_lock == lock", file=0x7fcec5066d30 "/data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc", line=755) at /data/src/bb-10.2-jan/storage/innobase/ut/ut0dbg.cc:67
 
# 2016-08-28T00:47:43 [13578] #7  0x00007fcec4a01a75 in lock_reset_lock_and_trx_wait (lock=0x7fcec16e6808) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:755
 
# 2016-08-28T00:47:43 [13578] #8  0x00007fcec4a07404 in lock_grant (lock=0x7fcec16e6808) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:2801
 
# 2016-08-28T00:47:43 [13578] #9  0x00007fcec4a0bca9 in lock_table_dequeue (in_lock=0x7fce7e8c60e8) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:4712
 
# 2016-08-28T00:47:43 [13578] #10 0x00007fcec4a113e5 in lock_release_autoinc_last_lock (autoinc_locks=0x7fce7b8522a8) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:6907
 
# 2016-08-28T00:47:43 [13578] #11 0x00007fcec4a114c0 in lock_release_autoinc_locks (trx=0x7fceae001f50) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:6949
 
# 2016-08-28T00:47:43 [13578] #12 0x00007fcec4a11a1e in lock_cancel_waiting_and_release (lock=0x7fcec16e6560) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:7171
 
# 2016-08-28T00:47:43 [13578] #13 0x00007fcec4a0a8a4 in lock_table_create (c_lock=0x7fce7e8c60e8, table=0x7fce7e887608, type_mode=260, trx=0x7fceae0023c8) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:4197
 
# 2016-08-28T00:47:43 [13578] #14 0x00007fcec4a0b2eb in lock_table_enqueue_waiting (c_lock=0x7fce7e8c60e8, mode=4, table=0x7fce7e887608, thr=0x7fce7c53f960) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:4430
 
# 2016-08-28T00:47:43 [13578] #15 0x00007fcec4a0b937 in lock_table (flags=0, table=0x7fce7e887608, mode=LOCK_AUTO_INC, thr=0x7fce7c53f960) at /data/src/bb-10.2-jan/storage/innobase/lock/lock0lock.cc:4607
 
# 2016-08-28T00:47:43 [13578] #16 0x00007fcec4ad0c3a in row_lock_table_autoinc_for_mysql (prebuilt=0x7fce7c53f088) at /data/src/bb-10.2-jan/storage/innobase/row/row0mysql.cc:1285
 
# 2016-08-28T00:47:43 [13578] #17 0x00007fcec498d6b3 in ha_innobase::innobase_lock_autoinc (this=0x7fce7c4fa088) at /data/src/bb-10.2-jan/storage/innobase/handler/ha_innodb.cc:8707
 
# 2016-08-28T00:47:43 [13578] #18 0x00007fcec498d70c in ha_innobase::innobase_set_max_autoinc (this=0x7fce7c4fa088, auto_inc=143) at /data/src/bb-10.2-jan/storage/innobase/handler/ha_innodb.cc:8735
 
# 2016-08-28T00:47:43 [13578] #19 0x00007fcec498e6f0 in ha_innobase::write_row (this=0x7fce7c4fa088, record=0x7fce7c41c1a0 "\377") at /data/src/bb-10.2-jan/storage/innobase/handler/ha_innodb.cc:9112
 
# 2016-08-28T00:47:43 [13578] #20 0x00007fcec477c397 in handler::ha_write_row (this=0x7fce7c4fa088, buf=0x7fce7c41c1a0 "\377") at /data/src/bb-10.2-jan/sql/handler.cc:5892
 
# 2016-08-28T00:47:43 [13578] #21 0x00007fcec4e6b8ec in ha_partition::write_row (this=0x7fce7c4f9888, buf=0x7fce7c41c1a0 "\377") at /data/src/bb-10.2-jan/sql/ha_partition.cc:4170
 
# 2016-08-28T00:47:43 [13578] #22 0x00007fcec477c397 in handler::ha_write_row (this=0x7fce7c4f9888, buf=0x7fce7c41c1a0 "\377") at /data/src/bb-10.2-jan/sql/handler.cc:5892
 
# 2016-08-28T00:47:43 [13578] #23 0x00007fcec44f3f82 in write_record (thd=0x7fce7bc16070, table=0x7fce7c514470, info=0x7fce7bc63b78) at /data/src/bb-10.2-jan/sql/sql_insert.cc:1595
 
# 2016-08-28T00:47:43 [13578] #24 0x00007fcec44f911b in select_insert::send_data (this=0x7fce7bc63b38, values=...) at /data/src/bb-10.2-jan/sql/sql_insert.cc:3714
 
# 2016-08-28T00:47:43 [13578] #25 0x00007fcec458419d in end_send (join=0x7fce7bc63be0, join_tab=0x7fce7bc651f0, end_of_records=false) at /data/src/bb-10.2-jan/sql/sql_select.cc:19474
 
# 2016-08-28T00:47:43 [13578] #26 0x00007fcec4581cc5 in evaluate_join_record (join=0x7fce7bc63be0, join_tab=0x7fce7bc64e48, error=0) at /data/src/bb-10.2-jan/sql/sql_select.cc:18525
 
# 2016-08-28T00:47:43 [13578] #27 0x00007fcec458175b in sub_select (join=0x7fce7bc63be0, join_tab=0x7fce7bc64e48, end_of_records=false) at /data/src/bb-10.2-jan/sql/sql_select.cc:18339
 
# 2016-08-28T00:47:43 [13578] #28 0x00007fcec4580b85 in do_select (join=0x7fce7bc63be0, procedure=0x0) at /data/src/bb-10.2-jan/sql/sql_select.cc:17843
 
# 2016-08-28T00:47:43 [13578] #29 0x00007fcec455bc68 in JOIN::exec_inner (this=0x7fce7bc63be0) at /data/src/bb-10.2-jan/sql/sql_select.cc:3341
 
# 2016-08-28T00:47:43 [13578] #30 0x00007fcec455b1e0 in JOIN::exec (this=0x7fce7bc63be0) at /data/src/bb-10.2-jan/sql/sql_select.cc:3153
 
# 2016-08-28T00:47:43 [13578] #31 0x00007fcec455c309 in mysql_select (thd=0x7fce7bc16070, tables=0x7fce7bc62cb8, wild_num=0, fields=..., conds=0x0, og_num=5, order=0x7fce7bc633f8, group=0x0, having=0x0, proc_param=0x0, select_options=3489925888, result=0x7fce7bc63b38, unit=0x7fce7bc19ac8, select_lex=0x7fce7bc1a1f0) at /data/src/bb-10.2-jan/sql/sql_select.cc:3537
 
# 2016-08-28T00:47:43 [13578] #32 0x00007fcec4551833 in handle_select (thd=0x7fce7bc16070, lex=0x7fce7bc19a00, result=0x7fce7bc63b38, setup_tables_done_option=1073741824) at /data/src/bb-10.2-jan/sql/sql_select.cc:377
 
# 2016-08-28T00:47:43 [13578] #33 0x00007fcec4518284 in mysql_execute_command (thd=0x7fce7bc16070) at /data/src/bb-10.2-jan/sql/sql_parse.cc:4396
 
# 2016-08-28T00:47:43 [13578] #34 0x00007fcec4523048 in mysql_parse (thd=0x7fce7bc16070, rawbuf=0x7fce7bc62088 "REPLACE INTO `table0_innodb_hash_pk_parts_2_int_autoinc` ( `col_int` ) SELECT `col_int_key` FROM `table1_innodb_int_autoinc` AS X ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 8", length=207, parser_state=0x7fcec3f6de30, is_com_multi=false, is_next_command=false) at /data/src/bb-10.2-jan/sql/sql_parse.cc:7742
 
# 2016-08-28T00:47:43 [13578] #35 0x00007fcec4510ed7 in dispatch_command (command=COM_QUERY, thd=0x7fce7bc16070, packet=0x7fce7bc56071 "REPLACE INTO `table0_innodb_hash_pk_parts_2_int_autoinc` ( `col_int` ) SELECT `col_int_key` FROM `table1_innodb_int_autoinc` AS X ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 8", packet_length=207, is_com_multi=false, is_next_command=false) at /data/src/bb-10.2-jan/sql/sql_parse.cc:1790
 
# 2016-08-28T00:47:43 [13578] #36 0x00007fcec450f8ec in do_command (thd=0x7fce7bc16070) at /data/src/bb-10.2-jan/sql/sql_parse.cc:1353
 
# 2016-08-28T00:47:43 [13578] #37 0x00007fcec465175a in do_handle_one_connection (connect=0x7fcec145c050) at /data/src/bb-10.2-jan/sql/sql_connect.cc:1354
 
# 2016-08-28T00:47:43 [13578] #38 0x00007fcec46514e7 in handle_one_connection (arg=0x7fcec145c050) at /data/src/bb-10.2-jan/sql/sql_connect.cc:1260
 
# 2016-08-28T00:47:43 [13578] #39 0x00007fcec3bcf0a4 in start_thread (arg=0x7fcec3f6f300) at pthread_create.c:309
 
# 2016-08-28T00:47:43 [13578] #40 0x00007fcec1d8787d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111


Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7fce7bc62088): REPLACE INTO `table0_innodb_hash_pk_parts_2_int_autoinc` ( `col_int` ) SELECT `col_int_key` FROM `table1_innodb_int_autoinc` AS X ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 8
 
Connection ID (thread ID): 14
 
Status: NOT_KILLED

Clone rqg from https://github.com/elenst/rqg

perl ./runall-new.pl --grammar=conf/mariadb/gtid_stress.yy --gendata=conf/mariadb/gtid_stress.zz --duration=600 --threads=8 --queries=100M --rpl_mode=mixed --use_gtid=current_pos \
 
--basedir=<basedir> --vardir=<vardir>



 Comments   
Comment by Jan Lindström (Inactive) [ 2016-08-28 ]

This is not a new problem: https://jira.mariadb.org/browse/MDEV-10544

Comment by Elena Stepanova [ 2016-08-28 ]

Sorry, on some reason it didn't come up in my search.

Comment by Elena Stepanova [ 2016-09-24 ]

Re-opened as agreed – since it's not wsrep-related, it is likely to be different from MDEV-10544.

Comment by Jan Lindström (Inactive) [ 2016-09-25 ]

Do you have repeatable test case for this (non galera) ?

Comment by Jan Lindström (Inactive) [ 2016-09-25 ]

Do you have repeatable test case for this (non galera) ?

Comment by Elena Stepanova [ 2016-10-14 ]

jplindst, the test is described in the description. It's marginally repeatable (or at least it was at the time of report creation). Naturally, it's non-deterministic, as it's essentially concurrent flow.

That said, I'm getting it a lot in various concurrent tests, so it's quite a pain.

Comment by Jan Lindström (Inactive) [ 2016-11-09 ]

For some reason could not repeat using 10.1 after several tries. Switching to 10.2 where we have VATS lock wait method as default.

Comment by Jan Lindström (Inactive) [ 2016-11-09 ]

For 10.2:
commit ada3d7581bd619a729f1243a730499eb4d07b054
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Nov 9 15:17:55 2016 +0200

MDEV-10692: InnoDB: Failing assertion: lock->trx->lock.wait_lock == lock

When we enter here wait_lock could be already gone i.e. NULL, that
should be allowed.

commit 8e5f532dc2cb5922ee59fd6c9a33e9d1614b7b05
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Nov 9 13:32:43 2016 +0200

MDEV-10692: InnoDB: Failing assertion: lock->trx->lock.wait_lock == lock

This is not a fix, this is instrumentation to find the bug.

Comment by Jan Lindström (Inactive) [ 2016-11-09 ]

10.1:
commit 1fee0171bcc9a71eb4f1e503232682e232c0bf6e
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Nov 9 15:23:25 2016 +0200

MDEV-10692: InnoDB: Failing assertion: lock->trx->lock.wait_lock == lock
When we enter here wait_lock could be already gone i.e. NULL, that
should be allowed.

Generated at Thu Feb 08 07:44:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.