Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-14100

Assertion `!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1' failed

Details

    Description

      10.2 7c85a8d936b1a

      mysqld: /data/src/10.2/storage/innobase/rem/rem0rec.cc:598: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1' failed.
      171110  3:25:12 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007fe3f2b07ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x000055da9940e3f8 in rec_get_offsets_func (rec=0x7fe3c0005e37 "", index=0x7fe39414e598, offsets=0x7fe3c0004e80, leaf=false, n_fields=1, file=0x55da99a7d3c8 "/data/src/10.2/storage/innobase/dict/dict0stats.cc", line=1197, heap=0x7fe3d9ffa550) at /data/src/10.2/storage/innobase/rem/rem0rec.cc:595
      #9  0x000055da995f8554 in dict_stats_analyze_index_level (index=0x7fe39414e598, level=1, n_diff=0x7fe3c0006b20, total_recs=0x7fe3d9ffa6f8, total_pages=0x7fe3d9ffa700, n_diff_boundaries=0x7fe3c0006b78, mtr=0x7fe3d9ffa780) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:1197
      #10 0x000055da995f9f94 in dict_stats_analyze_index (index=0x7fe39414e598) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2155
      #11 0x000055da995fa519 in dict_stats_update_persistent (table=0x7fe394150be8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2266
      #12 0x000055da995fcb3a in dict_stats_update (table=0x7fe394150be8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:3227
      #13 0x000055da996005ac in dict_stats_process_entry_from_recalc_pool () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:382
      #14 0x000055da9960076a in dict_stats_thread () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:468
      #15 0x00007fe3f47de494 in start_thread (arg=0x7fe3d9ffb700) at pthread_create.c:333
      #16 0x00007fe3f2bc493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      The test case is concurrent, but it fails very well for me as long as the machine isn't being under a heavy load. Run in -mem and if it still doesn't fail right away, with -repeat=N.

      --source include/have_innodb.inc
       
      SET @innodb_stats_persistent.save= @@innodb_stats_persistent;
      SET GLOBAL innodb_stats_persistent= ON;
      SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
       
      CREATE TABLE t1 (
        pk INT,
        c1 VARCHAR(8),
        c2 VARCHAR(8),
        i1 INT,
        t1 TIME,
        t2 TIME,
        c3 VARCHAR(8),
        c4 VARCHAR(8),
        t3 TIME,
        v1 TIME AS (t3) VIRTUAL,
        i2 INT,
        c5 VARCHAR(8),
        t4 TIME,
        c6 VARCHAR(8),
        i3 INT,
        t5 TIME,
        c7 VARCHAR(8),
        n1 DOUBLE,
        i4 INT,
        i5 INT,
        t6 TIME DEFAULT '00:00:00'
      ) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
       
      INSERT INTO t1 () VALUES (),(),(),(),(),(),(),(),(),(),(),();
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 () VALUES (),(),(),(),(),(),(),();
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 () VALUES (),(),(),();
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 () VALUES ();
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      ALTER TABLE t1 ADD COLUMN n2 DOUBLE DEFAULT 0;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 () VALUES (),();
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 (t6) SELECT v1 FROM t1;
      ALTER TABLE t1 ADD COLUMN i6 INT NOT NULL DEFAULT 0, ALGORITHM=COPY;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      --send
      	ALTER TABLE t1 FORCE;
       
      --connect (con1,localhost,root,,test)
      SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
      --error 0,ER_LOCK_WAIT_TIMEOUT
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      --error 0,ER_LOCK_WAIT_TIMEOUT
      INSERT INTO t1 (pk) SELECT pk FROM t1;
      --disconnect con1
       
      --connection default
      --error 0,ER_LOCK_WAIT_TIMEOUT
      --reap
       
      # Cleanup
      DROP TABLE t1;
      SET GLOBAL innodb_stats_persistent= @innodb_stats_persistent.save;
      

      10.3 is also affected.

      On bb-10.2-marko it mostly fails with the assertion below:

      bb-10.2-marko 5d142f9958d5cbb

      mysqld: /data/src/bb-10.2-marko/storage/innobase/row/row0log.cc:2313: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*): Assertion `0' failed.
      171110  3:26:12 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007f3e8dee4ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x000055c33c21d683 in row_log_table_apply_op (thr=0x7f3e38079e00, trx_id_col=1, new_trx_id_col=1, dup=0x7f3e803422e0, error=0x7f3e80342084, offsets_heap=0x7f3e38042540, heap=0x7f3e3803e4b0, mrec=0x7f3e801b712b "", mrec_end=0x7f3e8027a0e6 "", offsets=0x7f3e3800bb50) at /data/src/bb-10.2-marko/storage/innobase/row/row0log.cc:2313
      #9  0x000055c33c21f581 in row_log_table_apply_ops (thr=0x7f3e38079e00, dup=0x7f3e803422e0, stage=0x7f3e38160730) at /data/src/bb-10.2-marko/storage/innobase/row/row0log.cc:2929
      #10 0x000055c33c21fa8c in row_log_table_apply (thr=0x7f3e38079e00, old_table=0x7f3e38057e88, table=0x7f3e3807e970, stage=0x7f3e38160730) at /data/src/bb-10.2-marko/storage/innobase/row/row0log.cc:3028
      #11 0x000055c33c104b5c in ha_innobase::inplace_alter_table (this=0x7f3e38057658, altered_table=0x7f3e3807e970, ha_alter_info=0x7f3e80342610) at /data/src/bb-10.2-marko/storage/innobase/handler/handler0alter.cc:6488
      #12 0x000055c33bc1d4af in handler::ha_inplace_alter_table (this=0x7f3e38057658, altered_table=0x7f3e3807e970, ha_alter_info=0x7f3e80342610) at /data/src/bb-10.2-marko/sql/handler.h:3768
      #13 0x000055c33bc14729 in mysql_inplace_alter_table (thd=0x7f3e38000b00, table_list=0x7f3e38012520, table=0x7f3e38064830, altered_table=0x7f3e3807e970, ha_alter_info=0x7f3e80342610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f3e80342680, alter_ctx=0x7f3e80343240) at /data/src/bb-10.2-marko/sql/sql_table.cc:7332
      #14 0x000055c33bc19a6b in mysql_alter_table (thd=0x7f3e38000b00, new_db=0x7f3e38012b30 "test", new_name=0x0, create_info=0x7f3e80343e50, table_list=0x7f3e38012520, alter_info=0x7f3e80343da0, order_num=0, order=0x0, ignore=false) at /data/src/bb-10.2-marko/sql/sql_table.cc:9324
      #15 0x000055c33bc92b5c in Sql_cmd_alter_table::execute (this=0x7f3e38012b38, thd=0x7f3e38000b00) at /data/src/bb-10.2-marko/sql/sql_alter.cc:324
      #16 0x000055c33bb4f15d in mysql_execute_command (thd=0x7f3e38000b00) at /data/src/bb-10.2-marko/sql/sql_parse.cc:6189
      #17 0x000055c33bb53a0e in mysql_parse (thd=0x7f3e38000b00, rawbuf=0x7f3e38012448 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f3e80345200, is_com_multi=false, is_next_command=false) at /data/src/bb-10.2-marko/sql/sql_parse.cc:7861
      #18 0x000055c33bb419ca in dispatch_command (command=COM_QUERY, thd=0x7f3e38000b00, packet=0x7f3e3808caf1 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/bb-10.2-marko/sql/sql_parse.cc:1805
      #19 0x000055c33bb40328 in do_command (thd=0x7f3e38000b00) at /data/src/bb-10.2-marko/sql/sql_parse.cc:1360
      #20 0x000055c33bc8d84d in do_handle_one_connection (connect=0x55c33fa9c0f0) at /data/src/bb-10.2-marko/sql/sql_connect.cc:1354
      #21 0x000055c33bc8d5da in handle_one_connection (arg=0x55c33fa9c0f0) at /data/src/bb-10.2-marko/sql/sql_connect.cc:1260
      #22 0x000055c33c0aac00 in pfs_spawn_thread (arg=0x55c33faa6660) at /data/src/bb-10.2-marko/storage/perfschema/pfs.cc:1863
      #23 0x00007f3e8fbbb494 in start_thread (arg=0x7f3e80346700) at pthread_create.c:333
      #24 0x00007f3e8dfa193f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      However, the initial assertion is also there:

      bb-10.2-marko 5d142f9958d5cbb

      mysqld: /data/src/bb-10.2-marko/storage/innobase/rem/rem0rec.cc:598: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1' failed.
       
      #7  0x00007f6d567f2ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x000055c747cd9261 in rec_get_offsets_func (rec=0x7f6d04006b27 "", index=0x7f6ce8051218, offsets=0x7f6d040064e0, leaf=false, n_fields=1, file=0x55c74834c748 "/data/src/bb-10.2-marko/storage/innobase/dict/dict0stats.cc", line=1197, heap=0x7f6d2e7fb550) at /data/src/bb-10.2-marko/storage/innobase/rem/rem0rec.cc:595
      #9  0x000055c747ec2870 in dict_stats_analyze_index_level (index=0x7f6ce8051218, level=1, n_diff=0x7f6d04005ef0, total_recs=0x7f6d2e7fb6f8, total_pages=0x7f6d2e7fb700, n_diff_boundaries=0x7f6d040069a8, mtr=0x7f6d2e7fb780) at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats.cc:1197
      #10 0x000055c747ec42b0 in dict_stats_analyze_index (index=0x7f6ce8051218) at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats.cc:2155
      #11 0x000055c747ec4835 in dict_stats_update_persistent (table=0x7f6ce804f5a8) at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats.cc:2266
      #12 0x000055c747ec6e56 in dict_stats_update (table=0x7f6ce804f5a8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats.cc:3227
      #13 0x000055c747eca8c8 in dict_stats_process_entry_from_recalc_pool () at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats_bg.cc:382
      #14 0x000055c747ecaa86 in dict_stats_thread () at /data/src/bb-10.2-marko/storage/innobase/dict/dict0stats_bg.cc:468
      #15 0x00007f6d584c9494 in start_thread (arg=0x7f6d2e7fc700) at pthread_create.c:333
      #16 0x00007f6d568af93f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Attachments

        Activity

          elenst Elena Stepanova added a comment - - edited

          As of 10.2 5d142f9958d5cbb (after the merge of MDEV-13795/MDEV-14332 fix), 10.2 behaves on the provided test case as described above for bb-10.2-marko:

          10.2 5d142f9958d5cbb

          mysqld: /data/src/10.2/storage/innobase/row/row0log.cc:2313: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, ulint, row_merge_dup_t*, dberr_t*, mem_he
          ap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*): Assertion `0' failed.
          171110 14:20:17 [ERROR] mysqld got signal 6 ;
           
          #7  0x00007f1dcc817ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
          #8  0x0000557c59182683 in row_log_table_apply_op (thr=0x7f1d7805b050, trx_id_col=1, new_trx_id_col=1, dup=0x7f1dc447f2e0, error=0x7f1dc447f084, offsets_heap=0x7f1d78042a10, heap=0x7f1d7803e980, mrec=0x7f1dbc6fd12b "", mrec_end=0x7f1dbc7c5720 "", offsets=0x7f1d78037490) at /data/src/10.2/storage/innobase/row/row0log.cc:2313
          #9  0x0000557c59184581 in row_log_table_apply_ops (thr=0x7f1d7805b050, dup=0x7f1dc447f2e0, stage=0x7f1d7800c860) at /data/src/10.2/storage/innobase/row/row0log.cc:2929
          #10 0x0000557c59184a8c in row_log_table_apply (thr=0x7f1d7805b050, old_table=0x7f1d7807a4a8, table=0x7f1d7803d800, stage=0x7f1d7800c860) at /data/src/10.2/storage/innobase/row/row0log.cc:3028
          #11 0x0000557c59069b5c in ha_innobase::inplace_alter_table (this=0x7f1d78009d28, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:6488
          #12 0x0000557c58b824af in handler::ha_inplace_alter_table (this=0x7f1d78009d28, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610) at /data/src/10.2/sql/handler.h:3768
          #13 0x0000557c58b79729 in mysql_inplace_alter_table (thd=0x7f1d78000b00, table_list=0x7f1d78012520, table=0x7f1d78009120, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f1dc447f680, alter_ctx=0x7f1dc4480240) at /data/src/10.2/sql/sql_table.cc:7332
          #14 0x0000557c58b7ea6b in mysql_alter_table (thd=0x7f1d78000b00, new_db=0x7f1d78012b30 "test", new_name=0x0, create_info=0x7f1dc4480e50, table_list=0x7f1d78012520, alter_info=0x7f1dc4480da0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9324
          #15 0x0000557c58bf7b5c in Sql_cmd_alter_table::execute (this=0x7f1d78012b38, thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_alter.cc:324
          #16 0x0000557c58ab415d in mysql_execute_command (thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_parse.cc:6189
          #17 0x0000557c58ab8a0e in mysql_parse (thd=0x7f1d78000b00, rawbuf=0x7f1d78012448 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f1dc4482200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7861
          #18 0x0000557c58aa69ca in dispatch_command (command=COM_QUERY, thd=0x7f1d78000b00, packet=0x7f1d7808c9a1 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1805
          #19 0x0000557c58aa5328 in do_command (thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_parse.cc:1360
          #20 0x0000557c58bf284d in do_handle_one_connection (connect=0x557c5c131290) at /data/src/10.2/sql/sql_connect.cc:1354
          #21 0x0000557c58bf25da in handle_one_connection (arg=0x557c5c131290) at /data/src/10.2/sql/sql_connect.cc:1260
          #22 0x0000557c5900fc00 in pfs_spawn_thread (arg=0x557c5c13b800) at /data/src/10.2/storage/perfschema/pfs.cc:1863
          #23 0x00007f1dce4ee494 in start_thread (arg=0x7f1dc4483700) at pthread_create.c:333
          #24 0x00007f1dcc8d493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
          

          Here is the slightly modified test case which still causes the initially reported assertion failure. It needs to be run with --mysqld=--performance-schema=off (I don't know why):

          --source include/have_innodb.inc
           
          SET @innodb_stats_persistent.save= @@innodb_stats_persistent;
          SET GLOBAL innodb_stats_persistent= ON;
           
          SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
           
          CREATE TABLE t1 (
            pk INT,
            c1 VARCHAR(8),
            c2 VARCHAR(8),
            i1 INT,
            t1 TIME,
            t2 TIME,
            c3 VARCHAR(8),
            c4 VARCHAR(8),
            t3 TIME,
            v1 TIME AS (t3) VIRTUAL,
            i2 INT,
            c5 VARCHAR(8),
            t4 TIME,
            c6 VARCHAR(8),
            i3 INT,
            t5 TIME,
            c7 VARCHAR(8),
            n1 DOUBLE,
            i4 INT,
            i5 INT,
            t6 TIME DEFAULT '00:00:00'
          ) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
           
          --connect (con1,localhost,root,,test)
          SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
           
          INSERT INTO t1 () VALUES (),(),(),(),(),(),(),(),(),(),(),();
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 () VALUES (),(),(),(),(),(),(),();
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 () VALUES (),(),(),();
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 () VALUES ();
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          ALTER TABLE t1 ADD COLUMN n2 DOUBLE DEFAULT 0;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 () VALUES (),();
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 (t6) SELECT v1 FROM t1;
          ALTER TABLE t1 ADD COLUMN i6 INT NOT NULL DEFAULT 0, ALGORITHM=COPY;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          --send
          	ALTER TABLE t1 FORCE;
           
          --connection default
          --error 0,ER_LOCK_WAIT_TIMEOUT
          INSERT INTO t1 (pk) SELECT pk FROM t1;
          --error 0,ER_LOCK_WAIT_TIMEOUT
          INSERT INTO t1 (pk) SELECT pk FROM t1;
           
          --connection con1
          --error 0,ER_LOCK_WAIT_TIMEOUT
          --reap
           
          # Cleanup
          --disconnect con1
          --connection default
          DROP TABLE t1;
          SET GLOBAL innodb_stats_persistent= @innodb_stats_persistent.save;
          

          10.2 5d142f9958d5cbb

          mysqld: /data/src/10.2/storage/innobase/rem/rem0rec.cc:598: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1' failed.
          171110 14:23:57 [ERROR] mysqld got signal 6 ;
           
          #7  0x00007f3751e54ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
          #8  0x0000557c9f714261 in rec_get_offsets_func (rec=0x7f3724006b27 "", index=0x7f36f80484e8, offsets=0x7f37240064e0, leaf=false, n_fields=1, file=0x557c9fd82308 "/data/src/10.2/storage/innobase/dict/dict0stats.cc", line=1197, heap=0x7f37417f9550) at /data/src/10.2/storage/innobase/rem/rem0rec.cc:595
          #9  0x0000557c9f8fd870 in dict_stats_analyze_index_level (index=0x7f36f80484e8, level=1, n_diff=0x7f3724005ef0, total_recs=0x7f37417f96f8, total_pages=0x7f37417f9700, n_diff_boundaries=0x7f37240069a8, mtr=0x7f37417f9780) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:1197
          #10 0x0000557c9f8ff2b0 in dict_stats_analyze_index (index=0x7f36f80484e8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2155
          #11 0x0000557c9f8ff835 in dict_stats_update_persistent (table=0x7f36f801f2d8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2266
          #12 0x0000557c9f901e56 in dict_stats_update (table=0x7f36f801f2d8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:3227
          #13 0x0000557c9f9058c8 in dict_stats_process_entry_from_recalc_pool () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:382
          #14 0x0000557c9f905a86 in dict_stats_thread () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:468
          #15 0x00007f3753b2b494 in start_thread (arg=0x7f37417fa700) at pthread_create.c:333
          #16 0x00007f3751f1193f in clone () from /lib/x86_64-linux-gnu/libc.so.6
          

          Non-debug build in both cases complains about index corruption:

          mysqltest: At line 63: query 'reap' failed with wrong errno 1034: 'Index for table 't1' is corrupt; try to repair it', instead of 0...
          

          elenst Elena Stepanova added a comment - - edited As of 10.2 5d142f9958d5cbb (after the merge of MDEV-13795 / MDEV-14332 fix), 10.2 behaves on the provided test case as described above for bb-10.2-marko: 10.2 5d142f9958d5cbb mysqld: /data/src/10.2/storage/innobase/row/row0log.cc:2313: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, ulint, row_merge_dup_t*, dberr_t*, mem_he ap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*): Assertion `0' failed. 171110 14:20:17 [ERROR] mysqld got signal 6 ;   #7 0x00007f1dcc817ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000557c59182683 in row_log_table_apply_op (thr=0x7f1d7805b050, trx_id_col=1, new_trx_id_col=1, dup=0x7f1dc447f2e0, error=0x7f1dc447f084, offsets_heap=0x7f1d78042a10, heap=0x7f1d7803e980, mrec=0x7f1dbc6fd12b "", mrec_end=0x7f1dbc7c5720 "", offsets=0x7f1d78037490) at /data/src/10.2/storage/innobase/row/row0log.cc:2313 #9 0x0000557c59184581 in row_log_table_apply_ops (thr=0x7f1d7805b050, dup=0x7f1dc447f2e0, stage=0x7f1d7800c860) at /data/src/10.2/storage/innobase/row/row0log.cc:2929 #10 0x0000557c59184a8c in row_log_table_apply (thr=0x7f1d7805b050, old_table=0x7f1d7807a4a8, table=0x7f1d7803d800, stage=0x7f1d7800c860) at /data/src/10.2/storage/innobase/row/row0log.cc:3028 #11 0x0000557c59069b5c in ha_innobase::inplace_alter_table (this=0x7f1d78009d28, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:6488 #12 0x0000557c58b824af in handler::ha_inplace_alter_table (this=0x7f1d78009d28, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610) at /data/src/10.2/sql/handler.h:3768 #13 0x0000557c58b79729 in mysql_inplace_alter_table (thd=0x7f1d78000b00, table_list=0x7f1d78012520, table=0x7f1d78009120, altered_table=0x7f1d7803d800, ha_alter_info=0x7f1dc447f610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f1dc447f680, alter_ctx=0x7f1dc4480240) at /data/src/10.2/sql/sql_table.cc:7332 #14 0x0000557c58b7ea6b in mysql_alter_table (thd=0x7f1d78000b00, new_db=0x7f1d78012b30 "test", new_name=0x0, create_info=0x7f1dc4480e50, table_list=0x7f1d78012520, alter_info=0x7f1dc4480da0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9324 #15 0x0000557c58bf7b5c in Sql_cmd_alter_table::execute (this=0x7f1d78012b38, thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_alter.cc:324 #16 0x0000557c58ab415d in mysql_execute_command (thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_parse.cc:6189 #17 0x0000557c58ab8a0e in mysql_parse (thd=0x7f1d78000b00, rawbuf=0x7f1d78012448 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f1dc4482200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7861 #18 0x0000557c58aa69ca in dispatch_command (command=COM_QUERY, thd=0x7f1d78000b00, packet=0x7f1d7808c9a1 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1805 #19 0x0000557c58aa5328 in do_command (thd=0x7f1d78000b00) at /data/src/10.2/sql/sql_parse.cc:1360 #20 0x0000557c58bf284d in do_handle_one_connection (connect=0x557c5c131290) at /data/src/10.2/sql/sql_connect.cc:1354 #21 0x0000557c58bf25da in handle_one_connection (arg=0x557c5c131290) at /data/src/10.2/sql/sql_connect.cc:1260 #22 0x0000557c5900fc00 in pfs_spawn_thread (arg=0x557c5c13b800) at /data/src/10.2/storage/perfschema/pfs.cc:1863 #23 0x00007f1dce4ee494 in start_thread (arg=0x7f1dc4483700) at pthread_create.c:333 #24 0x00007f1dcc8d493f in clone () from /lib/x86_64-linux-gnu/libc.so.6 Here is the slightly modified test case which still causes the initially reported assertion failure. It needs to be run with --mysqld=--performance-schema=off (I don't know why): --source include/have_innodb.inc   SET @innodb_stats_persistent.save= @@innodb_stats_persistent; SET GLOBAL innodb_stats_persistent= ON ;   SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;   CREATE TABLE t1 ( pk INT , c1 VARCHAR (8), c2 VARCHAR (8), i1 INT , t1 TIME , t2 TIME , c3 VARCHAR (8), c4 VARCHAR (8), t3 TIME , v1 TIME AS (t3) VIRTUAL, i2 INT , c5 VARCHAR (8), t4 TIME , c6 VARCHAR (8), i3 INT , t5 TIME , c7 VARCHAR (8), n1 DOUBLE , i4 INT , i5 INT , t6 TIME DEFAULT '00:00:00' ) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;   --connect (con1,localhost,root,,test) SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;   INSERT INTO t1 () VALUES (),(),(),(),(),(),(),(),(),(),(),(); INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 () VALUES (),(),(),(),(),(),(),(); INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 () VALUES (),(),(),(); INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 () VALUES (); INSERT INTO t1 (pk) SELECT pk FROM t1; ALTER TABLE t1 ADD COLUMN n2 DOUBLE DEFAULT 0; INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 () VALUES (),(); INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 (t6) SELECT v1 FROM t1; ALTER TABLE t1 ADD COLUMN i6 INT NOT NULL DEFAULT 0, ALGORITHM=COPY; INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 (pk) SELECT pk FROM t1; INSERT INTO t1 (pk) SELECT pk FROM t1; --send ALTER TABLE t1 FORCE ;   --connection default --error 0,ER_LOCK_WAIT_TIMEOUT INSERT INTO t1 (pk) SELECT pk FROM t1; --error 0,ER_LOCK_WAIT_TIMEOUT INSERT INTO t1 (pk) SELECT pk FROM t1;   --connection con1 --error 0,ER_LOCK_WAIT_TIMEOUT --reap   # Cleanup --disconnect con1 --connection default DROP TABLE t1; SET GLOBAL innodb_stats_persistent= @innodb_stats_persistent.save; 10.2 5d142f9958d5cbb mysqld: /data/src/10.2/storage/innobase/rem/rem0rec.cc:598: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1' failed. 171110 14:23:57 [ERROR] mysqld got signal 6 ;   #7 0x00007f3751e54ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000557c9f714261 in rec_get_offsets_func (rec=0x7f3724006b27 "", index=0x7f36f80484e8, offsets=0x7f37240064e0, leaf=false, n_fields=1, file=0x557c9fd82308 "/data/src/10.2/storage/innobase/dict/dict0stats.cc", line=1197, heap=0x7f37417f9550) at /data/src/10.2/storage/innobase/rem/rem0rec.cc:595 #9 0x0000557c9f8fd870 in dict_stats_analyze_index_level (index=0x7f36f80484e8, level=1, n_diff=0x7f3724005ef0, total_recs=0x7f37417f96f8, total_pages=0x7f37417f9700, n_diff_boundaries=0x7f37240069a8, mtr=0x7f37417f9780) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:1197 #10 0x0000557c9f8ff2b0 in dict_stats_analyze_index (index=0x7f36f80484e8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2155 #11 0x0000557c9f8ff835 in dict_stats_update_persistent (table=0x7f36f801f2d8) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:2266 #12 0x0000557c9f901e56 in dict_stats_update (table=0x7f36f801f2d8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /data/src/10.2/storage/innobase/dict/dict0stats.cc:3227 #13 0x0000557c9f9058c8 in dict_stats_process_entry_from_recalc_pool () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:382 #14 0x0000557c9f905a86 in dict_stats_thread () at /data/src/10.2/storage/innobase/dict/dict0stats_bg.cc:468 #15 0x00007f3753b2b494 in start_thread (arg=0x7f37417fa700) at pthread_create.c:333 #16 0x00007f3751f1193f in clone () from /lib/x86_64-linux-gnu/libc.so.6 Non-debug build in both cases complains about index corruption: mysqltest: At line 63: query 'reap' failed with wrong errno 1034: 'Index for table 't1' is corrupt; try to repair it', instead of 0...

          The assertion in rec_get_offsets_func() is bogus. It should be relaxed, because we are operating on a copied prefix of a node pointer record.
          I introduced this debug assertion in 10.2 when refactoring some code for MDEV-11369 (instant ADD COLUMN for 10.3):

          diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc
          index b29a43772b0..37bf6e649a2 100644
          --- a/storage/innobase/rem/rem0rec.cc
          +++ b/storage/innobase/rem/rem0rec.cc
          @@ -594,6 +594,7 @@ rec_get_offsets_func(
           		ut_ad(is_user_rec || n == 1);
           		ut_ad(!is_user_rec || leaf || index->is_dummy
           		      || dict_index_is_ibuf(index)
          +		      || n == n_fields /* dict_stats_analyze_index_level() */
           		      || n
           		      == dict_index_get_n_unique_in_tree_nonleaf(index) + 1);
           		ut_ad(!is_user_rec || !leaf || index->is_dummy
          

          The assertion failure in row_log_table_apply_op() is a real problem. The online_log for the ALTER TABLE t1 FORCE consists mostly of ROW_T_INSERT records, and in my case of repeating it, it appears that 10 bytes too little of the previous record was consumed. The last two records (correctly and wrongly parsed, respectively) are:

          good record

          4103 07ff ff00 0000 010a 1200 0000 0005
          65b8 0000 016a 1cda 8000 0000 0000 0000
          0000 0080 0000 00
          

          bad record

          4103 07ff ff00 0000 010a 1300 0000 0005
          65b8 0000 016a 1ceb 8000 0000 0000 0000
          0000 0080 0000 00
          

          The only differences are the bytes 12/13 and da/eb.
          It is rather unlikely that we failed to consume 10 bytes of the preceding record. More likely is that because I forgot to remove some code in the MDEV-13795/MDEV-14332 fix, we jumped from somewhere earlier due to

          next_mrec += mach_read_from_2(next_mrec);
          

          After searching all of row0log.cc for any occurrence of "n_v" removing the bogus code, the test passes.

          marko Marko Mäkelä added a comment - The assertion in rec_get_offsets_func() is bogus. It should be relaxed, because we are operating on a copied prefix of a node pointer record. I introduced this debug assertion in 10.2 when refactoring some code for MDEV-11369 (instant ADD COLUMN for 10.3): diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index b29a43772b0..37bf6e649a2 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -594,6 +594,7 @@ rec_get_offsets_func( ut_ad(is_user_rec || n == 1); ut_ad(!is_user_rec || leaf || index->is_dummy || dict_index_is_ibuf(index) + || n == n_fields /* dict_stats_analyze_index_level() */ || n == dict_index_get_n_unique_in_tree_nonleaf(index) + 1); ut_ad(!is_user_rec || !leaf || index->is_dummy The assertion failure in row_log_table_apply_op() is a real problem. The online_log for the ALTER TABLE t1 FORCE consists mostly of ROW_T_INSERT records, and in my case of repeating it, it appears that 10 bytes too little of the previous record was consumed. The last two records (correctly and wrongly parsed, respectively) are: good record 4103 07ff ff00 0000 010a 1200 0000 0005 65b8 0000 016a 1cda 8000 0000 0000 0000 0000 0080 0000 00 bad record 4103 07ff ff00 0000 010a 1300 0000 0005 65b8 0000 016a 1ceb 8000 0000 0000 0000 0000 0080 0000 00 The only differences are the bytes 12/13 and da/eb. It is rather unlikely that we failed to consume 10 bytes of the preceding record. More likely is that because I forgot to remove some code in the MDEV-13795 / MDEV-14332 fix, we jumped from somewhere earlier due to next_mrec += mach_read_from_2(next_mrec); After searching all of row0log.cc for any occurrence of "n_v" removing the bogus code, the test passes.

          People

            marko Marko Mäkelä
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.