[MDEV-14663] Assertion `page_is_root(block->frame)' failed in innobase_add_instant_try - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.3(EOL)
Fix Version/s: 10.3.5
Component/s: Storage Engine - InnoDB
Labels:
None

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.

Attachments

Issue Links

is caused by

MDEV-11369 Instant add column for InnoDB

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2017-12-15 14:21

Elena Stepanova made changes - 2018-02-01 13:44

Field	Original Value	New Value
Attachment	threads [ 44793 ]

Elena Stepanova made changes - 2018-02-01 13:44

Comment

[ {noformat}
perl /home/travis/rqg/runall-new.pl --duration=350 --threads=6 --redefine=conf/mariadb/instant_add.yy --reporters=Backtrace,ErrorLog,Deadlock --engine=InnoDB --seed=1515233110 --basedir=/home/travis/server --mysqld=--max-statement-time=30 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/mariadb/oltp-transactional.yy --gendata=conf/mariadb/oltp.zz --rpl-mode=mixed --vardir=/home/travis/logs/vardir1_3
{noformat} ]

Elena Stepanova made changes - 2018-02-01 14:05

Fix Version/s		10.3 [ 22126 ]
Description	[Travis log\|https://api.travis-ci.org/v3/job/316707233/log.txt] {noformat:title=10.3 2b67b7cb08bf163df3e02115ddc13d05dc966c03} Version: '10.3.3-MariaDB-debug-log' socket: '/home/travis/logs/vardir1_1/mysql.sock' port: 19300 Source distribution 2017-12-15 11:09:09 17 [ERROR] InnoDB: Cannot save table statistics for table `test`.`t13`: Operation interrupted 2017-12-15 11:10:11 19 [Warning] InnoDB: Deleting persistent statistics for table `test`.`PP_K` /* Partition `p1` / failed: Unable to delete statistics for table test.PP_K#P#p1: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'PP_K#P#p1'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'PP_K#P#p1'; 2017-12-15 11:11:43 19 [ERROR] InnoDB: Cannot save table statistics for table `test`.`t1`: Lock wait timeout 2017-12-15 11:11:46 19 [Warning] InnoDB: Deleting persistent statistics for table `test`.`PP_I` / Partition `p0`, Subpartition `p0sp0` / failed: Unable to delete statistics for table test.PP_I#P#p0#SP#p0sp0: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'PP_I#P#p0#SP#p0sp0'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'PP_I#P#p0#SP#p0sp0'; 2017-12-15 11:12:29 18 [ERROR] InnoDB: Unable to rename statistics from test.PP_K#P#p0 to test.#mysql50##sql2-5e17-12#P#p0 in mysql.innodb_table_stats: Operation interrupted. They can be renamed later using UPDATE mysql.innodb_table_stats SET database_name = 'test', table_name = '#mysql50##sql2-5e17-12#P#p0' WHERE database_name = 'test' AND table_name = 'PP_K#P#p0'; 2017-12-15 11:12:30 18 [ERROR] InnoDB: Unable to rename statistics from test.PP_K#P#p1 to test.#mysql50##sql2-5e17-12#P#p1 in mysql.innodb_table_stats: Operation interrupted. They can be renamed later using UPDATE mysql.innodb_table_stats SET database_name = 'test', table_name = '#mysql50##sql2-5e17-12#P#p1' WHERE database_name = 'test' AND table_name = 'PP_K#P#p1'; 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:31 19 [Warning] InnoDB: Quiesce aborted! 2017-12-15 11:12:34 17 [Warning] InnoDB: Unable to delete statistics for table test.#mysql50##sql-ib301-2999256496: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = '#mysql50##sql-ib301-2999256496'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = '#mysql50##sql-ib301-2999256496'; mysqld: /home/travis/src/storage/innobase/handler/handler0alter.cc:4305: 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. 171215 11:12:35 [ERROR] mysqld got signal 6 ; {noformat} {noformat} Some pointers may be invalid and cause the dump to abort. Query (0x7f0f5401dda8): ALTER TABLE `PP_F` DROP COLUMN IF EXISTS icol8, LOCK=SHARED, ADD COLUMN IF NOT EXISTS ( icol7 SMALLINT ZEROFILL NOT NULL ) /* QNO 1979 CON_ID 19 / Connection ID (thread ID): 19 Status: NOT_KILLED Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_grouping_derived=on {noformat} {noformat} #6 0x00007f0f9c8c2bf6 in __assert_fail_base (fmt=0x7f0f9ca17018 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x561363ab1b32 "page_is_root(block->frame)", file=file@entry=0x561363ab01f0 "/home/travis/src/storage/innobase/handler/handler0alter.cc", line=line@entry=4305, function=function@entry=0x561363ab61a0 <innobase_add_instant_try(Alter_inplace_info, ha_innobase_inplace_ctx, TABLE const, TABLE const, trx_t)::__PRETTY_FUNCTION__> "bool innobase_add_instant_try(Alter_inplace_info, ha_innobase_inplace_ctx, const TABLE, const TABLE, trx_t)") at assert.c:92 #7 0x00007f0f9c8c2ca2 in __GI___assert_fail (assertion=0x561363ab1b32 "page_is_root(block->frame)", file=0x561363ab01f0 "/home/travis/src/storage/innobase/handler/handler0alter.cc", line=4305, function=0x561363ab61a0 <innobase_add_instant_try(Alter_inplace_info, ha_innobase_inplace_ctx, TABLE const, TABLE const, trx_t)::__PRETTY_FUNCTION__> "bool innobase_add_instant_try(Alter_inplace_info, ha_innobase_inplace_ctx, const TABLE, const TABLE, trx_t)") at assert.c:101 #8 0x00005613632d301e in innobase_add_instant_try (ha_alter_info=0x7f0f845ec4c0, ctx=0x7f0f54023950, altered_table=0x7f0f5413c820, table=0x7f0f500de330, trx=0x7f0f87217e28) at /home/travis/src/storage/innobase/handler/handler0alter.cc:4305 #9 0x00005613632e6926 in commit_try_norebuild (ha_alter_info=0x7f0f845ec4c0, ctx=0x7f0f54023950, altered_table=0x7f0f5413c820, old_table=0x7f0f500de330, trx=0x7f0f87217e28, table_name=0x7f0f516bba35 "PP_F") at /home/travis/src/storage/innobase/handler/handler0alter.cc:8687 #10 0x00005613632e04cf in ha_innobase::commit_inplace_alter_table (this=0x7f0f51583a48, altered_table=0x7f0f5413c820, ha_alter_info=0x7f0f845ec4c0, commit=true) at /home/travis/src/storage/innobase/handler/handler0alter.cc:9268 #11 0x000056136307e23a in handler::ha_commit_inplace_alter_table (this=0x7f0f51583a48, altered_table=0x7f0f5413c820, ha_alter_info=0x7f0f845ec4c0, commit=true) at /home/travis/src/sql/handler.cc:4251 #12 0x0000561362e76859 in mysql_inplace_alter_table (thd=0x7f0f5400b1d0, table_list=0x7f0f5401df90, table=0x7f0f500de330, altered_table=0x7f0f5413c820, ha_alter_info=0x7f0f845ec4c0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f0f845ec530, alter_ctx=0x7f0f845ed0f0) at /home/travis/src/sql/sql_table.cc:7416 #13 0x0000561362e7bb8b in mysql_alter_table (thd=0x7f0f5400b1d0, new_db=0x7f0f5401e5a0 "test", new_name=0x0, create_info=0x7f0f845edd00, table_list=0x7f0f5401df90, alter_info=0x7f0f845edc50, order_num=0, order=0x0, ignore=false) at /home/travis/src/sql/sql_table.cc:9395 #14 0x0000561362efd1a3 in Sql_cmd_alter_table::execute (this=0x7f0f5401e6e8, thd=0x7f0f5400b1d0) at /home/travis/src/sql/sql_alter.cc:331 #15 0x0000561362dacb1d in mysql_execute_command (thd=0x7f0f5400b1d0) at /home/travis/src/sql/sql_parse.cc:6248 #16 0x0000561362db14f7 in mysql_parse (thd=0x7f0f5400b1d0, rawbuf=0x7f0f5401dda8 "ALTER TABLE `PP_F` DROP COLUMN IF EXISTS icol8, LOCK=SHARED, ADD COLUMN IF NOT EXISTS ( icol7 SMALLINT ZEROFILL NOT NULL ) / QNO 1979 CON_ID 19 /", length=148, parser_state=0x7f0f845ef620, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7963 #17 0x0000561362d9eec1 in dispatch_command (command=COM_QUERY, thd=0x7f0f5400b1d0, packet=0x7f0f540155e1 "ALTER TABLE `PP_F` DROP COLUMN IF EXISTS icol8, LOCK=SHARED, ADD COLUMN IF NOT EXISTS ( icol7 SMALLINT ZEROFILL NOT NULL ) / QNO 1979 CON_ID 19 */ ", packet_length=149, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1825 #18 0x0000561362d9d901 in do_command (thd=0x7f0f5400b1d0) at /home/travis/src/sql/sql_parse.cc:1370 #19 0x0000561362ef7d72 in do_handle_one_connection (connect=0x561366259bf0) at /home/travis/src/sql/sql_connect.cc:1420 #20 0x0000561362ef7aff in handle_one_connection (arg=0x561366259bf0) at /home/travis/src/sql/sql_connect.cc:1326 #21 0x00007f0f9d484184 in start_thread (arg=0x7f0f845f0700) at pthread_create.c:312 #22 0x00007f0f9c990ffd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 {noformat} {noformat:title=experimental 19162eb568134ce4ac39f96e9ef7a2a17d90c73a} perl /home/travis/rqg/runall-new.pl --grammar=conf/partitioning/partition_pruning.yy --gendata=conf/partitioning/partition_pruning.zz --duration=400 --threads=6 --queries=100M --redefine=/home/travis/rqg/conf/mariadb/instant_add.yy --mysqld=--max-statement-time=30 --reporters=Backtrace,ErrorLog,Deadlock --engine=InnoDB --seed=1513336047 --basedir=/home/travis/server --vardir=/home/travis/logs/vardir1_1 {noformat} Not easily reproducible	{noformat:title=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 {noformat} To reproduce: {noformat} git clone https://github.com/elenst/rqg --branch mdev14663 rqg-mdev14663 cd rqg-mdev14663 ./run <your basedir> {noformat} {{run}} is a one-line wrapper which runs RQG like this: {noformat} perl ./runall-new.pl --threads=2 --duration=600 --grammar=mdev14663.yy --skip-gendata --vardir1=/dev/shm/mdev14663 --basedir=$1 {noformat} 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 {{<basedir>/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 {noformat} perl ./gentest.pl --threads=2 --duration=600 --grammar=mdev14663.yy --dsn="dbi:mysql:user=root:host=127.0.0.1:port=3306:database=test" {noformat} (assuming that the server is running on port 3306). Again, it's faster and more reliable if the datadir is in shm.
Summary	[Draft] Assertion `page_is_root(block->frame)' failed in innobase_add_instant_try	Assertion `page_is_root(block->frame)' failed in innobase_add_instant_try

