MySQL Bugs: #75784: InnoDB: Failing assertion: level <= 50 in file btr0btr.ic line 126

Bug #75784	InnoDB: Failing assertion: level <= 50 in file btr0btr.ic line 126
Submitted:	5 Feb 2015 3:45	Modified:	5 Feb 2015 21:20
Reporter:	Roel Van de Paar	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server	Severity:	S6 (Debug Builds)
Version:	5.7.5-m15	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Version: '5.7.5-m15-debug'  socket: '/sda/MS-mysql-5.7.5-m15-linux-x86_64-debug/socket.sock'  port: 16633  MySQL Community Server (GPL)
2015-02-05 14:40:37 0x7f04b4708700  InnoDB: Assertion failure in thread 139658183870208 in file btr0btr.ic line 126
InnoDB: Failing assertion: level <= 50

(gdb) bt
#0  0x00007f04b421f771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e15cd8 in my_write_core (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/mysys/stacktrace.c:247
#2  0x0000000000822044 in handle_fatal_signal (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x00007f04b2e235c9 in raise () from /lib64/libc.so.6
#5  0x00007f04b2e24cd8 in abort () from /lib64/libc.so.6
#6  0x00000000010d4a9b in ut_dbg_assertion_failed (expr=0x14f3f2f "level <= 50", file=0x14f3ee8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/include/btr0btr.ic", line=126) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ut/ut0dbg.cc:68
#7  0x00000000010fcce5 in btr_page_get_level_low (page=0x7f0444cb8000 "") at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/include/btr0btr.ic:126
#8  0x0000000001100c9b in btr_cur_search_to_nth_level (index=0x7f03f707f098, level=51, tuple=0x7f03f71fa098, mode=4, latch_mode=34, cursor=0x7f04b46d1310, has_search_latch=0, file=0x14ef688 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc", line=2225, mtr=0x7f04b47040f0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc:1249
#9  0x00000000010ece37 in btr_insert_on_non_leaf_level_func (flags=7, index=0x7f03f707f098, level=51, tuple=0x7f03f71fa098, file=0x14ef688 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc", line=2225, mtr=0x7f04b47040f0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2072
#10 0x00000000010ed5a5 in btr_attach_half_pages (flags=7, index=0x7f03f707f098, block=0x7f041fe116f8, split_rec=0x7f03f7209818 'c' <repeats 948 times>, new_block=0x7f041fe11a40, direction=111, mtr=0x7f04b47040f0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2225
[...many similar frames...]
#266 0x0000000001071997 in row_upd_clust_rec_by_insert (flags=0, node=0x7f03f713f568, index=0x7f03f707f098, thr=0x7f03f713f850, referenced=0, mtr=0x7f04b4704ac0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0upd.cc:2084
#267 0x0000000001072770 in row_upd_clust_step (node=0x7f03f713f568, thr=0x7f03f713f850) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0upd.cc:2460
#268 0x0000000001072ac8 in row_upd (node=0x7f03f713f568, thr=0x7f03f713f850) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0upd.cc:2534
#269 0x0000000001072fae in row_upd_step (thr=0x7f03f713f850) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0upd.cc:2681
#270 0x000000000101f3b8 in row_update_for_mysql_using_upd_graph (mysql_rec=0x7f03f709af68 "\376\240\017", 'a' <repeats 1497 times>..., prebuilt=0x7f03f708c098) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0mysql.cc:2357
#271 0x000000000101fb7b in row_update_for_mysql (mysql_rec=0x7f03f709af68 "\376\240\017", 'a' <repeats 1497 times>..., prebuilt=0x7f03f708c098) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0mysql.cc:2534
#272 0x0000000000f123c9 in ha_innobase::update_row (this=0x7f03f707e020, old_row=0x7f03f709af68 "\376\240\017", 'a' <repeats 1497 times>..., new_row=0x7f03f7099020 "\376\240\017", 'c' <repeats 1497 times>...) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc:7251
#273 0x000000000088ce43 in handler::ha_update_row (this=0x7f03f707e020, old_data=0x7f03f709af68 "\376\240\017", 'a' <repeats 1497 times>..., new_data=0x7f03f7099020 "\376\240\017", 'c' <repeats 1497 times>...) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/handler.cc:7455
#274 0x0000000000be4808 in mysql_update (thd=0x7f03f701c000, fields=..., values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, found_return=0x7f04b47069a8, updated_return=0x7f04b47069a0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_update.cc:874
#275 0x0000000000b49502 in mysql_execute_command (thd=0x7f03f701c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:3194
#276 0x0000000000b4fcc1 in mysql_parse (thd=0x7f03f701c000, parser_state=0x7f04b4706e60) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:5427
#277 0x0000000000b44814 in dispatch_command (command=COM_QUERY, thd=0x7f03f701c000, packet=0x7f03f7033011 "UPDATE t1 SET c_1vc=REPEAT(\"c\",4000)", packet_length=36) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:1250
#278 0x0000000000b4354d in do_command (thd=0x7f03f701c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:834
#279 0x0000000000c4d4ce in handle_connection (arg=0x7f0495fffee0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#280 0x0000000000e394b8 in pfs_spawn_thread (arg=0x7f04967f8a50) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/perfschema/pfs.cc:2137
#281 0x00007f04b421adf3 in start_thread () from /lib64/libpthread.so.0
#282 0x00007f04b2ee41ad in clone () from /lib64/libc.so.6

