[MDEV-15800] Assertion `next_insert_id >= auto_inc_interval_for_cur_row.minimum()' failed in update_auto_increment() or unexpected ER_LOCK_DEADLOCK upon LOAD or INSERT Created: 2018-04-06  Updated: 2023-04-19  Resolved: 2023-04-19

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.2
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: not-10.3, not-10.4, not-10.5

Issue Links:
Relates
relates to MDEV-17333 Assertion in update_auto_increment() ... Closed
relates to MDEV-19130 Assertion `next_insert_id >= auto_inc... Closed
relates to MDEV-22711 Assertion `nr != 0' failed in handler... Closed
relates to MDEV-27770 Assertion `next_insert_id >= auto_inc... Closed
relates to MDEV-17610 Unexpected connection abort after cer... Closed
relates to MDEV-24613 Assertion `next_insert_id >= auto_inc... Open

 Description   

While the test case appears to be deterministic, the result is not. The test can pass, or it can fail in different ways, depending on version, build and luck. The description below will list variations of the failures that I got. Some of them are reported in the scope of this JIRA item, others will be filed separately and linked to the issue.

Run the test case with --repeat=N.

--source include/have_partition.inc
 
--source include/have_innodb.inc
 
 
 
--let $datadir= `SELECT @@datadir`
 
--write_file $datadir/test/load.data
 
1
 
1
 
1
 
EOF
 
 
 
CREATE PROCEDURE sp() ALTER TABLE non_existing_table OPTIMIZE PARTITION p0;
 
CALL sp;
 
 
 
--connect (con1,localhost,root,,test)
 
CREATE TABLE t1 ( 
  pk INTEGER AUTO_INCREMENT,
 
  f INT,
 
  PRIMARY KEY(pk,f),
 
  UNIQUE(f)
 
) ENGINE=InnoDB PARTITION BY RANGE(f) (PARTITION p0 VALUES LESS THAN (100), PARTITION p1 VALUES LESS THAN (MAXVALUE)); 
 
 
--connection default
 
LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (f);
 
 
 
--connection con1
 
LOAD DATA INFILE 'load.data' IGNORE INTO TABLE t1 (f);
 
 
 
# Cleanup
 
--disconnect con1
 
--connection default
 
--remove_file $datadir/test/load.data
 
DROP TABLE t1;
 
DROP PROCEDURE sp;

10.2 1c6b982e02e

 
mysqld: /data/src/10.2/sql/handler.cc:3015: int handler::update_auto_increment(): Assertion `next_insert_id >= auto_inc_interval_for_cur_row.minimum()' failed.
 
181103 21:29:34 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f0897ab9ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055ec5a48f136 in handler::update_auto_increment (this=0x7f0844019bb8) at /data/src/10.2/sql/handler.cc:3015
 
#9  0x000055ec5abaae30 in ha_partition::write_row (this=0x7f0844019bb8, buf=0x7f0844021618 "\377") at /data/src/10.2/sql/ha_partition.cc:4142
 
#10 0x000055ec5a4960a5 in handler::ha_write_row (this=0x7f0844019bb8, buf=0x7f0844021618 "\377") at /data/src/10.2/sql/handler.cc:5961
 
#11 0x000055ec5a1ee5e8 in write_record (thd=0x7f0844000b00, table=0x7f0844057e60, info=0x7f08900df040) at /data/src/10.2/sql/sql_insert.cc:1930
 
#12 0x000055ec5a630b32 in read_sep_field (thd=0x7f0844000b00, info=..., table_list=0x7f0844011240, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=true) at /data/src/10.2/sql/sql_load.cc:1256
 
#13 0x000055ec5a62ecca in mysql_load (thd=0x7f0844000b00, ex=0x7f08440111b8, table_list=0x7f0844011240, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_ERROR, ignore=true, read_file_from_client=false) at /data/src/10.2/sql/sql_load.cc:649
 
#14 0x000055ec5a215323 in mysql_execute_command (thd=0x7f0844000b00) at /data/src/10.2/sql/sql_parse.cc:4833
 
#15 0x000055ec5a21f087 in mysql_parse (thd=0x7f0844000b00, rawbuf=0x7f08440110c8 "LOAD DATA INFILE 'load.data' IGNORE INTO TABLE t1 (f)", length=53, parser_state=0x7f08900e0200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8011
 
#16 0x000055ec5a20c9e1 in dispatch_command (command=COM_QUERY, thd=0x7f0844000b00, packet=0x7f08440088e1 "LOAD DATA INFILE 'load.data' IGNORE INTO TABLE t1 (f)", packet_length=53, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1824
 
#17 0x000055ec5a20b344 in do_command (thd=0x7f0844000b00) at /data/src/10.2/sql/sql_parse.cc:1378
 
#18 0x000055ec5a35d647 in do_handle_one_connection (connect=0x55ec5c823f80) at /data/src/10.2/sql/sql_connect.cc:1335
 
#19 0x000055ec5a35d3d4 in handle_one_connection (arg=0x55ec5c823f80) at /data/src/10.2/sql/sql_connect.cc:1241
 
#20 0x000055ec5a78066e in pfs_spawn_thread (arg=0x55ec5c82a140) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#21 0x00007f0899790494 in start_thread (arg=0x7f08900e1700) at pthread_create.c:333
 
#22 0x00007f0897b7693f in clone () from /lib/x86_64-linux-gnu/libc.so.6

On 10.3 debug the test case above usually either passes or fails with the assertion failure.
On 10.2 it can also pass or fail with the assertion failure, but more often it fails with 

mysqltest: At line 26: query 'LOAD DATA INFILE 'load.data' IGNORE INTO TABLE t1 (f)' failed: 1213: Deadlock found when trying to get lock; try restarting transaction

If you are getting the deadlock but want to get the assertion failure, add --error 0,ER_LOCK_DEADLOCK before the second LOAD.

On 10.2 and 10.3 non-debug builds, the test case either passes or fails with 

mysqltest: At line 33: query 'DROP TABLE t1' failed: 1213: Deadlock found when trying to get lock; try restarting transaction

On 10.2 it happens much more often than on 10.3.

ASAN builds don't provide any additional information, they fail in the same way as corresponding non-ASAN builds.

On 5.5/10.0/10.1 debug and non-debug builds the test case fails differently, it reports

mysqltest: At line 23: query 'LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (f)' failed: 2013: Lost connection to MySQL server during query

It is not a crash, the server survives. Apparently, something goes wrong after the SP call. I don't know if it's anyhow related to 10.2/10.3 failures, I filed it separately as MDEV-17610, seems to be the client issue.

MySQL 5.6.39 and 5.7.24 fail with a different assertion failure. I think it is related more to MDEV-17610 than to MDEV-15800.

Please note that while the test case uses InnoDB, partitioning and LOAD DATA, the assertion failure is not restricted to either of them. It can be reproduced, for example, if InnoDB + partitioning is replaced by RocksDB. Also, in concurrent tests I had occurrences upon INSERT rather than LOAD, see the stack trace below.

