[MDEV-18871] InnoDB: Assertion failure in que_graph_free_recursive upon DROP TABLE after operations related to versioning Created: 2019-03-09  Updated: 2020-05-24  Resolved: 2020-05-24

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Versioned Tables
Affects Version/s: 10.4
Fix Version/s: 10.4.7

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: None


 Description   

Note: It's quite possible that the problem has nothing to do with versioning, but the test case demands it, I don't have a different one so far. See also MDEV-18870 which has a similar test case, but a different crash.

--source include/have_innodb.inc
 
 
 
CREATE OR REPLACE TABLE t1 (
 
  s DATE,
 
  e DATE,
 
  PERIOD FOR app(s,e),
 
  row_start BIGINT UNSIGNED AS ROW START,
 
  row_end BIGINT UNSIGNED AS ROW END,
 
  PERIOD FOR SYSTEM_TIME(row_start,row_end)
 
) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
 
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2020-08-03','2025-01-05');
 
DELETE FROM t1 ORDER BY s LIMIT 1;
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2019-11-30','2021-10-17');
 
DELETE FROM t1 FOR PORTION OF app FROM '2019-02-10' TO '2021-09-29';
 
DELETE FROM t1;
 
DELETE HISTORY FROM t1;
 
DROP TABLE t1;

10.4 5a796f1f

 
2019-03-09 18:30:25 0x7fd52cc03700  InnoDB: Assertion failure in file /data/src/10.4/storage/innobase/que/que0que.cc line 558
 
InnoDB: We intentionally generate a memory trap.
 
 
 
#5  0x00007fd5338e23fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x000055b9646b58f8 in ut_dbg_assertion_failed (expr=0x0, file=0x55b964c952d0 "/data/src/10.4/storage/innobase/que/que0que.cc", line=558) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x000055b964599a3c in que_graph_free_recursive (node=0x7fd4d4152630) at /data/src/10.4/storage/innobase/que/que0que.cc:558
 
#8  0x000055b9645f3cc5 in row_prebuilt_free (prebuilt=0x7fd4d4151808, dict_locked=0) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1006
 
#9  0x000055b96448b82e in ha_innobase::close (this=0x7fd4d41500d8) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:6558
 
#10 0x000055b9641517e6 in handler::ha_close (this=0x7fd4d41500d8) at /data/src/10.4/sql/handler.cc:2968
 
#11 0x000055b963f28928 in closefrm (table=0x7fd4d400d200) at /data/src/10.4/sql/table.cc:3993
 
#12 0x000055b96407442d in intern_close_table (table=0x7fd4d400d200) at /data/src/10.4/sql/table_cache.cc:222
 
#13 0x000055b96407730f in tdc_remove_table (thd=0x7fd4d4000b00, remove_type=TDC_RT_REMOVE_ALL, db=0x7fd4d4015c28 "test", table_name=0x7fd4d4015548 "t1", kill_delayed_threads=false) at /data/src/10.4/sql/table_cache.cc:1151
 
#14 0x000055b963edb1a0 in mysql_rm_table_no_locks (thd=0x7fd4d4000b00, tables=0x7fd4d4015580, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.4/sql/sql_table.cc:2488
 
#15 0x000055b963eda2a5 in mysql_rm_table (thd=0x7fd4d4000b00, tables=0x7fd4d4015580, if_exists=false, drop_temporary=false, drop_sequence=false) at /data/src/10.4/sql/sql_table.cc:2114
 
#16 0x000055b963e0a5bc in mysql_execute_command (thd=0x7fd4d4000b00) at /data/src/10.4/sql/sql_parse.cc:5158
 
#17 0x000055b963e14b63 in mysql_parse (thd=0x7fd4d4000b00, rawbuf=0x7fd4d40154c8 "DROP TABLE t1", length=13, parser_state=0x7fd52cc02180, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8204
 
#18 0x000055b963e001a5 in dispatch_command (command=COM_QUERY, thd=0x7fd4d4000b00, packet=0x7fd4d413a1a1 "DROP TABLE t1", packet_length=13, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1829
 
#19 0x000055b963dfe98b in do_command (thd=0x7fd4d4000b00) at /data/src/10.4/sql/sql_parse.cc:1358
 
