MySQL Bugs: #91033: InnoDB: ibuf cursor restoration fails!

Bug #91033	InnoDB: ibuf cursor restoration fails!
Submitted:	26 May 2018 11:11	Modified:	12 May 2020 16:33
Reporter:	Kevin Cai	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.7.17	OS:	Other (Amazon Linux AMI release 2016.09)
Assigned to:		CPU Architecture:	x86

Description:
Mysqld will get crashed/restarted unexpectedly and intermittently for no obvious reason. This has happened 6 times within two weeks. This is a new mysql setup.

Full crash:

2018-05-24T02:32:01.712735-00:00 38694 [ERROR] InnoDB: ibuf cursor restoration fails!. ibuf record inserted to page 157:1859
2018-05-24T02:32:01.712774-00:00 38694 [ERROR] InnoDB: Submit a detailed bug report to http://bugs.mysql.com
PHYSICAL RECORD: n_fields 1; 1-byte offsets; info bits 0
0: len 8; hex 696e66696d756d00; asc infimum ;;
PHYSICAL RECORD: n_fields 7; 1-byte offsets; info bits 32
0: len 4; hex 0000009d; asc ;;
1: len 1; hex 00; asc ;;
2: len 4; hex 00000743; asc C;;
3: len 22; hex 00e801010c0f003080530c0f000c80530c0f000c8053; asc 0 S S S;;
4: len 10; hex 30353334383639333739; asc 0534869379;;
5: len 4; hex 33303130; asc 3010;;
6: len 4; hex 30333635; asc 0365;;
DATA TUPLE: 3 fields;
0: len 4; hex 0000009d; asc ;;
1: len 1; hex 00; asc ;;
2: len 4; hex 00000000; asc ;;
PHYSICAL RECORD: n_fields 7; 1-byte offsets; info bits 32
0: len 4; hex 0000009d; asc ;;
1: len 1; hex 00; asc ;;
2: len 4; hex 00000743; asc C;;
3: len 22; hex 00e801010c0f003080530c0f000c80530c0f000c8053; asc 0 S S S;;
4: len 10; hex 30353334383639333739; asc 0534869379;;
5: len 4; hex 33303130; asc 3010;;
6: len 4; hex 30333635; asc 0365;;
2018-05-24T02:32:01.713203-00:00 38694 [ERROR] [FATAL] InnoDB: Failed to restore ibuf position.
2018-05-24 02:32:01 0x2ac416b91700 InnoDB: Assertion failure in thread 47021683185408 in file ut0ut.cc line 916
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
02:32:01 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=16777216
read_buffer_size=262144
max_used_connections=1020
max_threads=5351
thread_count=279
connection_count=278
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2827498 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2ac7555e3000
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 2ac416b90e40 thread_stack 0x40000
/rdsdbbin/mysql/bin/mysqld(my_print_stacktrace+0x2c)[0xebd1cc]
/rdsdbbin/mysql/bin/mysqld(handle_fatal_signal+0x451)[0x7afc61]
/lib64/libpthread.so.0(+0xf100)[0x2ab966870100]
/lib64/libc.so.6(gsignal+0x37)[0x2ab967d1c5f7]
/lib64/libc.so.6(abort+0x148)[0x2ab967d1dce8]
/rdsdbbin/mysql/bin/mysqld[0x780d70]
/rdsdbbin/mysql/bin/mysqld(_ZN2ib5fatalD1Ev+0xee)[0x107840e]
/rdsdbbin/mysql/bin/mysqld[0xf223e0]
/rdsdbbin/mysql/bin/mysqld[0xf243e1]
/rdsdbbin/mysql/bin/mysqld(_Z31ibuf_delete_for_discarded_spacem+0x2e5)[0xf25d25]
/rdsdbbin/mysql/bin/mysqld(_Z23fil_reinit_space_headermm+0x4b)[0x113721b]
/rdsdbbin/mysql/bin/mysqld(_Z28row_truncate_table_for_mysqlP12dict_table_tP5trx_t+0xa47)[0xff70b7]
/rdsdbbin/mysql/bin/mysqld(_ZN11ha_innobase8truncateEv+0xad)[0xeef8dd]
/rdsdbbin/mysql/bin/mysqld(_ZN22Sql_cmd_truncate_table16handler_truncateEP3THDP10TABLE_LISTb+0x478)[0xe1cfb8]
/rdsdbbin/mysql/bin/mysqld(_ZN22Sql_cmd_truncate_table14truncate_tableEP3THDP10TABLE_LIST+0x220)[0xe1d430]
/rdsdbbin/mysql/bin/mysqld(_ZN22Sql_cmd_truncate_table7executeEP3THD+0x5e)[0xe1d5ae]
/rdsdbbin/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x5b0)[0xc987e0]
/rdsdbbin/mysql/bin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x35d)[0xcc7acd]
/rdsdbbin/mysql/bin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0xca)[0xcc7eca]
/rdsdbbin/mysql/bin/mysqld(_Z19mysqld_stmt_executeP3THDmmPhm+0xe4)[0xcc81a4]
/rdsdbbin/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x194d)[0xca086d]
/rdsdbbin/mysql/bin/mysqld(_Z10do_commandP3THD+0x177)[0xca12a7]
/rdsdbbin/mysql/bin/mysqld(handle_connection+0x270)[0xd5b590]
/rdsdbbin/mysql/bin/mysqld(pfs_spawn_thread+0x18f)[0x11c7aff]
/lib64/libpthread.so.0(+0x7dc5)[0x2ab966868dc5]
/lib64/libc.so.6(clone+0x6d)[0x2ab967dddc9d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (2ac8b7532a50): TRUNCATE TABLE tblFoPremium
Connection ID (thread ID): 38694
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
This seems to happen in a random manner and no trigger has been identified yet.

Thank you for the bug report. To check this bug we need a repeatable test case and using a MySQL binary that you have not provided, please file a bug or contact the Administrator of the system you are using. Thanks.

This is a Amazon Linux AMI release 2016.09. Kernel version: Kernel 4.4.23-31.54.amzn1.x86_64 on an x86_64.

Currently we have difficulty finding out how to reproduce the issue. It just hit intermittently and seems not to have obvious patterns. Could you let us know what information you need to further investigate the issue?

Thanks.

We don't support AWS binaries, please ask support for them. Thanks.

this is a real bug.  

Version: '5.7.30-asan' (Built on 11 January 2020 with g++ (GCC) 10.0.0 20191215 (experimental))

[ERROR] InnoDB: ibuf cursor restoration fails!. ibuf record inserted to page 368:19443
[ERROR] InnoDB: Submit a detailed bug report to http://bugs.mysql.com
PHYSICAL RECORD: n_fields 7; 1-byte offsets; info bits 0
<cut>
ERROR] [FATAL] InnoDB: Failed to restore ibuf position.
InnoDB: Assertion failure in thread 139877061887744 in file ut0ut.cc line 918
InnoDB: We intentionally generate a memory trap.

(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./pthread_kill.c:56
#1  in my_write_core (sig=sig@entry=6) at ./include/my_thread.h:105
#2  in handle_fatal_signal (sig=6) at ./sql/signal_handler.cc:227
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  in __GI_abort () at abort.c:79
#6  in ut_dbg_assertion_failed  at ./storage/innobase/ut/ut0dbg.cc:75
#7  in ib::fatal::~fatal at ./storage/innobase/ut/ut0ut.cc:918
#8  in ibuf_restore_pos at 
#9  in ibuf_delete_rec at ./storage/innobase/ibuf/ibuf0ibuf.cc:4380
#10 in ibuf_merge_or_delete_for_page at ./storage/innobase/include/buf0buf.h:251
#11 in buf_page_io_complete at ./storage/innobase/buf/buf0buf.cc:5836
#12 in fil_aio_wait at ./storage/innobase/fil/fil0fil.cc:5896
#13 in io_handler_thread at ./storage/innobase/srv/srv0start.cc:319
#14 in start_thread at pthread_create.c:479

I'll look into making a testcase.
o)  small innodb_buffer_pool_size=50M
o)  tables with varchar cols + many secondary indexes
o)  random DML workload
o)  truncate table

When making a testcase,  one needs to be sure change buffering is getting used.
e.g.  show engine innodb status :

-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 14, free list len 680, seg size 695, 62188 merges
merged operations:
 insert 1051877, delete mark 4217777, delete 359159
discarded operations:
 insert 6039, delete mark 33790, delete 64

Verified on 5.7.   Have not managed to repeat this on 8.0.

Posted by developer:
 
Fixed as of the upcoming 5.7.31, 8.0.21 release, and here's the proposed changelog entry from the documentation team:

The server failed intermittently with an "ibuf cursor restoration fails" error.

Bug #104850 marked as duplicate of this one

How to test and reproduce this bug？

https://github.com/mysql/mysql-server/commit/5a0b4ba9d39f40bce2f40fa99512e38444662cac

In 8.0.21, there isn't conditional judgement: fil_space_is_being_truncated(space).
If concurrently `discard tablespace` statement is executing, ibuf cursor restoration fails.