[MDEV-24859] Assertion `static_cast<ins_node_t*>(thr->run_node)->bulk_insert' failed in trx_undo_report_row_operation Created: 2021-02-13  Updated: 2021-04-22  Resolved: 2021-03-31

Status: Closed
Project: MariaDB Server
Component/s: Binary Protocol, Stored routines
Affects Version/s: 10.6
Fix Version/s: N/A

Type: Bug Priority: Blocker
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: not-10.2, not-10.3, not-10.4, not-10.5, regression

Issue Links:
Relates
relates to MDEV-25297 InnoDB: Failing assertion: trx->roll_... Closed
relates to MDEV-515 innodb bulk insert Closed
relates to MDEV-24700 Assertion `"lock not found" == 0' fai... Closed
relates to MDEV-24716 Assertion `thr->graph->trx->id == trx... Closed
relates to MDEV-24812 Assertion `!trx->read_only' failed in... Confirmed
relates to MDEV-24818 Concurrent use of InnoDB table is imp... Closed

 Description    

# mysqld options required for replay:  --log_bin_trust_function_creators=1
 
SET sql_mode='';
 
DELIMITER //
 
CREATE FUNCTION f (arg CHAR(1)) RETURNS VARCHAR(1) BEGIN DECLARE v1 VARCHAR(1);DECLARE v2 VARCHAR(1);SET v1=CONCAT (LOWER (arg),UPPER (arg));SET v2=CONCAT (LOWER (v1),UPPER (v1));INSERT INTO t VALUES(v1), (v2);RETURN CONCAT (LOWER (arg),UPPER (arg));END;//
 
DELIMITER ;
 
SET GLOBAL innodb_limit_optimistic_insert_debug=2;
 
CREATE TEMPORARY TABLE t (c DEC);
 
INSERT INTO t SELECT f (1);

Leads to:

10.6.0 bfb4761ca04704d68dba51f76d7c9967f880a6ee (Debug)

 
mysqld: /test/10.6_dbg/storage/innobase/trx/trx0rec.cc:2015: 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 `static_cast<ins_node_t*>(thr->run_node)->bulk_insert' failed.

10.6.0 bfb4761ca04704d68dba51f76d7c9967f880a6ee (Debug)

 
Core was generated by `/test/MD110221-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x14c064ad2700 (LWP 3300385))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x000055eefc65355c in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x000055eefbdeb4de in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x000014c067690859 in __GI_abort () at abort.c:79
 
#6  0x000014c067690729 in __assert_fail_base (fmt=0x14c067826588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55eefca636b8 "static_cast<ins_node_t*>(thr->run_node)->bulk_insert", file=0x55eefca62a30 "/test/10.6_dbg/storage/innobase/trx/trx0rec.cc", line=2015, function=<optimized out>) at assert.c:92
 
#7  0x000014c0676a1f36 in __GI___assert_fail (assertion=assertion@entry=0x55eefca636b8 "static_cast<ins_node_t*>(thr->run_node)->bulk_insert", file=file@entry=0x55eefca62a30 "/test/10.6_dbg/storage/innobase/trx/trx0rec.cc", line=line@entry=2015, function=function@entry=0x55eefca635a8 "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  0x000055eefc4064e0 in trx_undo_report_row_operation (thr=thr@entry=0x14c020024870, index=index@entry=0x14c020022608, clust_entry=clust_entry@entry=0x14c020063378, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x14c064acf470) at /test/10.6_dbg/storage/innobase/trx/trx0rec.cc:2015
 
#9  0x000055eefc462b9f in btr_cur_ins_lock_and_undo (flags=flags@entry=2, cursor=cursor@entry=0x14c064acf610, entry=entry@entry=0x14c020063378, thr=thr@entry=0x14c020024870, mtr=mtr@entry=0x14c064acfbd0, inherit=inherit@entry=0x14c064acf51b) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:3274
 
#10 0x000055eefc46630b in btr_cur_pessimistic_insert (flags=flags@entry=2, cursor=cursor@entry=0x14c064acf610, offsets=offsets@entry=0x14c064acf5d8, heap=heap@entry=0x14c064acf5d0, entry=entry@entry=0x14c020063378, rec=rec@entry=0x14c064acf5e8, big_rec=0x14c064acf5c8, n_ext=<optimized out>, thr=0x14c020024870, mtr=0x14c064acfbd0) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:3692
 
#11 0x000055eefc343969 in row_ins_clust_index_entry_low (flags=flags@entry=2, mode=<optimized out>, mode@entry=33, index=index@entry=0x14c020022608, n_uniq=n_uniq@entry=0, entry=entry@entry=0x14c020063378, n_ext=n_ext@entry=0, thr=<optimized out>) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:2802
 
#12 0x000055eefc344633 in row_ins_clust_index_entry (index=index@entry=0x14c020022608, entry=entry@entry=0x14c020063378, thr=thr@entry=0x14c020024870, n_ext=n_ext@entry=0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3272
 
#13 0x000055eefc3490b5 in row_ins_index_entry (thr=0x14c020024870, entry=0x14c020063378, index=0x14c020022608) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3380
 
#14 row_ins_index_entry_step (thr=0x14c020024870, node=0x14c020024650) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3549
 
#15 row_ins (thr=0x14c020024870, node=0x14c020024650) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3695
 
#16 row_ins_step (thr=thr@entry=0x14c020024870) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3837
 
#17 0x000055eefc36d754 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x14c020023498 <incomplete sequence \375\200>, prebuilt=0x14c020024158, ins_mode=ROW_INS_NORMAL) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1384
 
#18 0x000055eefc1f75dd in ha_innobase::write_row (this=0x14c020023900, record=0x14c020023498 <incomplete sequence \375\200>) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7361
 
#19 0x000055eefbdff826 in handler::ha_write_row (this=0x14c020023900, buf=0x14c020023498 <incomplete sequence \375\200>) at /test/10.6_dbg/sql/handler.cc:7151
 
#20 0x000055eefbad5547 in write_record (thd=0x14c020000db8, table=0x14c020023008, info=info@entry=0x14c020015468, sink=0x0) at /test/10.6_dbg/sql/sql_insert.cc:2106
 
#21 0x000055eefbad599f in select_insert::send_data (this=0x14c020015418, values=<optimized out>) at /test/10.6_dbg/sql/sql_insert.cc:4076
 
#22 0x000055eefbba80d2 in select_result_sink::send_data_with_check (sent=0, u=<optimized out>, items=<optimized out>, this=<optimized out>) at /test/10.6_dbg/sql/sql_class.h:5377
 
#23 JOIN::exec_inner (this=this@entry=0x14c0200154d0) at /test/10.6_dbg/sql/sql_select.cc:4344
 
#24 0x000055eefbba8fbc in JOIN::exec (this=this@entry=0x14c0200154d0) at /test/10.6_dbg/sql/sql_select.cc:4256
 
#25 0x000055eefbba721c in mysql_select (thd=thd@entry=0x14c020000db8, tables=0x0, fields=@0x14c020012fc8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14c0200140d0, last = 0x14c0200140d0, elements = 1}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2202244745984, result=0x14c020015418, unit=0x14c020004f88, select_lex=0x14c020012e78) at /test/10.6_dbg/sql/sql_select.cc:4729
 
#26 0x000055eefbba74e2 in handle_select (thd=thd@entry=0x14c020000db8, lex=lex@entry=0x14c020004ec0, result=result@entry=0x14c020015418, setup_tables_done_option=setup_tables_done_option@entry=1073741824) at /test/10.6_dbg/sql/sql_select.cc:417
 
#27 0x000055eefbb28f65 in mysql_execute_command (thd=thd@entry=0x14c020000db8) at /test/10.6_dbg/sql/sql_parse.cc:4599
 
#28 0x000055eefbb1321a in mysql_parse (thd=thd@entry=0x14c020000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14c064ad13d0) at /test/10.6_dbg/sql/sql_parse.cc:7906
 
#29 0x000055eefbb2130b in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14c020000db8, packet=packet@entry=0x14c02001aac9 "INSERT INTO t SELECT f (1)", packet_length=packet_length@entry=26) at /test/10.6_dbg/sql/sql_class.h:1295
 
#30 0x000055eefbb2463d in do_command (thd=0x14c020000db8) at /test/10.6_dbg/sql/sql_parse.cc:1365
 
#31 0x000055eefbc801ab in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55eeff033468, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#32 0x000055eefbc808af in handle_one_connection (arg=arg@entry=0x55eeff033468) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#33 0x000055eefc13427d in pfs_spawn_thread (arg=0x55eefef189b8) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#34 0x000014c067b9e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#35 0x000014c06778d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.37 (dbg), 10.2.37 (opt), 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (dbg), 10.5.9 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

 Comments   
Comment by Roel Van de Paar [ 2021-02-17 ]

I have one now without the need to set innodb_limit_optimistic_insert_debug and this one is btr_cur_optimistic_insert instead of btr_cur_pessimistic_insert

# mysqld options required for replay:  --log_bin_trust_function_creators=1
 
SET sql_mode='';
 
DELIMITER //
 
CREATE FUNCTION f () RETURNS INT BEGIN INSERT INTO t VALUES(1);RETURN 1;END; //
 
DELIMITER ;
 
CREATE TEMPORARY TABLE t(c INT);
 
INSERT INTO t SELECT f();

Leads to:

10.6.0 bfb4761ca04704d68dba51f76d7c9967f880a6ee (Debug)

 
mysqld: /test/10.6_dbg/storage/innobase/trx/trx0rec.cc:2015: 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 `static_cast<ins_node_t*>(thr->run_node)->bulk_insert' failed.

10.6.0 bfb4761ca04704d68dba51f76d7c9967f880a6ee (Debug)

 
Core was generated by `/test/MD110221-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x14d555616700 (LWP 3555930))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x0000556e39baf55c in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x0000556e393474de in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x000014d56c48c859 in __GI_abort () at abort.c:79
 
#6  0x000014d56c48c729 in __assert_fail_base (fmt=0x14d56c622588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x556e39fbf6b8 "static_cast<ins_node_t*>(thr->run_node)->bulk_insert", file=0x556e39fbea30 "/test/10.6_dbg/storage/innobase/trx/trx0rec.cc", line=2015, function=<optimized out>) at assert.c:92
 
#7  0x000014d56c49df36 in __GI___assert_fail (assertion=assertion@entry=0x556e39fbf6b8 "static_cast<ins_node_t*>(thr->run_node)->bulk_insert", file=file@entry=0x556e39fbea30 "/test/10.6_dbg/storage/innobase/trx/trx0rec.cc", line=line@entry=2015, function=function@entry=0x556e39fbf5a8 "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  0x0000556e399624e0 in trx_undo_report_row_operation (thr=thr@entry=0x14d524024870, index=index@entry=0x14d524022608, clust_entry=clust_entry@entry=0x14d524052648, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x14d555613100) at /test/10.6_dbg/storage/innobase/trx/trx0rec.cc:2015
 
#9  0x0000556e399beb9f in btr_cur_ins_lock_and_undo (flags=flags@entry=2, cursor=cursor@entry=0x14d555613610, entry=entry@entry=0x14d524052648, thr=thr@entry=0x14d524024870, mtr=mtr@entry=0x14d555613bd0, inherit=inherit@entry=0x14d5556131e7) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:3274
 
#10 0x0000556e399c56a1 in btr_cur_optimistic_insert (flags=flags@entry=2, cursor=cursor@entry=0x14d555613610, offsets=offsets@entry=0x14d5556135d8, heap=heap@entry=0x14d5556135d0, entry=entry@entry=0x14d524052648, rec=rec@entry=0x14d5556135e8, big_rec=0x14d5556135c8, n_ext=<optimized out>, thr=0x14d524024870, mtr=0x14d555613bd0) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:3501
 
#11 0x0000556e3989e968 in row_ins_clust_index_entry_low (flags=flags@entry=2, mode=<optimized out>, mode@entry=2, index=index@entry=0x14d524022608, n_uniq=n_uniq@entry=0, entry=entry@entry=0x14d524052648, n_ext=n_ext@entry=0, thr=<optimized out>) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:2783
 
#12 0x0000556e398a0504 in row_ins_clust_index_entry (index=index@entry=0x14d524022608, entry=entry@entry=0x14d524052648, thr=thr@entry=0x14d524024870, n_ext=n_ext@entry=0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3255
 
#13 0x0000556e398a50b5 in row_ins_index_entry (thr=0x14d524024870, entry=0x14d524052648, index=0x14d524022608) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3380
 
#14 row_ins_index_entry_step (thr=0x14d524024870, node=0x14d524024650) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3549
 
