Failing assertion: level <= 50 in file btr0btr.ic line 143 | abort (sig=6) in btr_page_set_level from btr_page_empty

[Roel Van de Paar]

2014-09-16 07:04:52 7fb1c11d3700 InnoDB: Assertion failure in thread 140401425856256 in file btr0btr.ic line 143
InnoDB: Failing assertion: level <= 50
[...]
Query (7fb0c741f010): SELECT * FROM t2

There was only 1 thread of SQL running, but at the time of the crash I had a secondary connection (via mysql CLI) and had executed "show processlist;" - so issue may have been triggered by one thread executing 'SELECT * FROM t2' and the other 'show processlist'.

Also, the level <=50 issue seems clear as to what it means - the stack trace is humongous. Some sort of infinte loop?

(gdb) bt
#0 0x00007fb1c0c22771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab09a2 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/mysys/stacktrace.c:422
#2 0x000000000072ca03 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x00007fb1bf826989 in raise () from /lib64/libc.so.6
#5 0x00007fb1bf828098 in abort () from /lib64/libc.so.6
#6 0x0000000000c7ace1 in btr_page_set_level (page=0x7fb18f3f8000 "\274\060\206", <incomplete sequence \364>, page_zip=0x0, level=51, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/include/btr0btr.ic:143
#7 0x0000000000c7e94a in btr_page_empty (block=0x7fb17f3ffa70, page_zip=0x0, index=0x7fb0c744fff8, level=51, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2134
#8 0x0000000000c7ee94 in btr_root_raise_and_insert (flags=7, cursor=0x7fb1c11bef00, offsets=0x7fb1c11bef90, heap=0x7fb1c11bef88, tuple=0x7fb0c74b6378, n_ext=0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2272
#9 0x0000000000c92030 in btr_cur_pessimistic_insert (flags=7, cursor=0x7fb1c11bef00, offsets=0x7fb1c11bef90, heap=0x7fb1c11bef88, entry=0x7fb0c74b6378, rec=0x7fb1c11bef98, big_rec=0x7fb1c11befa0, n_ext=0, thr=0x0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0cur.cc:1728
#10 0x0000000000c7f953 in btr_insert_on_non_leaf_level_func (flags=7, index=0x7fb0c744fff8, level=50, tuple=0x7fb0c74b6378, file=0x1090a40 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc", line=2767, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2674
#11 0x0000000000c7fd14 in btr_attach_half_pages (flags=7, index=0x7fb0c744fff8, block=0x7fb15c3f3a88, split_rec=0x7fb0c75b6d1f "testt2", new_block=0x7fb15c3f37c0, direction=111, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2767
#12 0x0000000000c808bd in btr_page_split_and_insert (flags=7, cursor=0x7fb1c11bf400, offsets=0x7fb1c11bf490, heap=0x7fb1c11bf488, tuple=0x7fb0c74b5978, n_ext=0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:3007
#13 0x0000000000c7efc7 in btr_root_raise_and_insert (flags=7, cursor=0x7fb1c11bf400, offsets=0x7fb1c11bf490, heap=0x7fb1c11bf488, tuple=0x7fb0c74b5978, n_ext=0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2311
#14 0x0000000000c92030 in btr_cur_pessimistic_insert (flags=7, cursor=0x7fb1c11bf400, offsets=0x7fb1c11bf490, heap=0x7fb1c11bf488, entry=0x7fb0c74b5978, rec=0x7fb1c11bf498, big_rec=0x7fb1c11bf4a0, n_ext=0, thr=0x0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0cur.cc:1728
#15 0x0000000000c7f953 in btr_insert_on_non_leaf_level_func (flags=7, index=0x7fb0c744fff8, level=49, tuple=0x7fb0c74b5978, file=0x1090a40 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc", line=2767, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2674
#16 0x0000000000c7fd14 in btr_attach_half_pages (flags=7, index=0x7fb0c744fff8, block=0x7fb16dbf3a88, split_rec=0x7fb0c75b6c7f "testt2", new_block=0x7fb15c3f3d50, direction=111, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2767
#17 0x0000000000c808bd in btr_page_split_and_insert (flags=7, cursor=0x7fb1c11bf900, offsets=0x7fb1c11bf990, heap=0x7fb1c11bf988, tuple=0x7fb0c74b4f78, n_ext=0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:3007
#18 0x0000000000c7efc7 in btr_root_raise_and_insert (flags=7, cursor=0x7fb1c11bf900, offsets=0x7fb1c11bf990, heap=0x7fb1c11bf988, tuple=0x7fb0c74b4f78, n_ext=0, mtr=0x7fb1c11ce980) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/btr/btr0btr.cc:2
311
[...]
#271 0x0000000000d0d8c8 in dict_stats_save (table_orig=0x7fb0c7528778, only_for_index=0x0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/dict/dict0stats.cc:2424
#272 0x0000000000d0eebe in dict_stats_update (table=0x7fb0c7528778, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/dict/dict0stats.cc:3133
#273 0x0000000000d0f17f in dict_stats_update (table=0x7fb0c7528778, stats_upd_option=DICT_STATS_FETCH_ONLY_IF_NOT_IN_MEMORY) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/dict/dict0stats.cc:3248
#274 0x0000000000ac6765 in dict_stats_init (table=0x7fb0c7528778) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/include/dict0stats.ic:174
#275 0x0000000000accbd8 in ha_innobase::open (this=0x7fb0c74da010, name=0x7fb0c745db48 "./test/t2", mode=2, test_if_locked=2) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/handler/ha_innodb.cc:5508
#276 0x000000000063f1a9 in handler::ha_open (this=0x7fb0c74da010, table_arg=0x7fb0c7425200, name=0x7fb0c745db48 "./test/t2", mode=2, test_if_locked=2) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/handler.cc:2683
#277 0x00000000008a82a6 in open_table_from_share (thd=0x7fb101b12000, share=0x7fb0c745d810, alias=0x7fb0c741f1f8 "t2", db_stat=39, prgflag=44, ha_open_flags=0,outparam=0x7fb0c7425200, is_create_table=false) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/table.cc:2364
#278 0x000000000076e0dd in open_table (thd=0x7fb101b12000, table_list=0x7fb0c741f200, ot_ctx=0x7fb1c11d0a50) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_base.cc:3205
#279 0x0000000000770892 in open_and_process_table (thd=0x7fb101b12000, lex=0x7fb101b14540, tables=0x7fb0c741f200, counter=0x7fb101b14600, flags=0, prelocking_strategy=0x7fb1c11d0b50, has_prelocking_list=false, ot_ctx=0x7fb1c11d0a50) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_base.cc:4699
#280 0x0000000000771797 in open_tables (thd=0x7fb101b12000, start=0x7fb1c11d0b10, counter=0x7fb101b14600, flags=0, prelocking_strategy=0x7fb1c11d0b50) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_base.cc:5213
#281 0x0000000000772926 in open_normal_and_derived_tables (thd=0x7fb101b12000, tables=0x7fb0c741f200, flags=0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_base.cc:5913
#282 0x00000000007e75da in execute_sqlcom_select (thd=0x7fb101b12000, all_tables=0x7fb0c741f200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:5541
#283 0x00000000007dfd7a in mysql_execute_command (thd=0x7fb101b12000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:2953
#284 0x00000000007ea051 in mysql_parse (thd=0x7fb101b12000, rawbuf=0x7fb0c741f010 "SELECT * FROM t2", length=16, parser_state=0x7fb1c11d1df0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:6744
#285 0x00000000007dc5ec in dispatch_command (command=COM_QUERY, thd=0x7fb101b12000, packet=0x7fb101b16001 "SELECT * FROM t2;", packet_length=17) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1432
#286 0x00000000007db518 in do_command (thd=0x7fb101b12000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1049
#287 0x00000000007a34d5 in do_handle_one_connection (thd_arg=0x7fb111fc0000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1532
#288 0x00000000007a2fdd in handle_one_connection (arg=0x7fb111fc0000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1443
#289 0x0000000000dbdbb8 in pfs_spawn_thread (arg=0x7fb1a4bccb00) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/perfschema/pfs.cc:1860
#290 0x00007fb1c0c1ddf3 in start_thread () from /lib64/libpthread.so.0
#291 0x00007fb1bf8e73dd in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

