[MDEV-22653] Assertion `level <= 50' failed in btr_cur_latch_leaves Created: 2020-05-21  Updated: 2023-11-29  Resolved: 2021-03-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.38, 10.3.29, 10.4.19, 10.5.10, 10.6.0

Type: Bug Priority: Minor
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: not-10.1

Attachments: File MDEV-22653.sql    
Issue Links:
Relates
relates to MDEV-20526 innodb.innodb_simulate_comp_failures_... Closed
relates to MDEV-23165 Assertion `level <= 50' failed in btr... Confirmed

 Description   

Briefly discussed with Marko online. Agreed to log this as a bug for the time being, though it is not clear if it is a bug or not. Marko mentioned that this could be a case of MDEV-13542. Feel free to close if it's a dud.

USE test;
 
SET GLOBAL innodb_simulate_comp_failures=99;  # (!)
 
CREATE TABLE t(c INT);
 
INSERT INTO t VALUES (1),(1),(1);
 
ALTER TABLE t KEY_BLOCK_SIZE=2;

Leads to:

10.5.3 cfe5ee90c8e4b9dfa98a41fcd299197a59261be7

 
mysqld: /test/10.5_dbg/storage/innobase/include/btr0btr.ic:51: void btr_page_set_level(buf_block_t*, ulint, mtr_t*): Assertion `level <= 50' failed.

Also seen:

2020-05-21 16:19:55 0 [Note] /test/MD110520-mariadb-10.5.3-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.5.3-MariaDB-debug'  socket: '/test/MD110520-mariadb-10.5.3-linux-x86_64-dbg/socket.sock'  port: 11832  MariaDB Server
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 4(leaf)
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 5(leaf)
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 6(non-leaf)
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 8(non-leaf)
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 3(non-leaf)
 
2020-05-21 16:19:59 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-381de-4` index GEN_CLUST_INDEX page 9(non-leaf)
 
2020-05-21 16:19:59 0x14deefa53700  InnoDB: Assertion failure in file /test/10.5_dbg/storage/innobase/btr/btr0cur.cc line 382
 
InnoDB: We intentionally generate a memory trap.

