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

Assertion `!m.first->second.is_bulk_insert()' failed in trx_undo_report_row_operation

Details

    Description

      Despite being simple and single-threaded, the test case is non-deterministic on whatever reason. Run with --repeat=N.
      It fails for me within a few attempts, but since I don't know why it is non-deterministic, I suppose it can vary a lot on different machines and builds.

      Upd: after later changes, the test case also requires

      SET unique_checks=0,foreign_key_checks=0;
      

      --source include/have_innodb.inc
      --source include/have_partition.inc
       
      SET SESSION TIME_ZONE= '+00:00';
       
      CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB WITH SYSTEM VERSIONING PARTITION BY KEY() PARTITIONS 2;
      INSERT INTO t1 VALUES (1),(2);
      DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999';
       
      # Cleanup
      DROP TABLE t1;
      

      10.6 1146e98b

      mariadbd: /data/src/10.6/storage/innobase/trx/trx0rec.cc:2006: dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*): Assertion `!m.first->second.is_bulk_insert()' failed.
      210217 14:49:40 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007f4bec262f36 in __GI___assert_fail (assertion=0x55de3d288798 "!m.first->second.is_bulk_insert()", file=0x55de3d287708 "/data/src/10.6/storage/innobase/trx/trx0rec.cc", line=2006, function=0x55de3d288658 "dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*)") at assert.c:101
      #8  0x000055de3cb6beec in trx_undo_report_row_operation (thr=0x7f4bb8227b48, index=0x7f4bb8232638, clust_entry=0x7f4bb8060138, update=0x0, cmpl_info=0, rec=0x7f4be1d8c07d "\200", offsets=0x7f4be15fb980, roll_ptr=0x7f4be15fb388) at /data/src/10.6/storage/innobase/trx/trx0rec.cc:2006
      #9  0x000055de3cbd9920 in btr_cur_del_mark_set_clust_rec (block=0x7f4be18a5f40, rec=0x7f4be1d8c07d "\200", index=0x7f4bb8232638, offsets=0x7f4be15fb980, thr=0x7f4bb8227b48, entry=0x7f4bb8060138, mtr=0x7f4be15fbbe0) at /data/src/10.6/storage/innobase/btr/btr0cur.cc:5358
      #10 0x000055de3cb2d973 in row_upd_del_mark_clust_rec (node=0x7f4bb8227820, index=0x7f4bb8232638, offsets=0x7f4be15fb980, thr=0x7f4bb8227b48, referenced=0, foreign=false, mtr=0x7f4be15fbbe0) at /data/src/10.6/storage/innobase/row/row0upd.cc:2683
      #11 0x000055de3cb2e40b in row_upd_clust_step (node=0x7f4bb8227820, thr=0x7f4bb8227b48) at /data/src/10.6/storage/innobase/row/row0upd.cc:2860
      #12 0x000055de3cb2e9fb in row_upd (node=0x7f4bb8227820, thr=0x7f4bb8227b48) at /data/src/10.6/storage/innobase/row/row0upd.cc:2992
      #13 0x000055de3cb2efb7 in row_upd_step (thr=0x7f4bb8227b48) at /data/src/10.6/storage/innobase/row/row0upd.cc:3136
      #14 0x000055de3cad1209 in row_update_for_mysql (prebuilt=0x7f4bb8226d68) at /data/src/10.6/storage/innobase/row/row0mysql.cc:1805
      #15 0x000055de3c920ce7 in ha_innobase::delete_row (this=0x7f4bb81b9c30, record=0x7f4bb81b25b0 "\377\001") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:8267
      #16 0x000055de3c4b4022 in handler::ha_delete_row (this=0x7f4bb81b9c30, buf=0x7f4bb81b25b0 "\377\001") at /data/src/10.6/sql/handler.cc:7269
      #17 0x000055de3c81f319 in ha_partition::delete_row (this=0x7f4bb81b8ae0, buf=0x7f4bb81b25b0 "\377\001") at /data/src/10.6/sql/ha_partition.cc:4695
      #18 0x000055de3c4b3e65 in handler::ha_delete_row (this=0x7f4bb81b8ae0, buf=0x7f4bb81b25b0 "\377\001") at /data/src/10.6/sql/handler.cc:7269
      #19 0x000055de3c690c1f in TABLE::delete_row (this=0x7f4bb81b0768) at /data/src/10.6/sql/sql_delete.cc:280
      #20 0x000055de3c68d9cd in mysql_delete (thd=0x7f4bb8000db8, table_list=0x7f4bb8013f10, conds=0x7f4bb8014b40, order_list=0x7f4bb8005a28, limit=18446744073709551613, options=0, result=0x0) at /data/src/10.6/sql/sql_delete.cc:815
      #21 0x000055de3c137687 in mysql_execute_command (thd=0x7f4bb8000db8) at /data/src/10.6/sql/sql_parse.cc:4760
      #22 0x000055de3c142310 in mysql_parse (thd=0x7f4bb8000db8, rawbuf=0x7f4bb8013de0 "DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999'", length=70, parser_state=0x7f4be15fd510) at /data/src/10.6/sql/sql_parse.cc:7971
      #23 0x000055de3c12e7f1 in dispatch_command (command=COM_QUERY, thd=0x7f4bb8000db8, packet=0x7f4bb8008f59 "DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999'", packet_length=70, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1886
      #24 0x000055de3c12d198 in do_command (thd=0x7f4bb8000db8, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1397
      #25 0x000055de3c2daa3e in do_handle_one_connection (connect=0x55de3f7e01f8, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
      #26 0x000055de3c2da79c in handle_one_connection (arg=0x55de3f84b288) at /data/src/10.6/sql/sql_connect.cc:1312
      #27 0x000055de3c838a13 in pfs_spawn_thread (arg=0x55de3f7dff78) at /data/src/10.6/storage/perfschema/pfs.cc:2201
      #28 0x00007f4bec77a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #29 0x00007f4bec34e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      No obvious immediate problem on a non-debug build.
      Did not get any failure on 10.5.
      Did not get any failure with MyISAM.
      Couldn't reproduce without partitioning, without versioning, without BEFORE condition.
      Timezone setting is not needed on my machine, but intermediate versions of the test case seemed to depend on the timezone, so I kept it there for more reliability.

      Attachments

        Issue Links

          Activity

            Delete history statement does the following:

            insert into p1 partition; - does bulk insert operation
            delete from p0 partition;
            insert into p1 partition;
            delete from p0 partition;
            delete from p1 partition; - here it is failing.
            

            In MDEV-515, InnoDB gets notified about statement boundary and call trx->end_bulk_insert(*table). These calls are present in ha_innobase::extra(), ha_innobase::external_lock, ha_innobase::start_stmt and trx_mark_sql_stat_end().

            But in this case, InnoDB never gets call for end_bulk_insert(). may be Versioning should need a fake statement boundary call once it is done with one partition. (my guess only)

            As per marko's suggestion, moving this issue to midenok

            thiru Thirunarayanan Balathandayuthapani added a comment - Delete history statement does the following: insert into p1 partition; - does bulk insert operation delete from p0 partition; insert into p1 partition; delete from p0 partition; delete from p1 partition; - here it is failing. In MDEV-515 , InnoDB gets notified about statement boundary and call trx->end_bulk_insert(*table) . These calls are present in ha_innobase::extra() , ha_innobase::external_lock , ha_innobase::start_stmt and trx_mark_sql_stat_end() . But in this case, InnoDB never gets call for end_bulk_insert(). may be Versioning should need a fake statement boundary call once it is done with one partition. (my guess only) As per marko's suggestion, moving this issue to midenok

            In MDEV-24818, the logic was changed: we now have the flag trx_t::bulk_insert. This bug is not repeatable anymore, not even after adding the ‘opt-in’ magic that was added in MDEV-24818:

            --source include/have_innodb.inc
            --source include/have_partition.inc
             
            SET unique_checks=0,foreign_key_checks=0;
            SET SESSION TIME_ZONE= '+00:00';
             
            CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB WITH SYSTEM VERSIONING PARTITION BY KEY() PARTITIONS 2;
            INSERT INTO t1 VALUES (1),(2);
            DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999';
            DROP TABLE t1;
            

            With this test, I can repeat a crash right before the MDEV-25315 fix but not after it:

            10.6 f9bd7f20124dff1af76a12691b8c337fac6ad3e6

            #6  0x00007f3ae33ff662 in __GI___assert_fail (assertion=0x5588b59a19c3 "!m.first->second.is_bulk_insert()", file=0x5588b59a1348 "/mariadb/10.6/storage/innobase/trx/trx0rec.cc", line=2006, function=0x5588b59a1905 "dberr_t trx_undo_report_row_operation(que_thr_t *, dict_index_t *, const dtuple_t *, const upd_t *, ulint, const rec_t *, const rec_offs *, roll_ptr_t *)") at assert.c:101
            #7  0x00005588b5478b47 in trx_undo_report_row_operation (thr=thr@entry=0x7f3ab0100648, index=index@entry=0x7f3ab020b628, clust_entry=0x7f3ab0053d98, clust_entry@entry=0x7f3adc4fc428, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x7f3adcc8c07d "\200", offsets=0x7f3adc4fc800, roll_ptr=0x7f3adc4fc428) at /mariadb/10.6/storage/innobase/trx/trx0rec.cc:2006
            #8  0x00005588b54e71e5 in btr_cur_del_mark_set_clust_rec (block=<optimized out>, rec=<optimized out>, rec@entry=0x7f3adcc8c07d "\200", index=index@entry=0x7f3ab020b628, offsets=offsets@entry=0x7f3adc4fc800, thr=thr@entry=0x7f3ab0100648, entry=<optimized out>, mtr=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:5389
            #9  0x00005588b543e219 in row_upd_del_mark_clust_rec (node=0x7f3ab0100320, index=0x7f3ab020b628, offsets=0x7f3adc4fc800, thr=0x7f3ab0100648, referenced=false, foreign=<optimized out>, mtr=0x7f3adc4fce48) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2706
            #10 row_upd_clust_step (node=0x7f3ab0100320, thr=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2843
            #11 row_upd (node=node@entry=0x7f3ab0100320, thr=<optimized out>, thr@entry=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2965
            #12 0x00005588b543d63e in row_upd_step (thr=thr@entry=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:3109
            #13 0x00005588b53e4148 in row_update_for_mysql (prebuilt=<optimized out>) at /mariadb/10.6/storage/innobase/row/row0mysql.cc:1814
            #14 0x00005588b5272dd5 in ha_innobase::delete_row (this=0x7f3ab0210af0, record=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:8310
            #15 0x00005588b4f5012c in handler::ha_delete_row (this=0x7f3ab0210af0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/handler.cc:7272
            #16 0x00005588b51c40a5 in ha_partition::delete_row (this=0x7f3ab020faa0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/ha_partition.cc:4687
            #17 0x00005588b4f50175 in handler::ha_delete_row (this=0x7f3ab020faa0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/handler.cc:7272
            #18 0x00005588b50d0611 in TABLE::delete_row (this=0x7f3ab020e2c8) at /mariadb/10.6/sql/sql_delete.cc:280
            #19 mysql_delete (thd=thd@entry=0x7f3ab0000d48, table_list=<optimized out>, conds=<optimized out>, order_list=<optimized out>, order_list@entry=0x7f3ab00059c0, limit=18446744073709551613, options=0, result=<optimized out>) at /mariadb/10.6/sql/sql_delete.cc:815
            #20 0x00005588b4ce98b0 in mysql_execute_command (thd=thd@entry=0x7f3ab0000d48) at /mariadb/10.6/sql/sql_parse.cc:4788
            #21 0x00005588b4cdf37e in mysql_parse (thd=0x7f3ab0000d48, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, parser_state@entry=0x7f3adc4fe590) at /mariadb/10.6/sql/sql_parse.cc:8004
            #22 0x00005588b4cdc448 in dispatch_command (command=<optimized out>, command@entry=COM_QUERY, thd=thd@entry=0x7f3ab0000d48, packet=packet@entry=0x7f3ab000ab49 "DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999'", packet_length=packet_length@entry=70, blocking=true) at /mariadb/10.6/sql/sql_parse.cc:1888
            

            marko Marko Mäkelä added a comment - In MDEV-24818 , the logic was changed: we now have the flag trx_t::bulk_insert . This bug is not repeatable anymore, not even after adding the ‘opt-in’ magic that was added in MDEV-24818 : --source include/have_innodb.inc --source include/have_partition.inc   SET unique_checks=0,foreign_key_checks=0; SET SESSION TIME_ZONE= '+00:00' ;   CREATE TABLE t1 (pk INT PRIMARY KEY ) ENGINE=InnoDB WITH SYSTEM VERSIONING PARTITION BY KEY () PARTITIONS 2; INSERT INTO t1 VALUES (1),(2); DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999' ; DROP TABLE t1; With this test, I can repeat a crash right before the MDEV-25315 fix but not after it: 10.6 f9bd7f20124dff1af76a12691b8c337fac6ad3e6 #6 0x00007f3ae33ff662 in __GI___assert_fail (assertion=0x5588b59a19c3 "!m.first->second.is_bulk_insert()", file=0x5588b59a1348 "/mariadb/10.6/storage/innobase/trx/trx0rec.cc", line=2006, function=0x5588b59a1905 "dberr_t trx_undo_report_row_operation(que_thr_t *, dict_index_t *, const dtuple_t *, const upd_t *, ulint, const rec_t *, const rec_offs *, roll_ptr_t *)") at assert.c:101 #7 0x00005588b5478b47 in trx_undo_report_row_operation (thr=thr@entry=0x7f3ab0100648, index=index@entry=0x7f3ab020b628, clust_entry=0x7f3ab0053d98, clust_entry@entry=0x7f3adc4fc428, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x7f3adcc8c07d "\200", offsets=0x7f3adc4fc800, roll_ptr=0x7f3adc4fc428) at /mariadb/10.6/storage/innobase/trx/trx0rec.cc:2006 #8 0x00005588b54e71e5 in btr_cur_del_mark_set_clust_rec (block=<optimized out>, rec=<optimized out>, rec@entry=0x7f3adcc8c07d "\200", index=index@entry=0x7f3ab020b628, offsets=offsets@entry=0x7f3adc4fc800, thr=thr@entry=0x7f3ab0100648, entry=<optimized out>, mtr=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:5389 #9 0x00005588b543e219 in row_upd_del_mark_clust_rec (node=0x7f3ab0100320, index=0x7f3ab020b628, offsets=0x7f3adc4fc800, thr=0x7f3ab0100648, referenced=false, foreign=<optimized out>, mtr=0x7f3adc4fce48) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2706 #10 row_upd_clust_step (node=0x7f3ab0100320, thr=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2843 #11 row_upd (node=node@entry=0x7f3ab0100320, thr=<optimized out>, thr@entry=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:2965 #12 0x00005588b543d63e in row_upd_step (thr=thr@entry=0x7f3ab0100648) at /mariadb/10.6/storage/innobase/row/row0upd.cc:3109 #13 0x00005588b53e4148 in row_update_for_mysql (prebuilt=<optimized out>) at /mariadb/10.6/storage/innobase/row/row0mysql.cc:1814 #14 0x00005588b5272dd5 in ha_innobase::delete_row (this=0x7f3ab0210af0, record=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:8310 #15 0x00005588b4f5012c in handler::ha_delete_row (this=0x7f3ab0210af0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/handler.cc:7272 #16 0x00005588b51c40a5 in ha_partition::delete_row (this=0x7f3ab020faa0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/ha_partition.cc:4687 #17 0x00005588b4f50175 in handler::ha_delete_row (this=0x7f3ab020faa0, buf=0x7f3ab01f89c0 "\377\001") at /mariadb/10.6/sql/handler.cc:7272 #18 0x00005588b50d0611 in TABLE::delete_row (this=0x7f3ab020e2c8) at /mariadb/10.6/sql/sql_delete.cc:280 #19 mysql_delete (thd=thd@entry=0x7f3ab0000d48, table_list=<optimized out>, conds=<optimized out>, order_list=<optimized out>, order_list@entry=0x7f3ab00059c0, limit=18446744073709551613, options=0, result=<optimized out>) at /mariadb/10.6/sql/sql_delete.cc:815 #20 0x00005588b4ce98b0 in mysql_execute_command (thd=thd@entry=0x7f3ab0000d48) at /mariadb/10.6/sql/sql_parse.cc:4788 #21 0x00005588b4cdf37e in mysql_parse (thd=0x7f3ab0000d48, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, parser_state@entry=0x7f3adc4fe590) at /mariadb/10.6/sql/sql_parse.cc:8004 #22 0x00005588b4cdc448 in dispatch_command (command=<optimized out>, command@entry=COM_QUERY, thd=thd@entry=0x7f3ab0000d48, packet=packet@entry=0x7f3ab000ab49 "DELETE HISTORY FROM t1 BEFORE SYSTEM_TIME '2038-01-19 05:15:07.999999'", packet_length=packet_length@entry=70, blocking=true) at /mariadb/10.6/sql/sql_parse.cc:1888

            Maybe the test is nondeterministic, but it does crash for me on the latest 10.6.

            marko Marko Mäkelä added a comment - Maybe the test is nondeterministic, but it does crash for me on the latest 10.6.

            One possible cause of non-determinism is now described in MDEV-25468. I don't know if it causes the failure here, but it's the same test case.

            elenst Elena Stepanova added a comment - One possible cause of non-determinism is now described in MDEV-25468 . I don't know if it causes the failure here, but it's the same test case.

            Fixing MDEV-25468 could end up fixing this one as well. Thank you, elenst!

            marko Marko Mäkelä added a comment - Fixing MDEV-25468 could end up fixing this one as well. Thank you, elenst !
            elenst Elena Stepanova added a comment - - edited

            As said above, the merge which contained a fix for MDEV-25468 made this failure go away.

            commit 916b237b3f6ee4d8e113d480c53bca232cadbb7b (HEAD)
            Merge: a04202673fe 35977e81f96
            Author: Marko Mäkelä
            Date:   Fri May 7 15:00:27 2021 +0300
             
                Merge 10.5 into 10.6
            

            elenst Elena Stepanova added a comment - - edited As said above, the merge which contained a fix for MDEV-25468 made this failure go away. commit 916b237b3f6ee4d8e113d480c53bca232cadbb7b (HEAD) Merge: a04202673fe 35977e81f96 Author: Marko Mäkelä Date: Fri May 7 15:00:27 2021 +0300   Merge 10.5 into 10.6

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              6 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.