[MDEV-14663] Assertion `page_is_root(block->frame)' failed in innobase_add_instant_try Created: 2017-12-15  Updated: 2018-02-09  Resolved: 2018-02-09

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3
Fix Version/s: 10.3.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-11369 Instant add column for InnoDB Closed

 Description   

10.3 1951e7f05ae7b6069

 
mysqld: /data/src/10.3/storage/innobase/handler/handler0alter.cc:4332: bool innobase_add_instant_try(Alter_inplace_info*, ha_innobase_inplace_ctx*, const TABLE*, const TABLE*, trx_t*): Assertion `page_is_root(block->frame)' failed.
 
180201 15:41:07 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f3c18077ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055b88f6643b5 in innobase_add_instant_try (ha_alter_info=0x7f3c14ba32e0, ctx=0x7f3bac017650, altered_table=0x7f3bac5a9e30, table=0x7f3bac59d300, trx=0x7f3c14c87738) at /data/src/10.3/storage/innobase/handler/handler0alter.cc:4332
 
#9  0x000055b88f677c1b in commit_try_norebuild (ha_alter_info=0x7f3c14ba32e0, ctx=0x7f3bac017650, altered_table=0x7f3bac5a9e30, old_table=0x7f3bac59d300, trx=0x7f3c14c87738, table_name=0x7f3bac59ba0d "t1") at /data/src/10.3/storage/innobase/handler/handler0alter.cc:8710
 
#10 0x000055b88f67182e in ha_innobase::commit_inplace_alter_table (this=0x7f3bac5a2ac8, altered_table=0x7f3bac5a9e30, ha_alter_info=0x7f3c14ba32e0, commit=true) at /data/src/10.3/storage/innobase/handler/handler0alter.cc:9271
 
#11 0x000055b88f2fefba in handler::ha_commit_inplace_alter_table (this=0x7f3bac5a2ac8, altered_table=0x7f3bac5a9e30, ha_alter_info=0x7f3c14ba32e0, commit=true) at /data/src/10.3/sql/handler.cc:4395
 
#12 0x000055b88f0e55b7 in mysql_inplace_alter_table (thd=0x7f3bac000b00, table_list=0x7f3bac015b10, table=0x7f3bac59d300, altered_table=0x7f3bac5a9e30, ha_alter_info=0x7f3c14ba32e0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f3c14ba3450, alter_ctx=0x7f3c14ba40f0) at /data/src/10.3/sql/sql_table.cc:7665
 
#13 0x000055b88f0eaf30 in mysql_alter_table (thd=0x7f3bac000b00, new_db=0x7f3bac005090, new_name=0x7f3bac005440, create_info=0x7f3c14ba4cd0, table_list=0x7f3bac015b10, alter_info=0x7f3c14ba4c20, order_num=0, order=0x0, ignore=false) at /data/src/10.3/sql/sql_table.cc:9721
 
#14 0x000055b88f17412b in Sql_cmd_alter_table::execute (this=0x7f3bac016278, thd=0x7f3bac000b00) at /data/src/10.3/sql/sql_alter.cc:334
 
#15 0x000055b88f0164d0 in mysql_execute_command (thd=0x7f3bac000b00) at /data/src/10.3/sql/sql_parse.cc:6250
 
#16 0x000055b88f01aff8 in mysql_parse (thd=0x7f3bac000b00, rawbuf=0x7f3bac0159e8 "ALTER TABLE t1 ADD COLUMN extra INT /* QNO 1934 CON_ID 10 */", length=60, parser_state=0x7f3c14ba6630, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7977
 
#17 0x000055b88f00883f in dispatch_command (command=COM_QUERY, thd=0x7f3bac000b00, packet=0x7f3bac00b061 "ALTER TABLE t1 ADD COLUMN extra INT /* QNO 1934 CON_ID 10 */ ", packet_length=61, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1825
 
#18 0x000055b88f00727f in do_command (thd=0x7f3bac000b00) at /data/src/10.3/sql/sql_parse.cc:1370
 
#19 0x000055b88f16eb74 in do_handle_one_connection (connect=0x55b891e4e080) at /data/src/10.3/sql/sql_connect.cc:1402
 