10.5.3 cfe5ee90c8e4b9dfa98a41fcd299197a59261be7

 
Core was generated by `/test/MD110520-mariadb-10.5.3-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x14b2ba881700 (LWP 1864040))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x0000563a2d886c11 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x0000563a2d02bf8d in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:329
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x000014b2b8fc5801 in __GI_abort () at abort.c:79
 
#6  0x0000563a2d642aae in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x563a2dd0cd50 "/test/10.5_dbg/storage/innobase/btr/btr0cur.cc", line=line@entry=382) at /test/10.5_dbg/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x0000563a2d6735fe in btr_cur_latch_leaves (block=block@entry=0x14b29e22b190, latch_mode=38, cursor=cursor@entry=0x14b2ba879c10, mtr=mtr@entry=0x14b2ba87a380) at /test/10.5_dbg/storage/innobase/btr/btr0cur.cc:382
 
#8  0x0000563a2d68678f in btr_cur_search_to_nth_level_func (index=index@entry=0x14b2978a5098, level=level@entry=7, tuple=0x14b29781ced8, mode=mode@entry=PAGE_CUR_LE, latch_mode=<optimized out>, latch_mode@entry=38, cursor=cursor@entry=0x14b2ba879c10, ahi_latch=0x0, file=0x563a2dd02708 "/test/10.5_dbg/storage/innobase/btr/btr0btr.cc", line=4897, mtr=0x14b2ba87a380, autoinc=0) at /test/10.5_dbg/storage/innobase/btr/btr0cur.cc:1847
 
#9  0x0000563a2d64b806 in btr_page_get_father_node_ptr_func (offsets=offsets@entry=0x14b29781ce98, heap=<optimized out>, cursor=cursor@entry=0x14b2ba879c10, latch_mode=latch_mode@entry=38, file=file@entry=0x563a2dd02708 "/test/10.5_dbg/storage/innobase/btr/btr0btr.cc", line=line@entry=4897, mtr=0x14b2ba87a380) at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:855
 
#10 0x0000563a2d650942 in btr_validate_level (lockout=<optimized out>, level=6, trx=0x0, index=0x14b2978a5098) at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:4896
 
#11 btr_validate_index (index=0x14b2978a5098, trx=trx@entry=0x0) at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:5133
 
#12 0x0000563a2d666fe1 in BtrBulk::finish (this=this@entry=0x14b2978803e8, err=DB_SUCCESS) at /test/10.5_dbg/storage/innobase/btr/btr0bulk.cc:1205
 
#13 0x0000563a2d55a496 in row_merge_read_clustered_index (allow_not_null=<optimized out>, eval_table=<optimized out>, crypt_block=<optimized out>, pct_cost=<optimized out>, stage=<optimized out>, tmpfd=0x14b2ba87b550, skip_pk_sort=<optimized out>, block=<optimized out>, sequence=..., add_autoinc=<optimized out>, col_map=<optimized out>, add_v=<optimized out>, defaults=<optimized out>, n_index=<optimized out>, key_numbers=<optimized out>, files=<optimized out>, psort_info=<optimized out>, fts_sort_idx=<optimized out>, index=0x14b297857270, online=<optimized out>, new_table=<optimized out>, old_table=0x14b297852598, table=<optimized out>, trx=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0merge.cc:2513
 
#14 row_merge_build_indexes (trx=<optimized out>, old_table=0x14b297852598, new_table=<optimized out>, online=<optimized out>, indexes=0x14b297857270, key_numbers=<optimized out>, n_indexes=<optimized out>, table=<optimized out>, defaults=<optimized out>, col_map=<optimized out>, add_autoinc=<optimized out>, sequence=..., skip_pk_sort=<optimized out>, stage=<optimized out>, add_v=<optimized out>, eval_table=<optimized out>, allow_not_null=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0merge.cc:4529
 
#15 0x0000563a2d42293e in ha_innobase::inplace_alter_table (this=0x14b297836ca0, altered_table=0x14b2ba87ca70, ha_alter_info=0x14b2ba87c9d0) at /test/10.5_dbg/storage/innobase/handler/handler0alter.cc:8384
 
#16 0x0000563a2ce4c984 in handler::ha_inplace_alter_table (ha_alter_info=0x14b2ba87c9d0, altered_table=0x14b2ba87ca70, this=<optimized out>) at /test/10.5_dbg/sql/handler.h:4513
 
#17 mysql_inplace_alter_table (thd=thd@entry=0x14b297815088, table_list=0x14b297874188, table=table@entry=0x14b2978f0088, altered_table=altered_table@entry=0x14b2ba87ca70, ha_alter_info=ha_alter_info@entry=0x14b2ba87c9d0, inplace_supported=inplace_supported@entry=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x14b2ba87d830, alter_ctx=0x14b2ba87e6c0) at /test/10.5_dbg/sql/sql_table.cc:7869
 
#18 0x0000563a2ce58f17 in mysql_alter_table (thd=thd@entry=0x14b297815088, new_db=new_db@entry=0x14b297819940, new_name=new_name@entry=0x14b297819d48, create_info=create_info@entry=0x14b2ba87f2b0, table_list=<optimized out>, table_list@entry=0x14b297874188, alter_info=alter_info@entry=0x14b2ba87f1e0, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10442
 
#19 0x0000563a2cedc7d0 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x14b297815088) at /test/10.5_dbg/sql/sql_alter.cc:532
 
#20 0x0000563a2cd87eda in mysql_execute_command (thd=thd@entry=0x14b297815088) at /test/10.5_dbg/sql/sql_parse.cc:5912
 
#21 0x0000563a2cd8f804 in mysql_parse (thd=thd@entry=0x14b297815088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b2ba8803e0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7957
 
#22 0x0000563a2cd7bffd in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b297815088, packet=packet@entry=0x14b297867089 "ALTER TABLE t KEY_BLOCK_SIZE=2", packet_length=packet_length@entry=30, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1839
 
#23 0x0000563a2cd7a8cc in do_command (thd=0x14b297815088) at /test/10.5_dbg/sql/sql_parse.cc:1358
 
#24 0x0000563a2ced499d in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14b2990433a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#25 0x0000563a2ced50b9 in handle_one_connection (arg=arg@entry=0x14b2990433a8) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#26 0x0000563a2d33310a in pfs_spawn_thread (arg=0x14b2b8445888) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#27 0x000014b2b9ca86db in start_thread (arg=0x14b2ba881700) at pthread_create.c:463
 
#28 0x000014b2b90a688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Presumed bug confirmed present in:
MariaDB: 10.2.32 (dbg), 10.3.23 (dbg), 10.4.13 (dbg), 10.5.2 (dbg), 10.5.3 (dbg)

Presumed bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (opt), 10.2.32 (opt), 10.3.23 (opt), 10.4.13 (opt), 10.5.2 (opt), 10.5.3 (opt), 10.5.4 (dbg), 10.5.4 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Roel Van de Paar [ 2020-06-10 ]

Secondary testcase with a different assertion, if SOURCE'd. If one instead copy/pastes the SQL from the testcase into the command line, the same assertion as above (Assertion `level <= 50' failed) happens instead.