How to repeat:
DROP DATABASE test;CREATE DATABASE test;USE test;
SET GLOBAL innodb_file_format=Barracuda;
set global innodb_large_prefix=-3;
CREATE TABLE t1(c_1vc VARCHAR (4000),c_2vc VARCHAR (4000),PRIMARY KEY (c_1vc(948))) ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=2,engine=innodb;
INSERT INTO t1 VALUES(REPEAT("a",4000),REPEAT("o",4000));
SET GLOBAL innodb_limit_optimistic_insert_debug=1;
UPDATE t1 SET c_1vc=REPEAT("c",4000);

Though the testcase above should suffice for reproducing the bug, the attached tarball gives the testcase as an exact match of our system, including some handy utilities

$ vi {epoch}_mybase     # Update base path in this file (the only change required!)
$ ./{epoch}_init        # Initializes the data dir
$ ./{epoch}_start       # Starts mysqld
$ ./{epoch}_cl          # To check mysqld is up
$ ./{epoch}_run         # Run the testcase (produces output)
$ vi /dev/shm/{epoch}/error.log.out  # Verify the error log
$ ./{epoch}_gdb         # Brings you to a gdb prompt attached to correct mysqld & generated core
$ ./{epoch}_parse_core  # Create {epoch}_STD.gdb and {epoch}_FULL.gdb; standard and full var gdb stack traces
etc.

Scripts, if needed

Attachment: 1423018579_bug_bundle.tar.gz (application/gzip, text), 149.30 KiB.

See bug 74605
See bug 74577

Hmm, maybe this bug was fixed in 5.7.6 ?

Not repeatable with 10 days older source.

C:\dbs>c:\dbs\5.7\bin\mysql -uroot --port=3570 --prompt="mysql 5.7 > "
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.7.6-m16-debug Source distribution

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql 5.7 > DROP DATABASE test;CREATE DATABASE test;USE test;
Query OK, 4 rows affected (1.56 sec)

Query OK, 1 row affected (0.00 sec)

Database changed
mysql 5.7 > SET GLOBAL innodb_file_format=Barracuda;
Query OK, 0 rows affected (0.00 sec)

mysql 5.7 > set global innodb_large_prefix=-3;
Query OK, 0 rows affected (0.00 sec)

mysql 5.7 > CREATE TABLE t1(c_1vc VARCHAR (4000),c_2vc VARCHAR (4000),PRIMARY KEY (c_1vc(948))) ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=2,engine=innodb;
Query OK, 0 rows affected (0.30 sec)

mysql 5.7 > INSERT INTO t1 VALUES(REPEAT("a",4000),REPEAT("o",4000));
Query OK, 1 row affected (0.14 sec)

mysql 5.7 > SET GLOBAL innodb_limit_optimistic_insert_debug=1;
Query OK, 0 rows affected (0.00 sec)

mysql 5.7 > UPDATE t1 SET c_1vc=REPEAT("c",4000);
Query OK, 1 row affected (0.03 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql 5.7 >

Thank you for the bug report. Not repeatable with recent debug build:

mysql 5.7 > UPDATE t1 SET c_1vc=REPEAT("c",4000);
Query OK, 1 row affected (0.03 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql 5.7 > show variables like "%version%";
+-------------------------+---------------------+
| Variable_name           | Value               |
+-------------------------+---------------------+
| innodb_version          | 5.7.6               |
| protocol_version        | 10                  |
| slave_type_conversions  |                     |
| version                 | 5.7.6-m16-debug     |
| version_comment         | Source distribution |
| version_compile_machine | x86_64              |
| version_compile_os      | Win64               |
+-------------------------+---------------------+
7 rows in set (0.00 sec)

Thanks Miguel, looks like 5.7.6 is all good in this area then.