Creating a testcase was not successful, likely due to (seemingly) two thread being needed to reproduce the issue.

[Roel Van de Paar (roel11)]

show processlist was not executing at time of crash according to core dump (query not present). Yet, it may have triggered it.

[Roel Van de Paar (roel11)]

This "very long stack trace" bug is also asserting itself in another way:

2014-09-19 01:05:33 7f8c80be0700 InnoDB: Assertion failure in thread 140241432086272 in file btr0btr.ic line 125
InnoDB: Failing assertion: level <= 50

i.e. btr0btr.ic line 143 instead of line 125.

Uploading details.

[Roel Van de Paar (roel11)]

This bug was also seen in a single-threaded single-mysqld run.

[Roel Van de Paar (roel11)]

DROP DATABASE test;CREATE DATABASE test;USE test;
set global innodb_limit_optimistic_insert_debug=1;
CREATE TABLE t1(c1 CHAR (1),c2 VARCHAR(1),c3 INT);

[Roel Van de Paar (roel11)]

Upstream

[Roel Van de Paar (roel11)]

Logged as http://bugs.mysql.com/bug.php?id=74577

[Laurynas Biveinis (laurynas-biveinis)]

Not a bug (hard to maintain a B-tree if each node is limited to a single entry)

[Laurynas Biveinis (laurynas-biveinis)]

Or might be a bug in the allowed value range for innodb_limit_optimistic_insert_debug if we are splitting hairs, but that's upstream concern, definitely nothing to fix for us.

[Ramesh Sivaraman (rameshvs02)]

** Testcase (for crash - btr0btr.ic line 125)

DROP DATABASE test;CREATE DATABASE test;USE test;
set global innodb_file_format=Barracuda;
create TABLE t1(a int key)engine=innodb row_format=compressed;
set global innodb_limit_optimistic_insert_debug=1;
INSERT INTO t1 VALUES(0xC8),(0xC9),(0xCA),(0xCB),(0xCC),(0xCD),(0xCE),(0xCF);

[Ramesh Sivaraman (rameshvs02)]

Please note the last testcase (comment #12) crashes in a different location as the original one.

[Roel Van de Paar (roel11)]

One more testcase which is solved on 5.6.22 but still crashes Percona (pre-5.6.22 merge) for the time being. Good verify testcase.

DROP DATABASE test;CREATE DATABASE test;USE test;
set global innodb_limit_optimistic_insert_debug=1;
CREATE TABLE t1(c1 INT,c2 CHAR,c3 INT,c4 CHAR KEY,c5 INT UNIQUE KEY,c6 DECIMAL(0,0)DEFAULT 3.141592);

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2083