#15 row_ins (thr=0x14d524024870, node=0x14d524024650) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3695
 
#16 row_ins_step (thr=thr@entry=0x14d524024870) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3837
 
#17 0x0000556e398c9754 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x14d524023498 "\375\001", prebuilt=0x14d524024158, ins_mode=ROW_INS_NORMAL) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1384
 
#18 0x0000556e397535dd in ha_innobase::write_row (this=0x14d524023900, record=0x14d524023498 "\375\001") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7361
 
#19 0x0000556e3935b826 in handler::ha_write_row (this=0x14d524023900, buf=0x14d524023498 "\375\001") at /test/10.6_dbg/sql/handler.cc:7151
 
#20 0x0000556e39031547 in write_record (thd=0x14d524000db8, table=0x14d524023008, info=info@entry=0x14d524015208, sink=0x0) at /test/10.6_dbg/sql/sql_insert.cc:2106
 
#21 0x0000556e3903199f in select_insert::send_data (this=0x14d5240151b8, values=<optimized out>) at /test/10.6_dbg/sql/sql_insert.cc:4076
 
#22 0x0000556e391040d2 in select_result_sink::send_data_with_check (sent=0, u=<optimized out>, items=<optimized out>, this=<optimized out>) at /test/10.6_dbg/sql/sql_class.h:5377
 
#23 JOIN::exec_inner (this=this@entry=0x14d524015270) at /test/10.6_dbg/sql/sql_select.cc:4344
 
#24 0x0000556e39104fbc in JOIN::exec (this=this@entry=0x14d524015270) at /test/10.6_dbg/sql/sql_select.cc:4256
 
#25 0x0000556e3910321c in mysql_select (thd=thd@entry=0x14d524000db8, tables=0x0, fields=@0x14d524012fc0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14d524013ff8, last = 0x14d524013ff8, elements = 1}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2202244745984, result=0x14d5240151b8, unit=0x14d524004f88, select_lex=0x14d524012e70) at /test/10.6_dbg/sql/sql_select.cc:4729
 
#26 0x0000556e391034e2 in handle_select (thd=thd@entry=0x14d524000db8, lex=lex@entry=0x14d524004ec0, result=result@entry=0x14d5240151b8, setup_tables_done_option=setup_tables_done_option@entry=1073741824) at /test/10.6_dbg/sql/sql_select.cc:417
 
#27 0x0000556e39084f65 in mysql_execute_command (thd=thd@entry=0x14d524000db8) at /test/10.6_dbg/sql/sql_parse.cc:4599
 
#28 0x0000556e3906f21a in mysql_parse (thd=thd@entry=0x14d524000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14d5556153d0) at /test/10.6_dbg/sql/sql_parse.cc:7906
 
#29 0x0000556e3907d30b in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14d524000db8, packet=packet@entry=0x14d52401aac9 "INSERT INTO t SELECT f()", packet_length=packet_length@entry=24) at /test/10.6_dbg/sql/sql_class.h:1295
 
#30 0x0000556e3908063d in do_command (thd=0x14d524000db8) at /test/10.6_dbg/sql/sql_parse.cc:1365
 
#31 0x0000556e391dc1ab in do_handle_one_connection (connect=<optimized out>, connect@entry=0x556e3c1a9058, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#32 0x0000556e391dc8af in handle_one_connection (arg=arg@entry=0x556e3c1a9058) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#33 0x0000556e3969027d in pfs_spawn_thread (arg=0x556e3c0ce998) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#34 0x000014d56c99a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#35 0x000014d56c589293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.37 (dbg), 10.2.37 (opt), 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (dbg), 10.5.9 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

Comment by Marko Mäkelä [ 2021-03-19 ]

Hi Roel, is this still repeateable after the opt-in mechanism was introduced in MDEV-24818? To have some chance of repeating this, I think that the following will be needed:

SET unique_checks=0, foreign_key_checks=0;

Comment by Roel Van de Paar [ 2021-03-31 ]

I tested both testcases, both with and without

SET unique_checks=0, foreign_key_checks=0;

Against 10.6, debug, at revision 1bd4115841ecded24217e5d753ed4d9822b4cffd (trunk as at 1/4/21), and the issue is no longer repeatable.

Generated at Thu Feb 08 09:33:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.