Elena Stepanova made changes - 2018-02-01 14:07

Assignee

Elena Stepanova [ elenst ]

Marko Mäkelä [ marko ]

Elena Stepanova made changes - 2018-02-01 14:09

Description

{noformat:title=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
{noformat}

To reproduce:
{noformat}
git clone https://github.com/elenst/rqg --branch mdev14663 rqg-mdev14663
cd rqg-mdev14663
./run <your basedir>
{noformat}

{{run}} is a one-line wrapper which runs RQG like this:
{noformat}
perl ./runall-new.pl --threads=2 --duration=600 --grammar=mdev14663.yy --skip-gendata --vardir1=/dev/shm/mdev14663 --basedir=$1
{noformat}
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 {{<basedir>/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
{noformat}
perl ./gentest.pl --threads=2 --duration=600 --grammar=mdev14663.yy --dsn="dbi:mysql:user=root:host=127.0.0.1:port=3306:database=test"
{noformat}
(assuming that the server is running on port 3306). Again, it's faster and more reliable if the datadir is in shm.

{noformat:title=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
{noformat}

To reproduce:
{noformat}
git clone https://github.com/elenst/rqg --branch mdev14663 rqg-mdev14663
cd rqg-mdev14663
./run <your basedir>
{noformat}

{{run}} is a one-line wrapper which runs RQG like this:
{noformat}
perl ./runall-new.pl --threads=2 --duration=600 --grammar=mdev14663.yy --skip-gendata --vardir1=/dev/shm/mdev14663 --basedir=$1
{noformat}
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
{noformat}
perl ./gentest.pl --threads=2 --duration=600 --grammar=mdev14663.yy --dsn="dbi:mysql:user=root:host=127.0.0.1:port=3306:database=test"
{noformat}
(assuming that the server is running on port 3306). Again, it's faster and more reliable if the datadir is in shm.

Marko Mäkelä made changes - 2018-02-08 18:50

Status

Open [ 1 ]

Confirmed [ 10101 ]

Marko Mäkelä made changes - 2018-02-08 19:01

Status

Confirmed [ 10101 ]

In Progress [ 3 ]

Marko Mäkelä added a comment - 2018-02-08 19:07

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

Marko Mäkelä added a comment - 2018-02-08 19:07 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

Marko Mäkelä made changes - 2018-02-08 19:07

Link

This issue is caused by ~~MDEV-11369~~ [ ~~MDEV-11369~~ ]

Marko Mäkelä added a comment - 2018-02-08 20:43

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.

Marko Mäkelä added a comment - 2018-02-08 20:43 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 .

Marko Mäkelä made changes - 2018-02-09 06:16

Fix Version/s		10.3.5 [ 22905 ]
Fix Version/s	10.3 [ 22126 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:46

Workflow

MariaDB v3 [ 84445 ]

MariaDB v4 [ 153360 ]

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2017-12-15 14:21

Updated:: 2018-02-09 06:16

Resolved:: 2018-02-09 06:16

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration