[MDEV-24613] Assertion `next_insert_id >= auto_inc_interval_for_cur_row.minimum()' failed in handler::update_auto_increment from sql/structs.h:410 Created: 2021-01-18  Updated: 2022-02-08

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.6
Fix Version/s: 10.6

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: rr-profile

Issue Links:
Relates
relates to MDEV-15800 Assertion `next_insert_id >= auto_inc... Closed
relates to MDEV-24038 Assertion `next_insert_id >= auto_inc... Confirmed
relates to MDEV-27770 Assertion `next_insert_id >= auto_inc... Closed

 Description   

Could be connected with both MDEV-15800 and MDEV-24038, however this issue is in sql/structs.h:410 whereas those are not. It seems that this bug will only show on multi-threaded runs. Note that the stack below is a rr based stack and thus has more initial frames.

10.6.0 9a08fcbf60567992971262ececee8d8429c20756

mysqld: /test/10.6_dbg/sql/handler.cc:3523: int handler::update_auto_increment(): Assertion `next_insert_id >= auto_inc_interval_for_cur_row.minimum()' failed.

10.6.0 9a08fcbf60567992971262ececee8d8429c20756

Core was generated by `/test/MD160121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'.
Program terminated with signal SIGABRT, Aborted.
#0  0x0000000070000002 in ?? ()
[Current thread is 1 (Thread 0x325b3bfff700 (LWP 1536605))]
(gdb) bt
#0  0x0000000070000002 in ?? ()
#1  0x000002e12ee9d3b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120
#2  0x000002e12ee992ff in traced_raw_syscall (call=call@entry=0x14de0489efa0) at ./src/preload/syscallbuf.c:229
#3  0x000002e12ee9a978 in sys_fcntl (call=<optimized out>) at ./src/preload/syscallbuf.c:1291
#4  syscall_hook_internal (call=0x14de0489efa0) at ./src/preload/syscallbuf.c:2855
#5  syscall_hook (call=0x14de0489efa0) at ./src/preload/syscallbuf.c:2987
#6  0x000002e12ee991da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282
#7  0x000002e12ee9920a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417
#8  0x000002e12ee99263 in _syscall_hook_trampoline_89_c2_f7_da () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:463
#9  0x000028ed6a312f0c in __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#10 0x000055a5e4bcaab1 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
#11 0x000055a5e4353856 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330
#12 <signal handler called>
#13 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#14 0x00002b9f5130f859 in __GI_abort () at abort.c:79
#15 0x00002b9f5130f729 in __assert_fail_base (fmt=0x2b9f514a5588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55a5e4ec9870 "next_insert_id >= auto_inc_interval_for_cur_row.minimum()", file=0x55a5e4ec783f "/test/10.6_dbg/sql/handler.cc", line=3523, function=<optimized out>) at assert.c:92
#16 0x00002b9f51320f36 in __GI___assert_fail (assertion=assertion@entry=0x55a5e4ec9870 "next_insert_id >= auto_inc_interval_for_cur_row.minimum()", file=file@entry=0x55a5e4ec783f "/test/10.6_dbg/sql/handler.cc", line=line@entry=3523, function=function@entry=0x55a5e4ec98b0 "int handler::update_auto_increment()") at assert.c:101
#17 0x000055a5e435f36f in handler::update_auto_increment (this=this@entry=0x14dde80dedf0) at /test/10.6_dbg/sql/structs.h:410
#18 0x000055a5e47634af in ha_innobase::write_row (this=0x14dde80dedf0, record=0x14dde80de988 "\377\001", '\245' <repeats 14 times>, "\320\351\r\350\335\024") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7304
#19 0x000055a5e4367b42 in handler::ha_write_row (this=0x14dde80dedf0, buf=0x14dde80de988 "\377\001", '\245' <repeats 14 times>, "\320\351\r\350\335\024") at /test/10.6_dbg/sql/handler.cc:7151
#20 0x000055a5e403eb87 in write_record (thd=0x67410000db8, table=0x14dde80de4f8, info=info@entry=0x67410014a98, sink=0x0) at /test/10.6_dbg/sql/sql_insert.cc:1784
#21 0x000055a5e403fc63 in select_insert::send_data (this=0x67410014a48, values=<optimized out>) at /test/10.6_dbg/sql/sql_insert.cc:4073
#22 0x000055a5e40f4787 in select_result_sink::send_data_with_check (sent=<optimized out>, u=<optimized out>, items=@0x67410014e88: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x67410016b20, last = 0x67410016b20, elements = 1}, <No data fields>}, this=<optimized out>) at /test/10.6_dbg/sql/sql_class.h:5376
#23 end_send (join=0x67410014b00, join_tab=0x674100164f8, end_of_records=<optimized out>) at /test/10.6_dbg/sql/sql_select.cc:21794
#24 0x000055a5e40c3f26 in evaluate_join_record (join=join@entry=0x67410014b00, join_tab=0x67410016148, error=error@entry=0) at /test/10.6_dbg/sql/sql_select.cc:20817
#25 0x000055a5e410511d in AGGR_OP::end_send (this=this@entry=0x674100169d0) at /test/10.6_dbg/sql/sql_select.cc:28906
#26 0x000055a5e4105460 in sub_select_postjoin_aggr (join=0x67410014b00, join_tab=0x67410016148, end_of_records=<optimized out>) at /test/10.6_dbg/sql/sql_select.cc:20304
#27 0x000055a5e40d995e in sub_select (join=0x67410014b00, join_tab=0x67410015d98, end_of_records=<optimized out>) at /test/10.6_dbg/sql/sql_select.cc:20538
#28 0x000055a5e41125d7 in do_select (procedure=<optimized out>, join=0x67410014b00) at /test/10.6_dbg/sql/sql_select.cc:20143
#29 JOIN::exec_inner (this=this@entry=0x67410014b00) at /test/10.6_dbg/sql/sql_select.cc:4472
#30 0x000055a5e4112a14 in JOIN::exec (this=this@entry=0x67410014b00) at /test/10.6_dbg/sql/sql_select.cc:4252
#31 0x000055a5e4110c74 in mysql_select (thd=thd@entry=0x67410000db8, tables=0x674100136a0, fields=@0x674100131e8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x67410013648, last = 0x67410013648, elements = 1}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2200097262336, result=0x67410014a48, unit=0x67410004f80, select_lex=0x67410013098) at /test/10.6_dbg/sql/sql_select.cc:4668
#32 0x000055a5e4110f3a in handle_select (thd=thd@entry=0x67410000db8, lex=lex@entry=0x67410004eb8, result=result@entry=0x67410014a48, setup_tables_done_option=setup_tables_done_option@entry=1073741824) at /test/10.6_dbg/sql/sql_select.cc:417
#33 0x000055a5e4093380 in mysql_execute_command (thd=thd@entry=0x67410000db8) at /test/10.6_dbg/sql/sql_parse.cc:4594
#34 0x000055a5e407d66c in mysql_parse (thd=thd@entry=0x67410000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x325b3bffe3d0) at /test/10.6_dbg/sql/sql_parse.cc:7901
#35 0x000055a5e408b73f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x67410000db8, packet=packet@entry=0x67410008e59 "insert ignore into t1 select a from t1 as t2 on duplicate key update a=t1.a+1;", packet_length=packet_length@entry=78) at /test/10.6_dbg/sql/sql_class.h:1294
#36 0x000055a5e408ea7a in do_command (thd=0x67410000db8) at /test/10.6_dbg/sql/sql_parse.cc:1365
#37 0x000055a5e41e9a11 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55a5e8665de8, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#38 0x000055a5e41ea115 in handle_one_connection (arg=arg@entry=0x55a5e8665de8) at /test/10.6_dbg/sql/sql_connect.cc:1312
#39 0x000055a5e469e6ab in pfs_spawn_thread (arg=0x55a5e8665ec8) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#40 0x000028ed6a30a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#41 0x00002b9f5140c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

