Marko Mäkelä added a comment - 2018-06-25 11:02 Some data from the core dump: Thread 32 (LWP 23409): #0 0x00007fe225f45404 in pthread_cond_wait@@GLIBC_2.3.2 () from /home/mariadb/for_marko/travis_libs/lib/x86_64-linux-gnu/libpthread.so.0 #1 0x000055a07b6b4679 in os_event::wait (this=0x7fe1c402b250) at /home/travis/src/storage/innobase/os/os0event.cc:163 #2 0x000055a07b6b408b in os_event::wait_low (this=0x7fe1c402b250, reset_sig_count=721) at /home/travis/src/storage/innobase/os/os0event.cc:333 #3 0x000055a07b6b4432 in os_event_wait_low (event=0x7fe1c402b250, reset_sig_count=0) at /home/travis/src/storage/innobase/os/os0event.cc:522 #4 0x000055a07b680c13 in lock_wait_suspend_thread (thr=0x7fe1cc134fb0) at /home/travis/src/storage/innobase/lock/lock0wait.cc:355 #5 0x000055a07b73d7d3 in row_mysql_handle_errors (new_err=0x7fe20d856874, trx=0x7fe20f9843b8, thr=0x7fe1cc134fb0, savept=0x0) at /home/travis/src/storage/innobase/row/row0mysql.cc:733 #6 0x000055a07b73e99e in row_lock_table_autoinc_for_mysql ( prebuilt=0x7fe1cc134488) at /home/travis/src/storage/innobase/row/row0mysql.cc:1202 #7 0x000055a07b5eaf4a in ha_innobase::innobase_lock_autoinc ( this=0x7fe1cc1a0a78) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:7964 #8 0x000055a07b5eafda in ha_innobase::innobase_set_max_autoinc ( this=0x7fe1cc1a0a78, auto_inc=12) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:7992 #9 0x000055a07b5eb6ad in ha_innobase::write_row (this=0x7fe1cc1a0a78, record=0x7fe1cc1a0630 "\377") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:8197 #10 0x000055a07b3e29e4 in handler::ha_write_row (this=0x7fe1cc1a0a78, buf=0x7fe1cc1a0630 "\377") at /home/travis/src/sql/handler.cc:6195 #11 0x000055a07bb37715 in ha_partition::write_row (this=0x7fe1cc19b638, buf=0x7fe1cc1a0630 "\377") at /home/travis/src/sql/ha_partition.cc:4310 #12 0x000055a07b3e29e4 in handler::ha_write_row (this=0x7fe1cc19b638, buf=0x7fe1cc1a0630 "\377") at /home/travis/src/sql/handler.cc:6195 #13 0x000055a07b0a541f in write_record (thd=0x7fe1cc00b430, table=0x7fe1cc19f9d0, info=0x7fe20d856ec0) at /home/travis/src/sql/sql_insert.cc:1694 #14 0x000055a07b0d22f3 in read_sep_field (thd=0x7fe1cc00b430, info=..., table_list=0x7fe1cc01e320, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false) at /home/travis/src/sql/sql_load.cc:1157 #15 0x000055a07b0d08c2 in mysql_load (thd=0x7fe1cc00b430, ex=0x7fe1cc01e258, table_list=0x7fe1cc01e320, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, read_file_from_client=false) at /home/travis/src/sql/sql_load.cc:665 #16 0x000055a07b0e53ef in mysql_execute_command (thd=0x7fe1cc00b430) at /home/travis/src/sql/sql_parse.cc:5121 #17 0x000055a07b0ee73a in mysql_parse (thd=0x7fe1cc00b430, rawbuf=0x7fe1cc01e0a8 "LOAD DATA INFILE 'load_table1_key_pk_parts_2_int_autoinc' REPLACE INTO TABLE table1_key_pk_parts_2_int_autoinc /* QNO 15113 CON_ID 19 */", length=136, parser_state=0x7fe20d858600, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8076 #18 0x000055a07b0dba4f in dispatch_command (command=COM_QUERY, thd=0x7fe1cc00b430, packet=0x7fe1cc0158e1 " LOAD DATA INFILE 'load_table1_key_pk_parts_2_int_autoinc' REPLACE INTO TABLE table1_key_pk_parts_2_int_autoinc /* QNO 15113 CON_ID 19 */ ", packet_length=138, is_com_multi=false, is_next_command=false) This wait was interrupted by the timeout thread: #6 0x000055a07b813b95 in ut_dbg_assertion_failed ( expr=0x55a07be1e8d0 "table->n_waiting_or_granted_auto_inc_locks > 0", file=0x55a07be1d378 "/home/travis/src/storage/innobase/lock/lock0lock.cc", line=3717) at /home/travis/src/storage/innobase/ut/ut0dbg.cc:61 #7 0x000055a07b66ff50 in lock_table_remove_low (lock=0x55a07d960c08) at /home/travis/src/storage/innobase/lock/lock0lock.cc:3717 #8 0x000055a07b670dc9 in lock_table_dequeue (in_lock=0x55a07d960c08) at /home/travis/src/storage/innobase/lock/lock0lock.cc:4030 #9 0x000055a07b676ec3 in lock_release_autoinc_last_lock ( autoinc_locks=0x7fe1cc011658) at /home/travis/src/storage/innobase/lock/lock0lock.cc:5945 #10 0x000055a07b676fc5 in lock_release_autoinc_locks (trx=0x7fe20f9843b8) at /home/travis/src/storage/innobase/lock/lock0lock.cc:5987 #11 0x000055a07b67764d in lock_cancel_waiting_and_release (lock=0x55a07d960c08) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6209 #12 0x000055a07b6812fe in lock_wait_check_and_cancel (slot=0x55a07e21caf8) at /home/travis/src/storage/innobase/lock/lock0wait.cc:508 #13 0x000055a07b681465 in lock_wait_timeout_thread () at /home/travis/src/storage/innobase/lock/lock0wait.cc:565 The table in question is the first partition: (gdb) p *lock->un_member.tab_lock.table $3 = {id = 1862, heap = 0x7fe1cc0d6860, name = { m_name = 0x7fe1cc034c70 "test/table1_key_pk_parts_2_int_autoinc#P#p0", static part_suffix = "#P#"}, data_dir_path = 0x0, space = 0x7fe1cc1675e0, space_id = 1845, flags = 33, flags2 = 80, skip_alter_undo = 0, … } The counter dict_table_t::n_waiting_or_granted_auto_inc_locks is only incremented in lock_table_create() as part of row_lock_table_autoinc_for_mysql() and only decremented in lock_table_remove_low() . The counter is only checked if innodb_autoinc_lock_mode=1 . lock_table_create() uses two different conditions for auto-increment locks: if ((type_mode & LOCK_MODE_MASK) == LOCK_AUTO_INC) { ++table->n_waiting_or_granted_auto_inc_locks; }   /* For AUTOINC locking we reuse the lock instance only if there is no wait involved else we allocate the waiting lock from the transaction lock heap. */ if (type_mode == LOCK_AUTO_INC) {   lock = table->autoinc_lock;   table->autoinc_trx = trx;   ib_vector_push(trx->autoinc_locks, &lock); Waiting auto-increment lock requests would not be added to trx->autoinc_locks , but they should be added to trx->lock.trx_locks and table->locks . In our case, lock_table_remove_low() is dealing with lock->type_mode == LOCK_TABLE | LOCK_WAIT | LOCK_AUTO_INC : if (!lock_get_wait(lock) && !ib_vector_is_empty(trx->autoinc_locks)) {   lock_table_remove_autoinc_lock(lock, trx); }   ut_a(table->n_waiting_or_granted_auto_inc_locks > 0); table->n_waiting_or_granted_auto_inc_locks--; }   UT_LIST_REMOVE(trx->lock.trx_locks, lock); ut_list_remove(table->locks, lock, TableLockGetNode()); We did correctly skip the trx->autoinc_locks because this was a waiting request. However, contrary to expectations, the counter had already reached 0, and trx->lock.trx_locks does not contain this lock (only 1 table IX lock and 2 record lock bitmaps for the clustered index root page). Furthermore, in table->locks the only table lock from this transaction is the table IX lock, that is, table->locks->start points to trx->lock.trx_locks.start . The issue seems to be that the waiting auto-increment lock request was registered in n_waiting_or_granted_auto_inc_locks but the lock does not exist. It must be some race condition that I am missing. The conflicting auto-increment lock is apparently being held by an active transaction that is waiting for a record lock: (gdb) p lock.un_member.tab_lock.table.autoinc_lock.trx.mysql_thd.query_string $49 = {string = { str = 0x7fe1c4013a78 "UPDATE LOW_PRIORITY `view_table1_key_pk_parts_2_int_autoinc` AS X SET `col_int` = 0 WHERE X.`col_char_12` BETWEEN 140 AND 1146355712 ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`p"..., length = 236}, cs = 0x55a07c6f3720 <my_charset_latin1>} It is waiting for a record X lock in the clustered index root page: p *lock.un_member.tab_lock.table.autoinc_lock.trx.lock.wait_lock $50 = {trx = 0x7fe20f983578, trx_locks = {prev = 0x55a07d95b540, next = 0x0}, index = 0x7fe1cc0ef7a8, hash = 0x55a07d95bf60, requested_time = 0, wait_time = 0, un_member = {tab_lock = {table = 0x300000735, locks = { prev = 0x48, next = 0x0}}, rec_lock = {space = 1845, page_no = 3, n_bits = 72}}, type_mode = 291} Here: Thread 26 (LWP 23403): #0 0x00007fe225f45404 in pthread_cond_wait@@GLIBC_2.3.2 () from /home/mariadb/for_marko/travis_libs/lib/x86_64-linux-gnu/libpthread.so.0 #1 0x000055a07b6b4679 in os_event::wait (this=0x7fe1d8058130) at /home/travis/src/storage/innobase/os/os0event.cc:163 #2 0x000055a07b6b408b in os_event::wait_low (this=0x7fe1d8058130, reset_sig_count=122) at /home/travis/src/storage/innobase/os/os0event.cc:333 #3 0x000055a07b6b4432 in os_event_wait_low (event=0x7fe1d8058130, reset_sig_count=0) at /home/travis/src/storage/innobase/os/os0event.cc:522 #4 0x000055a07b680c13 in lock_wait_suspend_thread (thr=0x7fe1b42add20) at /home/travis/src/storage/innobase/lock/lock0wait.cc:355 #5 0x000055a07b73d7d3 in row_mysql_handle_errors (new_err=0x7fe20d93376c, trx=0x7fe20f983578, thr=0x7fe1b42add20, savept=0x0) at /home/travis/src/storage/innobase/row/row0mysql.cc:733 #6 0x000055a07b77deec in row_search_mvcc (buf=0x7fe1b43720b0 "\357", mode=PAGE_CUR_G, prebuilt=0x7fe1b42ad588, match_mode=0, direction=0) at /home/travis/src/storage/innobase/row/row0sel.cc:5623 #7 0x000055a07b5ede68 in ha_innobase::index_read (this=0x7fe1b4382128, buf=0x7fe1b43720b0 "\357", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9315 #8 0x000055a07b5ef11c in ha_innobase::index_first (this=0x7fe1b4382128, buf=0x7fe1b43720b0 "\357") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9732 #9 0x000055a07b5ef327 in ha_innobase::rnd_next (this=0x7fe1b4382128, buf=0x7fe1b43720b0 "\357") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9825 #10 0x000055a07b3d93b9 in handler::ha_rnd_next (this=0x7fe1b4382128, buf=0x7fe1b43720b0 "\357") at /home/travis/src/sql/handler.cc:2764 #11 0x000055a07bb39304 in ha_partition::rnd_next (this=0x7fe1b4285038, buf=0x7fe1b43720b0 "\357") at /home/travis/src/sql/ha_partition.cc:5058 #12 0x000055a07b3d93b9 in handler::ha_rnd_next (this=0x7fe1b4285038, buf=0x7fe1b43720b0 "\357") at /home/travis/src/sql/handler.cc:2764 #13 0x000055a07b3cd733 in find_all_keys (thd=0x7fe1c4000d90, param=0x7fe20d934bb0, select=0x7fe1c40195a0, fs_info=0x7fe1c4093a30, buffpek_pointers=0x7fe20d934db0, tempfile=0x7fe20d934c40, pq=0x7fe20d934b60, found_rows=0x7fe1c4093c10) at /home/travis/src/sql/filesort.cc:778 #14 0x000055a07b3cbd57 in filesort (thd=0x7fe1c4000d90, table=0x7fe1b41d13d0, filesort=0x7fe20d9350c0, tracker=0x7fe1c4019a20, join=0x0, first_table_bit=0) at /home/travis/src/sql/filesort.cc:278 #15 0x000055a07b1d8df2 in mysql_update (thd=0x7fe1c4000d90, table_list=0x7fe1c4013da8, fields=..., values=..., conds=0x7fe1c4014878, order_num=5, order=0x7fe1c4014b18, limit=5, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fe20d9356d0, updated_return=0x7fe20d935790) at /home/travis/src/sql/sql_update.cc:669 #16 0x000055a07b0e3461 in mysql_execute_command (thd=0x7fe1c4000d90) at /home/travis/src/sql/sql_parse.cc:4575 #17 0x000055a07b0ee73a in mysql_parse (thd=0x7fe1c4000d90, rawbuf=0x7fe1c4013a78 "UPDATE LOW_PRIORITY `view_table1_key_pk_parts_2_int_autoinc` AS X SET `col_int` = 0 WHERE X.`col_char_12` BETWEEN 140 AND 1146355712 ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`p"..., length=236, parser_state=0x7fe20d936600, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8076

Elena Stepanova added a comment - 2018-07-20 21:13 I've got a test case which reliably causes the assertion failure with the stack trace as shown in the description for 10.3, but the test case only fails on 10.1 . --source include/have_innodb.inc   CREATE TABLE t1 (pk INTEGER AUTO_INCREMENT PRIMARY KEY ) ENGINE=InnoDB; INSERT INTO t1 VALUES ( NULL ),( NULL );   CREATE TABLE t2 LIKE t1; SET AUTOCOMMIT= OFF ;   --connect (con1,localhost,root,,test)   SET AUTOCOMMIT= OFF ; DELETE FROM t2;   --connection default --send LOCK TABLE t2 READ ;   --connection con1 SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2; --error ER_LOCK_WAIT_TIMEOUT INSERT INTO t2 SELECT * FROM t1;   # Cleanup --disconnect con1 --connection default --reap UNLOCK TABLES; DROP TABLE t1, t2; 10.1 4d06b7e1bd 2018-07-21 00:09:23 7f7f123ff700 InnoDB: Assertion failure in thread 140183743756032 in file lock0lock.cc line 5135 InnoDB: Failing assertion: table->n_waiting_or_granted_auto_inc_locks > 0   #5 0x00007f7f1f64a3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6 #6 0x00007f7f18b51b22 in lock_table_remove_low (lock=0x7f7f0982e7a0) at /data/src/10.1/storage/innobase/lock/lock0lock.cc:5135 #7 0x00007f7f18b52699 in lock_table_dequeue (in_lock=0x7f7f0982e7a0) at /data/src/10.1/storage/innobase/lock/lock0lock.cc:5477 #8 0x00007f7f18b57b65 in lock_release_autoinc_last_lock (autoinc_locks=0x7f7f098c7198) at /data/src/10.1/storage/innobase/lock/lock0lock.cc:7552 #9 0x00007f7f18b57c4e in lock_release_autoinc_locks (trx=0x7f7f09838a78) at /data/src/10.1/storage/innobase/lock/lock0lock.cc:7594 #10 0x00007f7f18b581f6 in lock_cancel_waiting_and_release (lock=0x7f7f0982e7a0) at /data/src/10.1/storage/innobase/lock/lock0lock.cc:7846 #11 0x00007f7f18b5bb33 in lock_wait_check_and_cancel (slot=0x7f7f17e7e1b0) at /data/src/10.1/storage/innobase/lock/lock0wait.cc:504 #12 0x00007f7f18b5bc7c in lock_wait_timeout_thread () at /data/src/10.1/storage/innobase/lock/lock0wait.cc:561 #13 0x00007f7f21345494 in start_thread (arg=0x7f7f123ff700) at pthread_create.c:333 #14 0x00007f7f1f6fe93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Matthias Leich added a comment - 2018-08-09 14:21 Simplified test =========== YY grammar ---------------- query: INSERT INTO _table SELECT * FROM _table;   _table: table100_innodb_key_pk_parts_2_int_autoinc | table100_innodb_int_autoinc ;   ZZ grammar ---------------- $tables = { rows => [100], partitions => [ undef , 'KEY (pk) PARTITIONS 2' ] };   $fields = { types => [ 'enum' ], indexes => [ undef, 'key' ], charsets => [ undef ], }; $tables = { rows => [100], partitions => [ undef , 'KEY (pk) PARTITIONS 2' ] };   With some luck I might be able to develop some MTR based replay test but I prefer to wait if the current information is already sufficient.

Marko Mäkelä added a comment - 2018-09-04 08:46 - edited elenst , the test that failed for you in 10.1 4d06b7e1bd appears to have been fixed in MDEV-13333 without any test case . The failure was introduced by my code clean-up in 10.1.32, 10.2.14, 10.3.6.

Matthias Leich added a comment - 2018-09-04 10:36 I have uploaded MDEV-11080.tgz which is an archive with the replay test.   How to replay ----------------- git clone https://github.com/mleich1/rqg --branch experimental RQG_MDEV-11080   cd RQG_MDEV-11080   tar xvzf <archive>   BASEDIR inside of MDEV-11080.sh needs to be adjusted and maybe more. Warning: The script MDEV-11080.sh is aggressive and kills mysqld's + cleans /dev/shm/vardir.   ./MDEV-11080.sh   A line between the final messages STATISTICS: 1 -- 'replay'-- Replay of desired effect (Whitelist match, no Blacklist match) means == RQG has observed that the server process has disappeared + the RQG log contains in its search region a line with "<signal handler called>".   RQG logs und archives with cores etc. can be found in the workdirectory of the last rqg_batch.pl run (storage/<timestamp>). rqg_batch.pl generates on every run a symlink 'last_batch_workdir' which points to that workdir.

Matthias Leich added a comment - 2018-09-04 15:11 Replaying the problem on actual (2018-09-04) 10.1/10.2/10.3 with the RQG test attached was impossible.   Trying on 10.1 with the RQG replay testcase from current report and MTR based replay testcase from MDEV-13333 showed - commit a54abf01753a69c2186d60c155212149be59a7a6 (Tue Mar 13 14:00:45 2018 +0200) Both replay tests pass without failure - the next commit is 723f87e9d318aedad30dfb9dde104312d6612662 (Wed Mar 14 09:39:47 2018 +0200) Both tests start to reveal the corresponding problem.

Marko Mäkelä added a comment - 2018-09-04 17:31 This shares the same cause and fix with MDEV-13333 . I pushed the test case only.