SOURCE MDEV-22653.sql;

Leads to:

10.5.4 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89

 
... more messages ...
 
2020-06-10 21:07:54 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-11edf5-4` index GEN_CLUST_INDEX page 24(non-leaf)
 
2020-06-10 21:07:54 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-11edf5-4` index GEN_CLUST_INDEX page 26(non-leaf)
 
2020-06-10 21:07:54 4 [ERROR] InnoDB: Simulating a compression failure for table `test`.`#sql-alter-11edf5-4` index GEN_CLUST_INDEX page 3(non-leaf)
 
2020-06-10 21:07:54 0x14c35b0c1700  InnoDB: Assertion failure in file /test/10.5_dbg/storage/innobase/btr/btr0cur.cc line 382
 
InnoDB: We intentionally generate a memory trap.

10.5.4 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89

 
Core was generated by `/test/MD060620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x14c35b0c1700 (LWP 1175222))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000056531021700d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x000056530f9c0bbc in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x000014c363a18801 in __GI_abort () at abort.c:79
 
#6  0x000056530ffd751e in ut_dbg_assertion_failed (expr=expr@entry=0x0, 
    file=file@entry=0x5653106a4558 "/test/10.5_dbg/storage/innobase/btr/btr0cur.cc", line=line@entry=382)
 
    at /test/10.5_dbg/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x0000565310006a7a in btr_cur_latch_leaves (block=block@entry=0x14c34841d778, latch_mode=38, 
    cursor=cursor@entry=0x14c35b0b9b50, mtr=mtr@entry=0x14c35b0ba2c0)
 
    at /test/10.5_dbg/storage/innobase/btr/btr0cur.cc:382
 
#8  0x000056531001a948 in btr_cur_search_to_nth_level_func (index=index@entry=0x14c343110a18, 
    level=level@entry=13, tuple=<optimized out>, mode=mode@entry=PAGE_CUR_LE, latch_mode=<optimized out>, 
    latch_mode@entry=38, cursor=cursor@entry=0x14c35b0b9b50, ahi_latch=<optimized out>, 
    file=<optimized out>, line=<optimized out>, mtr=<optimized out>, autoinc=<optimized out>)
 
    at /test/10.5_dbg/storage/innobase/btr/btr0cur.cc:1837
 
#9  0x000056530ffe183a in btr_page_get_father_node_ptr_func (offsets=offsets@entry=0x0, 
    heap=<optimized out>, cursor=cursor@entry=0x14c35b0b9b50, latch_mode=latch_mode@entry=38, 
    file=<optimized out>, file@entry=0x56531069a068 "/test/10.5_dbg/storage/innobase/btr/btr0btr.cc", 
    line=<optimized out>, line@entry=4878, mtr=0x14c35b0ba2c0)
 
    at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:858
 
#10 0x000056530ffe946d in btr_validate_level (lockout=<optimized out>, level=12, trx=0x0, 
    index=0x14c343110a18) at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:4877
 
#11 btr_validate_index (index=0x14c343110a18, trx=trx@entry=0x0)
 
    at /test/10.5_dbg/storage/innobase/btr/btr0btr.cc:5114
 
#12 0x000056530fffae5a in BtrBulk::finish (this=this@entry=0x14c343080348, err=DB_SUCCESS)
 
    at /test/10.5_dbg/storage/innobase/btr/btr0bulk.cc:1205
 
#13 0x000056530feeeeb3 in row_merge_read_clustered_index (allow_not_null=<optimized out>, 
    eval_table=<optimized out>, crypt_block=<optimized out>, pct_cost=<optimized out>, 
    stage=<optimized out>, tmpfd=0x14c35b0bb490, skip_pk_sort=<optimized out>, block=<optimized out>, 
    sequence=..., add_autoinc=<optimized out>, col_map=<optimized out>, add_v=<optimized out>, 
    defaults=<optimized out>, n_index=<optimized out>, key_numbers=<optimized out>, files=<optimized out>, 
    psort_info=<optimized out>, fts_sort_idx=<optimized out>, index=0x14c343058b70, online=<optimized out>, 
    new_table=<optimized out>, old_table=0x14c343053e98, table=<optimized out>, trx=<optimized out>)
 
    at /test/10.5_dbg/storage/innobase/row/row0merge.cc:2514
 
#14 row_merge_build_indexes (trx=<optimized out>, old_table=0x14c343053e98, new_table=<optimized out>, 
    online=<optimized out>, indexes=0x14c343058b70, key_numbers=<optimized out>, n_indexes=<optimized out>, 
    table=<optimized out>, defaults=<optimized out>, col_map=<optimized out>, add_autoinc=<optimized out>, 
    sequence=..., skip_pk_sort=<optimized out>, stage=<optimized out>, add_v=<optimized out>, 
    eval_table=<optimized out>, allow_not_null=<optimized out>)
 
    at /test/10.5_dbg/storage/innobase/row/row0merge.cc:4533
 
#15 0x000056530fdb96e8 in ha_innobase::inplace_alter_table (this=0x14c3430434a0, 
    altered_table=0x14c35b0bc9c0, ha_alter_info=0x14c35b0bc920)
 
    at /test/10.5_dbg/storage/innobase/handler/handler0alter.cc:8384
 
#16 0x000056530f7e154f in handler::ha_inplace_alter_table (ha_alter_info=0x14c35b0bc920, 
    altered_table=0x14c35b0bc9c0, this=<optimized out>) at /test/10.5_dbg/sql/handler.h:4546
 
#17 mysql_inplace_alter_table (thd=thd@entry=0x14c343015088, table_list=0x14c343074188, 
    table=table@entry=0x14c3430f7088, altered_table=altered_table@entry=0x14c35b0bc9c0, 
    ha_alter_info=ha_alter_info@entry=0x14c35b0bc920, 
    inplace_supported=inplace_supported@entry=HA_ALTER_INPLACE_COPY_NO_LOCK, 
    target_mdl_request=0x14c35b0bd790, alter_ctx=0x14c35b0be630) at /test/10.5_dbg/sql/sql_table.cc:7894
 
#18 0x000056530f7edbd1 in mysql_alter_table (thd=thd@entry=0x14c343015088, 
    new_db=new_db@entry=0x14c343019950, new_name=new_name@entry=0x14c343019d58, 
    create_info=create_info@entry=0x14c35b0bf220, table_list=<optimized out>, 
    table_list@entry=0x14c343074188, alter_info=alter_info@entry=0x14c35b0bf150, order_num=0, order=0x0, 
    ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10466
 
#19 0x000056530f87182c in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x14c343015088)
 
    at /test/10.5_dbg/sql/sql_alter.cc:532
 
#20 0x000056530f71ba13 in mysql_execute_command (thd=thd@entry=0x14c343015088)
 
    at /test/10.5_dbg/sql/sql_parse.cc:5950
 
#21 0x000056530f723322 in mysql_parse (thd=thd@entry=0x14c343015088, rawbuf=<optimized out>, 
    length=<optimized out>, parser_state=parser_state@entry=0x14c35b0c0350, 
    is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false)
 
    at /test/10.5_dbg/sql/sql_parse.cc:7992
 
#22 0x000056530f70fe1c in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14c343015088, 
    packet=packet@entry=0x14c343067089 "ALTER TABLE t1 KEY_BLOCK_SIZE=2", 
    packet_length=packet_length@entry=31, is_com_multi=is_com_multi@entry=false, 
    is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
 
#23 0x000056530f70e5f6 in do_command (thd=0x14c343015088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#24 0x000056530f8699f9 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14c345115808, 
    put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#25 0x000056530f86a115 in handle_one_connection (arg=arg@entry=0x14c345115808)
 
    at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#26 0x000056530fcc9104 in pfs_spawn_thread (arg=0x14c362445888)
 
    at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#27 0x000014c3646fb6db in start_thread (arg=0x14c35b0c1700) at pthread_create.c:463
 
#28 0x000014c363af988f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Marko Mäkelä [ 2020-06-10 ]

I do not see any point in having the parameter innodb_simulate_comp_failures at all. It seems to inject compression failures for ROW_FORMAT=COMPRESSED tables, breaking the pre-existing logic that I implemented in the InnoDB Plugin for MySQL 5.1 to prevent compressed page overflows. A much better check is already achieved by defining UNIV_ZIP_COPY at the compilation time. (Only UNIV_ZIP_DEBUG is part of cmake -DWITH_INNODB_EXTRA_DEBUG=ON.)

jplindst, you added the debug parameter. Do you have any objection if we remove it?

Comment by Marko Mäkelä [ 2020-06-10 ]

Also, a better test of ROW_FORMAT=COMPRESSED compression failure handling is to run with innodb_compression_level=0 (no compression at all).

Comment by Roel Van de Paar [ 2020-08-22 ]

jplindst Please see question above from Marko

Comment by Marko Mäkelä [ 2021-03-22 ]

I do not remember any bugs that would be specific to ROW_FORMAT=COMPRESSED, except one potential recovery bug that vlad.lesin noticed while working on MDEV-24719. And even that one does not depend on this parameter.

So, I would remove this parameter.

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