#20 0x000055b963f78703 in do_handle_one_connection (connect=0x55b9671744a0) at /data/src/10.4/sql/sql_connect.cc:1399
 
#21 0x000055b963f78474 in handle_one_connection (arg=0x55b9671744a0) at /data/src/10.4/sql/sql_connect.cc:1302
 
#22 0x000055b96446e031 in pfs_spawn_thread (arg=0x55b9671ba310) at /data/src/10.4/storage/perfschema/pfs.cc:1862
 
#23 0x00007fd5355b0494 in start_thread (arg=0x7fd52cc03700) at pthread_create.c:333
 
#24 0x00007fd53399693f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Non-debug crashes the same way.

 Comments   
Comment by Elena Stepanova [ 2019-03-09 ]

Changing the way the table gets closed, we can get somewhat different stack traces, some of them might be interesting in relation to open but not yet reproduced bugs:

In tc_purge instead of tdc_remove_table:

--source include/have_innodb.inc
 
 
 
CREATE OR REPLACE TABLE t1 (
 
  s DATE,
 
  e DATE,
 
  PERIOD FOR app(s,e),
 
  row_start BIGINT UNSIGNED AS ROW START,
 
  row_end BIGINT UNSIGNED AS ROW END,
 
  PERIOD FOR SYSTEM_TIME(row_start,row_end)
 
) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
 
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2020-08-03','2025-01-05');
 
DELETE FROM t1 ORDER BY s LIMIT 1;
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2019-11-30','2021-10-17');
 
DELETE FROM t1 FOR PORTION OF app FROM '2019-02-10' TO '2021-09-29';
 
DELETE FROM t1;
 
DELETE HISTORY FROM t1;
 
 
 
FLUSH TABLES;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.4

 
#5  0x00007f4f7fa103fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x000055c8c83c88f8 in ut_dbg_assertion_failed (expr=0x0, file=0x55c8c89a82d0 "/data/src/10.4/storage/innobase/que/que0que.cc", line=558) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x000055c8c82aca3c in que_graph_free_recursive (node=0x7f4f20151b50) at /data/src/10.4/storage/innobase/que/que0que.cc:558
 
#8  0x000055c8c8306cc5 in row_prebuilt_free (prebuilt=0x7f4f20150d28, dict_locked=0) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1006
 
#9  0x000055c8c819e82e in ha_innobase::close (this=0x7f4f2000d7e8) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:6558
 
#10 0x000055c8c7e647e6 in handler::ha_close (this=0x7f4f2000d7e8) at /data/src/10.4/sql/handler.cc:2968
 
#11 0x000055c8c7c3b928 in closefrm (table=0x7f4f2000c980) at /data/src/10.4/sql/table.cc:3993
 
#12 0x000055c8c7d8742d in intern_close_table (table=0x7f4f2000c980) at /data/src/10.4/sql/table_cache.cc:222
 
#13 0x000055c8c7d87835 in tc_purge (mark_flushed=false) at /data/src/10.4/sql/table_cache.cc:335
 
#14 0x000055c8c7a75f9e in purge_tables (purge_flag=false) at /data/src/10.4/sql/sql_base.cc:335
 
#15 0x000055c8c7a760b8 in close_cached_tables (thd=0x7f4f20000b00, tables=0x0, wait_for_refresh=true, timeout=86400) at /data/src/10.4/sql/sql_base.cc:364
 
#16 0x000055c8c7cc95ff in reload_acl_and_cache (thd=0x7f4f20000b00, options=4, tables=0x0, write_to_binlog=0x7f4f78d2f900) at /data/src/10.4/sql/sql_reload.cc:339
 
#17 0x000055c8c7b20039 in mysql_execute_command (thd=0x7f4f20000b00) at /data/src/10.4/sql/sql_parse.cc:5752
 
#18 0x000055c8c7b27b63 in mysql_parse (thd=0x7f4f20000b00, rawbuf=0x7f4f200154c8 "FLUSH TABLES", length=12, parser_state=0x7f4f78d30180, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8204
 