An rr trace is available on the rr server:

cd /data/854271/80/rr/mysqld-0
rr replay ${PWD}



 Comments   
Comment by Sergei Golubchik [ 2021-02-22 ]

Roel, could you please check if it's indeed a 10.6-only bug or it is present in earlier versions too?

Comment by Roel Van de Paar [ 2021-04-02 ]

I did another 3 day run (same server) on 10.5, and the bug is not seen there. It is thus likely 10.6 only.

Comment by Roel Van de Paar [ 2021-04-02 ]

Assigning back to Sanja as an rr trace (details above) is available for debugging.

Comment by Sergei Golubchik [ 2021-04-05 ]

What 10.6 change could've caused it? There aren't that many changes that could possibly affect it, in fact I don't remember any that deal with auto-increment

Comment by Roel Van de Paar [ 2021-04-05 ]

Another strange thing is that I have only seen this in 10.6 rr-based runs, not in other non-rr runs. Analyzing the rr trace may provide extra info.

Comment by Sergei Golubchik [ 2021-05-10 ]

So, what sequence of sql statements have caused it? after what 10.6 commit did it start to appear?

Comment by Roel Van de Paar [ 2021-05-24 ]

Removing need_feedback as there is a RR trace which can be reviewed and to avoid it from being looked into.

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