10.3 a5da1c64f8d96278c8e4408458f7e8d4b6dea415

 
mysqld: /home/travis/src/sql/handler.cc:3160: int handler::update_auto_increment(): Assertion `next_insert_id >= auto_inc_interval_for_cur_row.minimum()' failed.
 
180404  9:11:31 [ERROR] mysqld got signal 6 ;
 
 
 
Query (0x7fdf14140508): INSERT LOW_PRIORITY IGNORE INTO `table0_int_autoinc` ( `col_int_key` ) SELECT `col_int_key` FROM `table0_int_autoinc` AS X ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 5 /* QNO 3285 CON_ID 19 */  /* QNO 3290 CON_ID 19 */
 
Connection ID (thread ID): 19
 
Status: NOT_KILLED


#7  0x00007fdf38217ca2 in __GI___assert_fail (assertion=0x55dd82ab0990 "next_insert_id >= auto_inc_interval_for_cur_row.minimum()", file=0x55dd82aaf938 "/home/travis/src/sql/handler.cc", line=3160, function=0x55dd82ab28a0 <handler::update_auto_increment()::__PRETTY_FUNCTION__> "int handler::update_auto_increment()") at assert.c:101
 
#8  0x000055dd820ec6b8 in handler::update_auto_increment (this=0x7fdeec0af478) at /home/travis/src/sql/handler.cc:3160
 
#9  0x00007fdf35926d8e in myrocks::ha_rocksdb::write_row (this=0x7fdeec0af478, buf=0x7fdeec075988 "\377") at /home/travis/src/storage/rocksdb/ha_rocksdb.cc:8509
 
#10 0x000055dd820f3fed in handler::ha_write_row (this=0x7fdeec0af478, buf=0x7fdeec075988 "\377") at /home/travis/src/sql/handler.cc:6197
 
#11 0x000055dd81dbed7b in write_record (thd=0x7fdf14005270, table=0x7fdeec0c46a0, info=0x7fdf14140728) at /home/travis/src/sql/sql_insert.cc:2022
 
#12 0x000055dd81dc3fc8 in select_insert::send_data (this=0x7fdf141406e8, values=...) at /home/travis/src/sql/sql_insert.cc:3857
 
#13 0x000055dd81e6e255 in end_send (join=0x7fdf14140790, join_tab=0x7fdf14141ea0, end_of_records=false) at /home/travis/src/sql/sql_select.cc:20407
 
#14 0x000055dd81e6bbb2 in evaluate_join_record (join=0x7fdf14140790, join_tab=0x7fdf14141af0, error=0) at /home/travis/src/sql/sql_select.cc:19458
 
#15 0x000055dd81e8078a in AGGR_OP::end_send (this=0x7fdf14142440) at /home/travis/src/sql/sql_select.cc:27260
 
#16 0x000055dd81e6af69 in sub_select_postjoin_aggr (join=0x7fdf14140790, join_tab=0x7fdf14141af0, end_of_records=true) at /home/travis/src/sql/sql_select.cc:18953
 
#17 0x000055dd81e6b29b in sub_select (join=0x7fdf14140790, join_tab=0x7fdf14141740, end_of_records=true) at /home/travis/src/sql/sql_select.cc:19189
 
#18 0x000055dd81e6aa84 in do_select (join=0x7fdf14140790, procedure=0x0) at /home/travis/src/sql/sql_select.cc:18780
 
#19 0x000055dd81e43b4a in JOIN::exec_inner (this=0x7fdf14140790) at /home/travis/src/sql/sql_select.cc:3989
 
#20 0x000055dd81e42fea in JOIN::exec (this=0x7fdf14140790) at /home/travis/src/sql/sql_select.cc:3783
 
#21 0x000055dd81e4425e in mysql_select (thd=0x7fdf14005270, tables=0x7fdf14110088, wild_num=0, fields=..., conds=0x0, og_num=5, order=0x7fdf1413f788, group=0x0, having=0x0, proc_param=0x0, select_options=553246395904, result=0x7fdf141406e8, unit=0x7fdf1410e9e0, select_lex=0x7fdf1410f158) at /home/travis/src/sql/sql_select.cc:4188
 
#22 0x000055dd81e364f7 in handle_select (thd=0x7fdf14005270, lex=0x7fdf1410e918, result=0x7fdf141406e8, setup_tables_done_option=1073741824) at /home/travis/src/sql/sql_select.cc:382
 
#23 0x000055dd81dfaff3 in mysql_execute_command (thd=0x7fdf14005270) at /home/travis/src/sql/sql_parse.cc:4833
 
#24 0x000055dd81d28474 in sp_instr_stmt::exec_core (this=0x7fdf140d3fa8, thd=0x7fdf14005270, nextp=0x7fdf19f1e69c) at /home/travis/src/sql/sp_head.cc:3595
 
#25 0x000055dd81d2788c in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fdf140d3ff8, thd=0x7fdf14005270, nextp=0x7fdf19f1e69c, open_tables=false, instr=0x7fdf140d3fa8) at /home/travis/src/sql/sp_head.cc:3311
 
#26 0x000055dd81d28031 in sp_instr_stmt::execute (this=0x7fdf140d3fa8, thd=0x7fdf14005270, nextp=0x7fdf19f1e69c) at /home/travis/src/sql/sp_head.cc:3498
 
#27 0x000055dd81d21e20 in sp_head::execute (this=0x7fdf1413d8e8, thd=0x7fdf14005270, merge_da_on_success=true) at /home/travis/src/sql/sp_head.cc:1349
 
#28 0x000055dd81d247a3 in sp_head::execute_procedure (this=0x7fdf1413d8e8, thd=0x7fdf14005270, args=0x7fdf14009e50) at /home/travis/src/sql/sp_head.cc:2287
 
#29 0x000055dd81df5653 in do_execute_sp (thd=0x7fdf14005270, sp=0x7fdf1413d8e8) at /home/travis/src/sql/sql_parse.cc:2940
 
#30 0x000055dd81df61cb in Sql_cmd_call::execute (this=0x7fdf140168c0, thd=0x7fdf14005270) at /home/travis/src/sql/sql_parse.cc:3182
 
#31 0x000055dd81e0049f in mysql_execute_command (thd=0x7fdf14005270) at /home/travis/src/sql/sql_parse.cc:6284
 
#32 0x000055dd81e05038 in mysql_parse (thd=0x7fdf14005270, rawbuf=0x7fdf14016758 "CALL stored_proc_26383 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */ /* QNO 3292 CON_ID 19 */", length=87, parser_state=0x7fdf19f205e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8013
 
#33 0x000055dd81df272e in dispatch_command (command=COM_QUERY, thd=0x7fdf14005270, packet=0x7fdf1400df91 "CALL stored_proc_26383 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */ /* QNO 3292 CON_ID 19 */ ", packet_length=88, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1842
 
#34 0x000055dd81df117a in do_command (thd=0x7fdf14005270) at /home/travis/src/sql/sql_parse.cc:1387
 
#35 0x000055dd81f56921 in do_handle_one_connection (connect=0x55dd85456940) at /home/travis/src/sql/sql_connect.cc:1402
 
#36 0x000055dd81f566ae in handle_one_connection (arg=0x55dd85456940) at /home/travis/src/sql/sql_connect.cc:1308
 
#37 0x00007fdf38dd9184 in start_thread (arg=0x7fdf19f21700) at pthread_create.c:312
 
#38 0x00007fdf382e603d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111



 Comments   
Comment by Elena Stepanova [ 2018-11-03 ]

Please also see MDEV-17333, possibly the coming bugfix for MDEV-17333 will fix this issue as well.

Comment by Alice Sherepa [ 2020-11-23 ]

not reproducible on the current 10.2 (fa6d710b85bb5d689661ce)-10.4 (031e1427ed9a7b93) - (I've tried with --repeat=100)

Comment by Elena Stepanova [ 2020-11-23 ]

It just means we need a new test case. The assertion failure still happens in tests regularly enough.

Comment by Elena Stepanova [ 2020-11-23 ]

Apparently there can be different problems, or at least essentially different scenarios, causing the same assertion failure.
One is filed separately as MDEV-24038. Random tests have a variety of problems which boil down to the same issue, when an auto-increment column goes out of range, something like this:

CREATE TABLE t1 (id INT AUTO_INCREMENT, e TIMESTAMP, PRIMARY KEY(id));
 
INSERT INTO t1 (e) VALUES (NOW());
 
UPDATE IGNORE t1 SET id = e;
 
INSERT IGNORE INTO t1 (e) VALUES (NOW()),(NOW()) ON DUPLICATE KEY UPDATE e = NOW();

Then there is another, quite different scenario,, it is somewhat similar to the original test case.
Test case 2 – it fails on 10.1-10.2 (reliably, at least for me, now), but it stopped failing on 10.3+ after the fix for MDEV-17333.

--source include/have_partition.inc
 
 
 
CREATE TABLE t1 (
 
  id INT AUTO_INCREMENT,
 
  a INT,
 
  PRIMARY KEY(id,a),
 
  UNIQUE(a)
 
) PARTITION BY RANGE(a) (
 
  PARTITION p1 VALUES LESS THAN (49),
 
  PARTITION pmax VALUES LESS THAN (MAXVALUE)
 
);
 
--let $datadir= `SELECT @@datadir`
 
--write_file $datadir/test/load_t1
 
0	\N
 
2	\N
 
0	\N
 
4	\N
 
EOF
 
LOAD DATA INFILE 'load_t1' IGNORE INTO TABLE t1;
 
 
 
# Cleanup
 
DROP TABLE t1;
 
--remove_file $datadir/test/load_t1

10.2 1248c654

 
#7  0x00007f7acee60f36 in __GI___assert_fail (assertion=0x5646c51bea60 "next_insert_id >= auto_inc_interval_for_cur_row.minimum()", file=0x5646c51bd490 "/data/src/10.2/sql/handler.cc", line=3115, function=0x5646c51bea38 "int handler::update_auto_increment()") at assert.c:101
 
#8  0x00005646c4900240 in handler::update_auto_increment (this=0x7f7ab8039318) at /data/src/10.2/sql/handler.cc:3115
 
#9  0x00005646c5011372 in ha_partition::write_row (this=0x7f7ab8039318, buf=0x7f7ab80a52a8 "\377\004") at /data/src/10.2/sql/ha_partition.cc:4149
 
#10 0x00005646c490776b in handler::ha_write_row (this=0x7f7ab8039318, buf=0x7f7ab80a52a8 "\377\004") at /data/src/10.2/sql/handler.cc:6109
 
#11 0x00005646c4653051 in write_record (thd=0x7f7ab8000d90, table=0x7f7ab8038710, info=0x7f7ac8fb94a0) at /data/src/10.2/sql/sql_insert.cc:1939
 
#12 0x00005646c4a96f74 in read_sep_field (thd=0x7f7ab8000d90, info=..., table_list=0x7f7ab8012858, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=true) at /data/src/10.2/sql/sql_load.cc:1175
 
#13 0x00005646c4a95582 in mysql_load (thd=0x7f7ab8000d90, ex=0x7f7ab80127d0, table_list=0x7f7ab8012858, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_ERROR, ignore=true, read_file_from_client=false) at /data/src/10.2/sql/sql_load.cc:682
 
#14 0x00005646c4679367 in mysql_execute_command (thd=0x7f7ab8000d90) at /data/src/10.2/sql/sql_parse.cc:4604
 
#15 0x00005646c4683253 in mysql_parse (thd=0x7f7ab8000d90, rawbuf=0x7f7ab80126f8 "LOAD DATA INFILE 'load_t1' IGNORE INTO TABLE t1", length=47, parser_state=0x7f7ac8fba5f0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7761
 
#16 0x00005646c46714e8 in dispatch_command (command=COM_QUERY, thd=0x7f7ab8000d90, packet=0x7f7ab8008b51 "LOAD DATA INFILE 'load_t1' IGNORE INTO TABLE t1", packet_length=47, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
 
#17 0x00005646c466ffe3 in do_command (thd=0x7f7ab8000d90) at /data/src/10.2/sql/sql_parse.cc:1381
 
#18 0x00005646c47ca309 in do_handle_one_connection (connect=0x5646c73a08e0) at /data/src/10.2/sql/sql_connect.cc:1336
 
#19 0x00005646c47ca06e in handle_one_connection (arg=0x5646c73a08e0) at /data/src/10.2/sql/sql_connect.cc:1241
 
#20 0x00005646c4ff1a76 in pfs_spawn_thread (arg=0x5646c7383c70) at /data/src/10.2/storage/perfschema/pfs.cc:1869
 
#21 0x00007f7acf370609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#22 0x00007f7acef4c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Both affect tests, but I don't realistically expect the 10.2-only variety to be fixed, so I'm going to demote this report to minor, while the other problem will keep being tracked in MDEV-24038.

Generated at Thu Feb 08 08:24:06 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.