#19 0x000055c8c7b131a5 in dispatch_command (command=COM_QUERY, thd=0x7f4f20000b00, packet=0x7f4f20139ff1 "FLUSH TABLES", packet_length=12, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1829
 
#20 0x000055c8c7b1198b in do_command (thd=0x7f4f20000b00) at /data/src/10.4/sql/sql_parse.cc:1358
 
#21 0x000055c8c7c8b703 in do_handle_one_connection (connect=0x55c8cb4e84a0) at /data/src/10.4/sql/sql_connect.cc:1399
 
#22 0x000055c8c7c8b474 in handle_one_connection (arg=0x55c8cb4e84a0) at /data/src/10.4/sql/sql_connect.cc:1302
 
#23 0x000055c8c8181031 in pfs_spawn_thread (arg=0x55c8cb52e310) at /data/src/10.4/storage/perfschema/pfs.cc:1862
 
#24 0x00007f4f816de494 in start_thread (arg=0x7f4f78d31700) at pthread_create.c:333
 
#25 0x00007f4f7fac493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Comment by Elena Stepanova [ 2019-03-09 ]

In tc_remove_table instead of tdc_remove_table or tc_purge:

--source include/have_innodb.inc
 
 
 
CREATE OR REPLACE TABLE t1 (
 
  s DATE,
 
  e DATE,
 
  PERIOD FOR app(s,e),
 
  row_start BIGINT UNSIGNED AS ROW START,
 
  row_end BIGINT UNSIGNED AS ROW END,
 
  PERIOD FOR SYSTEM_TIME(row_start,row_end)
 
) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
 
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2020-08-03','2025-01-05');
 
DELETE FROM t1 ORDER BY s LIMIT 1;
 
INSERT INTO t1 (s,e) VALUES ('2020-08-03','2025-01-05'),('2019-11-30','2021-10-17');
 
DELETE FROM t1 FOR PORTION OF app FROM '2019-02-10' TO '2021-09-29';
 
DELETE FROM t1;
 
DELETE HISTORY FROM t1;
 
ALTER TABLE t1 DROP PERIOD IF EXISTS FOR x;
 
 
 
# Cleanup
 
DROP TABLE t1;


#6  0x00005579211c68f8 in ut_dbg_assertion_failed (expr=0x0, file=0x5579217a62d0 "/data/src/10.4/storage/innobase/que/que0que.cc", line=558) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x00005579210aaa3c in que_graph_free_recursive (node=0x7f9880152630) at /data/src/10.4/storage/innobase/que/que0que.cc:558
 
#8  0x0000557921104cc5 in row_prebuilt_free (prebuilt=0x7f9880151808, dict_locked=0) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1006
 
#9  0x0000557920f9c82e in ha_innobase::close (this=0x7f98801500d8) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:6558
 
#10 0x0000557920c627e6 in handler::ha_close (this=0x7f98801500d8) at /data/src/10.4/sql/handler.cc:2968
 
#11 0x0000557920a39928 in closefrm (table=0x7f988000d200) at /data/src/10.4/sql/table.cc:3993
 
#12 0x0000557920b8542d in intern_close_table (table=0x7f988000d200) at /data/src/10.4/sql/table_cache.cc:222
 
#13 0x0000557920b855c4 in tc_remove_table (table=0x7f988000d200) at /data/src/10.4/sql/table_cache.cc:260
 
#14 0x0000557920b85f8b in tc_release_table (table=0x7f988000d200) at /data/src/10.4/sql/table_cache.cc:474
 
#15 0x0000557920875855 in close_thread_table (thd=0x7f9880000b00, table_ptr=0x7f9880000be0) at /data/src/10.4/sql/sql_base.cc:1031
 
#16 0x00005579208750a1 in close_all_tables_for_name (thd=0x7f9880000b00, share=0x7f98801a2d88, extra=HA_EXTRA_NOT_USED, skip_table=0x0) at /data/src/10.4/sql/sql_base.cc:795
 
#17 0x00005579209fad83 in mysql_inplace_alter_table (thd=0x7f9880000b00, table_list=0x7f98800155d0, table=0x7f988000d200, altered_table=0x7f98800716f0, ha_alter_info=0x7f98cf1aa900, inplace_supported=HA_ALTER_INPLACE_INSTANT, target_mdl_request=0x7f98cf1aab30, alter_ctx=0x7f98cf1ab0e0) at /data/src/10.4/sql/sql_table.cc:7709
 
#18 0x0000557920a01371 in mysql_alter_table (thd=0x7f9880000b00, new_db=0x7f98800052a0, new_name=0x7f98800056a0, create_info=0x7f98cf1abcd0, table_list=0x7f98800155d0, alter_info=0x7f98cf1abc10, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_table.cc:9922
 
#19 0x0000557920a92b5a in Sql_cmd_alter_table::execute (this=0x7f9880015ca8, thd=0x7f9880000b00) at /data/src/10.4/sql/sql_alter.cc:499
 
#20 0x00005579209209ca in mysql_execute_command (thd=0x7f9880000b00) at /data/src/10.4/sql/sql_parse.cc:6393
 
#21 0x0000557920925b63 in mysql_parse (thd=0x7f9880000b00, rawbuf=0x7f98800154c8 "ALTER TABLE t1 DROP PERIOD IF EXISTS FOR x", length=42, parser_state=0x7f98cf1ad180, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8204
 
#22 0x00005579209111a5 in dispatch_command (command=COM_QUERY, thd=0x7f9880000b00, packet=0x7f988013a1a1 "ALTER TABLE t1 DROP PERIOD IF EXISTS FOR x", packet_length=42, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1829
 
#23 0x000055792090f98b in do_command (thd=0x7f9880000b00) at /data/src/10.4/sql/sql_parse.cc:1358
 
#24 0x0000557920a89703 in do_handle_one_connection (connect=0x557923834160) at /data/src/10.4/sql/sql_connect.cc:1399
 
#25 0x0000557920a89474 in handle_one_connection (arg=0x557923834160) at /data/src/10.4/sql/sql_connect.cc:1302
 
#26 0x0000557920f7f031 in pfs_spawn_thread (arg=0x557923879fd0) at /data/src/10.4/storage/perfschema/pfs.cc:1862
 
#27 0x00007f98dbb80494 in start_thread (arg=0x7f98cf1ae700) at pthread_create.c:333
 
#28 0x00007f98d9f6693f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Comment by Elena Stepanova [ 2020-05-16 ]

Doesn't fail anymore on the current 10.4 a4996f95 or 10.5 69077dea

Comment by Elena Stepanova [ 2020-05-24 ]

The behavior was first transformed into MDEV-19814 after this patch:

commit 48a662dae5cd5dcc2d3cd9cd03104b5152c1d23c 7056812ed15abb398089b9c6aa6d7bf5c3cb8c0e
 
Author:     Eugene Kosov
 
AuthorDate: Sun May 19 23:15:55 2019 +0300
 
Commit:     Marko Mäkelä
 
CommitDate: Mon May 20 10:23:17 2019 +0300
 
 
 
    MDEV-19486 Server crashes in row_upd or row_upd_del_mark_clust_rec on REPLACE into a versioned table
 
    
    row_insert_for_mysql(): InnoDB sets values for row_start and row_end.
 
    And this function used to return those values to server in
 
    ha_innobase::write_row().  This buggy behavior was removed. Also,
 
    a piece of code in this function was reformatted.
 
    
    upd_node_t::make_versioned_helper(): Assert that the preallocated size
 
    of the update vector is not exceeded.

And then eventually the test case started passing on 10.4 after this merge

commit 4c7a74396497ae28779016b5bd59283aeee0b6f4
 
Merge: de9e3930940 29df1003d9f
 
Author: Eugene Kosov
 
Date:   Fri Jul 26 15:22:31 2019 +0300
 
 
 
    Merge 10.3 into 10.4

which included

commit f6d0d309fa4ffe1d5890c09447d947103143a68a
 
Author: Aleksey Midenkov
 
Date:   Tue Jul 23 13:27:57 2019 +0300
 
 
 
    MDEV-19814 Assertion `update->n_fields < ulint(table->n_cols + table->n_v_cols)' on DELETE HISTORY
 
    
    Turn off versioned_write for DELETE HISTORY.

Generated at Thu Feb 08 08:47:22 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.