#20 0x000055b88f16e901 in handle_one_connection (arg=0x55b891e4e080) at /data/src/10.3/sql/sql_connect.cc:1308
 
#21 0x00007f3c19d4e494 in start_thread (arg=0x7f3c14ba7700) at pthread_create.c:333
 
#22 0x00007f3c1813493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

To reproduce:

git clone https://github.com/elenst/rqg --branch mdev14663 rqg-mdev14663
 
cd rqg-mdev14663
 
./run <your basedir>

run is a one-line wrapper which runs RQG like this:

perl ./runall-new.pl --threads=2 --duration=600  --grammar=mdev14663.yy --skip-gendata --vardir1=/dev/shm/mdev14663 --basedir=$1

You can run it directly instead.

It starts the server with default options (except for weaker SQL mode and general logging on which are irrelevant) on port 19300 with the datadir in /dev/shm/mdev14663/data and runs 2-thread test flow which consists of ALTER TABLE, INSERT and UPDATE on one table. See ./mdev14663.yy for exact statements.

The crash usually happens for me within a minute or so, but it can vary on different machines.
Also reproducible on an ASAN with the same result.

Running in shm is not strictly necessary, but it takes much longer to get the crash, and seems less reliable.

If you need to run it on your already started server instead, run

perl ./gentest.pl --threads=2 --duration=600  --grammar=mdev14663.yy --dsn="dbi:mysql:user=root:host=127.0.0.1:port=3306:database=test"

(assuming that the server is running on port 3306). Again, it's faster and more reliable if the datadir is in shm.

 Comments   
Comment by Marko Mäkelä [ 2018-02-08 ]

In a locally reproduced failure, the primary key index consists of 3 pages: the root page (3), left leaf (4) and right leaf (447). The right leaf only contains one record, which looks like the 'default row' record which should only exist in the leftmost leaf page. The left leaf does not start with the 'default row' record. So, the problem seems to be in the very first instant ADD COLUMN of that table:

#8  0x0000000001c5a55e in innobase_add_instant_try (ha_alter_info=0x7fa2642dd320, 
    ctx=0x613000221ea0, altered_table=0x61f0002f1688, table=0x61f000096888, trx=0x7fa280d47f50)
 
    at /mariadb/10.3/storage/innobase/handler/handler0alter.cc:4332
 
#9  0x0000000001c6862d in commit_try_norebuild (ha_alter_info=0x7fa2642dd320, ctx=0x613000221ea0, 
    altered_table=0x61f0002f1688, old_table=0x61f000096888, trx=0x7fa280d47f50, 
    table_name=0x61c00071c725 "t1") at /mariadb/10.3/storage/innobase/handler/handler0alter.cc:8710
 
#10 0x0000000001c331e4 in ha_innobase::commit_inplace_alter_table (this=0x61d0003f52a0, 
    altered_table=0x61f0002f1688, ha_alter_info=0x7fa2642dd320, commit=true)
 
    at /mariadb/10.3/storage/innobase/handler/handler0alter.cc:9269

Comment by Marko Mäkelä [ 2018-02-08 ]

Correction: the leftmost leaf page is 447, followed by the leaf pages 4 and 320.
The leftmost leaf page contains only the 'default row' record, indicating that exactly one instant ADD COLUMN had already been executed, to add the column col1. The problem occurs when instantly adding another column:

ALTER TABLE t1 ADD COLUMN extra INT;

The problem ought to be this condition:

	if (rec_is_default_row(rec, index)) {
 
		ut_ad(page_rec_is_user_rec(rec));
 
		if (page_rec_is_last(rec, block->frame)) {
 
			goto empty_table;
 
		}

The second condition is wrong. We should only empty the table if the pre-existing 'default row' is the only record in the table. The condition fails to ensure that there is no successor page.

I will introduce efficient predicates page_has_prev(), page_has_next(), page_has_siblings(), because previously we were inefficiently decoding the aligned fields FIL_PAGE_PREV and FIL_PAGE_NEXT and then comparing the result to the byte-order-agnostic constant FIL_NULL.

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