[MDEV-27843] Assertion `index->table->persistent_autoinc' failed in btr_read_autoinc Created: 2022-02-15  Updated: 2023-04-27

Status: Confirmed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Unresolved Votes: 0
Labels: not-10.5

Issue Links:
Problem/Incident
is caused by MDEV-25664 Potential hang in purge when virtual ... Closed
Relates
relates to MDEV-26951 gcol.innodb_virtual_basic fails with ... Stalled

 Description   

Setting to minor because I can only reproduce it on 10.2 debug builds. Please adjust accordingly if you find out that higher versions are affected.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t (id INT AUTO_INCREMENT PRIMARY KEY, a VARCHAR(8), b INT, c INT AS (b), KEY(a,c)) ENGINE=InnoDB;
 
INSERT INTO t (a) VALUES ('foo');
 
UPDATE t SET a = 'bar';
 
 
 
--source include/restart_mysqld.inc
 
--sleep 1
 
 
 
ALTER TABLE t ADD f INT;
 
 
 
# Cleanup
 
DROP TABLE t;

10.2 e777645d

 
mysqld: /data/src/10.2/storage/innobase/btr/btr0btr.cc:1342: ib_uint64_t btr_read_autoinc(dict_index_t*): Assertion `index->table->persistent_autoinc' failed.
 
220215  2:31:45 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f8855c23662 in __GI___assert_fail (assertion=0x5608984fb4a0 "index->table->persistent_autoinc", file=0x5608984fa578 "/data/src/10.2/storage/innobase/btr/btr0btr.cc", line=1342, function=0x5608984fb458 "ib_uint64_t btr_read_autoinc(dict_index_t*)") at assert.c:101
 
#8  0x0000560897f574c2 in btr_read_autoinc (index=0x7f8820012a10) at /data/src/10.2/storage/innobase/btr/btr0btr.cc:1342
 
#9  0x0000560897d815af in prepare_inplace_alter_table_dict (ha_alter_info=0x7f884bfb1070, altered_table=0x7f87f81339c0, old_table=0x7f882000c6d0, table_name=0x7f8820009e75 "t", flags=33, flags2=80, fts_doc_id_col=18446744073709551615, add_fts_doc_id=false, add_fts_doc_id_idx=false) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:4982
 
#10 0x0000560897d84dca in ha_innobase::prepare_inplace_alter_table (this=0x7f882000d2d8, altered_table=0x7f87f81339c0, ha_alter_info=0x7f884bfb1070) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:6118
 
#11 0x0000560897b53165 in handler::ha_prepare_inplace_alter_table (this=0x7f882000d2d8, altered_table=0x7f87f81339c0, ha_alter_info=0x7f884bfb1070) at /data/src/10.2/sql/handler.cc:4366
 
#12 0x00005608979a031d in mysql_inplace_alter_table (thd=0x7f87f8000d90, table_list=0x7f87f80148d8, table=0x7f882000c6d0, altered_table=0x7f87f81339c0, ha_alter_info=0x7f884bfb1070, inplace_supported=HA_ALTER_INPLACE_SHARED_LOCK_AFTER_PREPARE, target_mdl_request=0x7f884bfb1100, alter_ctx=0x7f884bfb16b0) at /data/src/10.2/sql/sql_table.cc:7487
 
#13 0x00005608979a6387 in mysql_alter_table (thd=0x7f87f8000d90, new_db=0x7f87f8014ef8 "test", new_name=0x0, create_info=0x7f884bfb22d0, table_list=0x7f87f80148d8, alter_info=0x7f884bfb2220, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9695
 
#14 0x0000560897a236aa in Sql_cmd_alter_table::execute (this=0x7f87f8014fe8, thd=0x7f87f8000d90) at /data/src/10.2/sql/sql_alter.cc:333
 
#15 0x00005608978d479d in mysql_execute_command (thd=0x7f87f8000d90) at /data/src/10.2/sql/sql_parse.cc:6017
 
#16 0x00005608978d9532 in mysql_parse (thd=0x7f87f8000d90, rawbuf=0x7f87f8014808 "ALTER TABLE t ADD f INT", length=23, parser_state=0x7f884bfb35e0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7793
 
#17 0x00005608978c78d5 in dispatch_command (command=COM_QUERY, thd=0x7f87f8000d90, packet=0x7f87f8008b61 "ALTER TABLE t ADD f INT", packet_length=23, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
 
#18 0x00005608978c63ee in do_command (thd=0x7f87f8000d90) at /data/src/10.2/sql/sql_parse.cc:1381
 
#19 0x0000560897a1e1d2 in do_handle_one_connection (connect=0x56089a78b730) at /data/src/10.2/sql/sql_connect.cc:1336
 
#20 0x0000560897a1df46 in handle_one_connection (arg=0x56089a78b730) at /data/src/10.2/sql/sql_connect.cc:1241
 
#21 0x0000560898226827 in pfs_spawn_thread (arg=0x56089a775a50) at /data/src/10.2/storage/perfschema/pfs.cc:1869
 
#22 0x00007f88560e7ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#23 0x00007f8855cecdef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

--sleep is somehow important. Also, while the test case fails for me every time, the presence of sleep indicates that it might be unstable on different machines and builds. Try to change it back and forth if the test doesn't fail for you.

 Comments   
Comment by Marko Mäkelä [ 2022-02-15 ]

I easily repeated a crash with 10.3 and 10.4, but not 10.5 or 10.9. Possibly we can thank MDEV-16678 in 10.5 for this.
A small but important change that I applied to the test was to prevent MDEV-11369:

ALTER TABLE t ADD f INT, FORCE, ALGORITHM=INPLACE;

Alternative:

./mtr --mysqld=--innodb-instant-alter-column-allowed=never

The crash:

10.3 e928fdbff1369036694320ee13b99d13fe6a3b60

 
mysqltest: At line 10: query 'ALTER TABLE t ADD f INT, FORCE, ALGORITHM=INPLACE' failed: 2013: Lost connection to MySQL server during query
 
…
 
#7  0x00007f5ed9be0212 in __GI___assert_fail (assertion=0x5575b5be4778 "index->table->persistent_autoinc", file=0x5575b5be3d20 "/mariadb/10.3/storage/innobase/btr/btr0btr.cc", line=1338, function=0x5575b5be4748 "ib_uint64_t btr_read_autoinc(dict_index_t*)") at assert.c:101
 
#8  0x00005575b5669f18 in btr_read_autoinc (index=index@entry=0x7f5e840126f0) at /mariadb/10.3/storage/innobase/btr/btr0btr.cc:1338
 
#9  0x00005575b544b90b in prepare_inplace_alter_table_dict (ha_alter_info=ha_alter_info@entry=0x7f5eceb57200, altered_table=altered_table@entry=0x7f5e7013c668, old_table=<optimized out>, table_name=<optimized out>, flags=<optimized out>, flags2=<optimized out>, fts_doc_id_col=<optimized out>, add_fts_doc_id=<optimized out>, add_fts_doc_id_idx=<optimized out>) at /mariadb/10.3/storage/innobase/handler/handler0alter.cc:5773
 
#10 0x00005575b5450bca in ha_innobase::prepare_inplace_alter_table (this=0x7f5e8c00cc40, altered_table=<optimized out>, ha_alter_info=<optimized out>) at /mariadb/10.3/storage/innobase/handler/handler0alter.cc:7012
 
…

The table definition had been loaded by purge, but the auto-increment counter had not been initialized at that time:

#0  dict_load_table_low (name=@0x7ff9c4af9480: {m_name = 0x7ff9e000a090 "test/t"}, rec=rec@entry=0x7ff9e765c352 "test/t", table=table@entry=0x7ff9c4af8c78)
 
    at /mariadb/10.3/storage/innobase/dict/dict0load.cc:2645
 
#1  0x0000564b778c2596 in dict_load_table_one (name=@0x7ff9c4af9480: {m_name = 0x7ff9e000a090 "test/t"}, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_FK_NOKEY, fk_tables=std::deque with 0 elements)
 
    at /mariadb/10.3/storage/innobase/dict/dict0load.cc:2927
 
#2  0x0000564b778ba9a4 in dict_load_table (name=0x7ff9e000a090 "test/t", ignore_err=ignore_err@entry=DICT_ERR_IGNORE_FK_NOKEY) at /mariadb/10.3/storage/innobase/dict/dict0load.cc:2746
 
#3  0x0000564b778c4103 in dict_load_table_on_id (table_id=table_id@entry=20, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_FK_NOKEY) at /mariadb/10.3/storage/innobase/dict/dict0load.cc:3185
 
#4  0x0000564b7789e790 in dict_table_open_on_id_low (table_id=table_id@entry=20, ignore_err=DICT_ERR_IGNORE_FK_NOKEY, open_only_if_in_cache=0) at /mariadb/10.3/storage/innobase/include/dict0priv.inl:90
 
#5  0x0000564b778a683f in dict_table_open_on_id (table_id=20, dict_locked=dict_locked@entry=0, table_op=table_op@entry=DICT_TABLE_OP_NORMAL) at /mariadb/10.3/storage/innobase/dict/dict0dict.cc:824
 
#6  0x0000564b7770dabf in row_purge_parse_undo_rec (node=node@entry=0x564b792e8018, undo_rec=undo_rec@entry=0x7ff9d4011540 "", updated_extern=updated_extern@entry=0x7ff9c4af9c3f, thr=thr@entry=0x564b792e7f58)
 
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:1069

Indexed virtual columns play a role here because ha_innobase::open() would normally invoke initialize_auto_increment(). Here it did not:

#0  ha_innobase::open (this=0x7ff9dc00d1a0, name=<optimized out>) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:6428
 
#1  0x0000564b7734266a in handler::ha_open (this=0x7ff9dc00d1a0, table_arg=table_arg@entry=0x7ff9dc00c5c8, name=0x7ff9dc00a020 "./test/t", mode=2, test_if_locked=test_if_locked@entry=18, 
    mem_root=mem_root@entry=0x0, partitions_to_open=0x0) at /mariadb/10.3/sql/handler.cc:2767
 
#2  0x0000564b771b8ae7 in open_table_from_share (thd=thd@entry=0x7ff9dc0011c8, share=share@entry=0x7ff9dc009ae0, alias=alias@entry=0x7ff9dc0090d8, db_stat=db_stat@entry=33, prgflag=prgflag@entry=8, 
    ha_open_flags=18, outparam=0x7ff9dc00c5c8, is_create_table=false, partitions_to_open=0x0) at /mariadb/10.3/sql/table.cc:3592
 
#3  0x0000564b77057d9b in open_table (thd=thd@entry=0x7ff9dc0011c8, table_list=table_list@entry=0x7ff9dc009090, ot_ctx=ot_ctx@entry=0x7ff9c54fa580) at /mariadb/10.3/sql/sql_base.cc:1992
 
#4  0x0000564b770798af in open_purge_table (thd=thd@entry=0x7ff9dc0011c8, db=db@entry=0x7ff9c54fa620 "test", dblen=4, tb=tb@entry=0x7ff9c54fa7c0 "t", tblen=1) at /mariadb/10.3/sql/sql_class.cc:4772
 
#5  0x0000564b7756c736 in innodb_acquire_mdl (thd=thd@entry=0x7ff9dc0011c8, table=table@entry=0x7ff9e00123f0) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:20874
 
#6  0x0000564b7756ca72 in innodb_find_table_for_vc (thd=0x7ff9dc0011c8, table=table@entry=0x7ff9e00123f0) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:20948
 
#7  0x0000564b7758c0e0 in innobase_init_vc_templ (table=0x7ff9e00123f0) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:20986
 
#8  0x0000564b7770ded2 in row_purge_parse_undo_rec (node=node@entry=0x564b792e8650, undo_rec=undo_rec@entry=0x7ff9d40134a8 "", updated_extern=updated_extern@entry=0x7ff9c54fac3f, thr=thr@entry=0x564b792e81d0)
 
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:1108

Here, for_vc_purge holds and the call will be skipped:

	const my_bool for_vc_purge = THDVAR(thd, background_thread);
 
 
 
	if (for_vc_purge || !m_prebuilt->table
 
	    || m_prebuilt->table->is_temporary()
 
	    || m_prebuilt->table->persistent_autoinc
 
	    || !m_prebuilt->table->is_readable()) {
 
	} else if (const Field* ai = table->found_next_number_field) {
 
		initialize_auto_increment(m_prebuilt->table, ai);
 
	}

This condition was added in MDEV-25664 in order to avoid a hang during purge.

In the trace of 10.9 that I tested, the table is likewise opened by purge:

#0  dict_load_table_on_id (table_id=table_id@entry=18, 
    ignore_err=DICT_ERR_IGNORE_FK_NOKEY)
 
    at /mariadb/10.9/storage/innobase/dict/dict0load.cc:2487
 
#1  0x000055baa9cff89d in dict_table_open_on_id (table_id=18, 
    dict_locked=dict_locked@entry=false, 
    table_op=table_op@entry=DICT_TABLE_OP_NORMAL, thd=0x55baac9c2668, 
    mdl=mdl@entry=0x55baacb07728)
 
    at /mariadb/10.9/storage/innobase/dict/dict0dict.cc:851
 
#2  0x000055baa9ba7ee5 in row_purge_parse_undo_rec (

But, the purge did not invoke ha_innobase::open() for this table. The first ha_innobase::open() call was for the ALTER TABLE, which is when the dict_table_t::persistent_autoinc was correctly initialized:

#0  initialize_auto_increment (table=0x7f6a9000f518, field=0x7f6a8402ef60) at /mariadb/10.9/storage/innobase/handler/ha_innodb.cc:5841
 
#1  0x000055baa9a134e0 in ha_innobase::open (this=0x7f6a84016640, name=<optimized out>) at /mariadb/10.9/storage/innobase/handler/ha_innodb.cc:6107
 
#2  0x000055baa9680788 in handler::ha_open (this=0x7f6a84016640, table_arg=table_arg@entry=0x7f6a84030c38, name=0x7f6a8403abd8 "./test/t", mode=2, test_if_locked=test_if_locked@entry=8210, 
    mem_root=mem_root@entry=0x0, partitions_to_open=0x0) at /mariadb/10.9/sql/handler.cc:3310
 
#3  0x000055baa94a699e in open_table_from_share (thd=thd@entry=0x7f6a84001ab8, share=share@entry=0x7f6a8403a630, alias=alias@entry=0x7f6a840178b0, db_stat=db_stat@entry=33, prgflag=prgflag@entry=8, 
    ha_open_flags=8210, outparam=0x7f6a84030c38, is_create_table=false, partitions_to_open=0x0) at /mariadb/10.9/sql/table.cc:4337
 
#4  0x000055baa92e8f71 in open_table (thd=thd@entry=0x7f6a84001ab8, table_list=table_list@entry=0x7f6a84017868, ot_ctx=ot_ctx@entry=0x7f6aa8054230) at /mariadb/10.9/sql/sql_base.cc:2003
 
#5  0x000055baa92ea6c5 in open_and_process_table (thd=thd@entry=0x7f6a84001ab8, tables=tables@entry=0x7f6a84017868, counter=counter@entry=0x7f6aa8054334, flags=flags@entry=0, 
    prelocking_strategy=prelocking_strategy@entry=0x7f6aa8054358, has_prelocking_list=has_prelocking_list@entry=false, ot_ctx=0x7f6aa8054230) at /mariadb/10.9/sql/sql_base.cc:3809
 
#6  0x000055baa92ec5c0 in open_tables (thd=thd@entry=0x7f6a84001ab8, options=@0x7f6a840073c8: {m_options = DDL_options_st::OPT_NONE}, start=start@entry=0x7f6aa8054318, counter=counter@entry=0x7f6aa8054334, 
    flags=flags@entry=0, prelocking_strategy=prelocking_strategy@entry=0x7f6aa8054358) at /mariadb/10.9/sql/sql_base.cc:4292
 
#7  0x000055baa946a537 in open_tables (prelocking_strategy=0x7f6aa8054358, flags=0, counter=0x7f6aa8054334, tables=0x7f6aa8054318, thd=0x7f6a84001ab8) at /mariadb/10.9/sql/sql_base.h:265
 
#8  mysql_alter_table (thd=thd@entry=0x7f6a84001ab8, new_db=new_db@entry=0x7f6a84006760, new_name=0x7f6a84006b78, create_info=create_info@entry=0x7f6aa8056570, table_list=<optimized out>, 
    table_list@entry=0x7f6a84017868, alter_info=alter_info@entry=0x7f6aa8056480, order_num=0, order=0x0, ignore=false, if_exists=false) at /mariadb/10.9/sql/sql_table.cc:9889
 
#9  0x000055baa94f27ea in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7f6a84001ab8) at /mariadb/10.9/sql/sql_alter.cc:547
 
#10 0x000055baa9380fdc in mysql_execute_command (thd=thd@entry=0x7f6a84001ab8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /mariadb/10.9/sql/sql_parse.cc:5988
 
#11 0x000055baa938236d in mysql_parse (thd=thd@entry=0x7f6a84001ab8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f6aa80573c0) at /mariadb/10.9/sql/sql_parse.cc:8027
 
#12 0x000055baa9384a53 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f6a84001ab8, packet=packet@entry=0x7f6a8400bd69 "ALTER TABLE t ADD f INT, FORCE, ALGORITHM=INPLACE", 
    packet_length=packet_length@entry=49, blocking=blocking@entry=true) at /mariadb/10.9/sql/sql_parse.cc:1894

Here is a slightly better test that I used, to ensure that nothing will be purged before the server is restarted:

--source include/have_innodb.inc
 
 
 
--let $restart_parameters=--innodb-force-recovery=2
 
--source include/restart_mysqld.inc
 
 
 
CREATE TABLE t (id INT AUTO_INCREMENT PRIMARY KEY, a VARCHAR(8), b INT, c INT AS (b), KEY(a,c)) ENGINE=InnoDB;
 
INSERT INTO t (a) VALUES ('foo');
 
UPDATE t SET a = 'bar';
 
 
 
--let $restart_parameters=
 
--source include/restart_mysqld.inc
 
--sleep 1
 
 
 
ALTER TABLE t ADD f INT, FORCE, ALGORITHM=INPLACE;
 
 
 
# Cleanup
 
DROP TABLE t;

The sleep could still be replaced with wait_all_purged.inc.

I am reassigning this to thiru because he worked on MDEV-16678 as well as some earlier fixes in this area.

Comment by Marko Mäkelä [ 2022-04-29 ]

I think that this needs to be investigated and fixed as part of MDEV-26951.

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