Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. 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

    Details

      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
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                serg Sergei Golubchik
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated: