Bug #82798 Small buffer pools might be too small for rseg init during crash recovery
Submitted: 30 Aug 2016 9:54 Modified: 30 Aug 2016 11:55
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Verified Impact on me:
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6, 5.6.32 OS:Any
Assigned to: CPU Architecture:Any
Tags: buffer pool, crash recovery, flushing, innodb, rseg

[30 Aug 2016 9:54] Laurynas Biveinis
With an 8MB buffer pool, if crash recovery runs, server might find itself in situation where all the data pages in the buffer pool are pinned by one of the two MTRs opened by the rseg initialisation.

Server error log will contain
016-08-30 10:49:27 28360 [Note] InnoDB: Log scan progressed past the checkpoint lsn 4428952
2016-08-30 10:49:27 28360 [Note] InnoDB: Database was not shutdown normally!
2016-08-30 10:49:27 28360 [Note] InnoDB: Starting crash recovery.
2016-08-30 10:49:27 28360 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-08-30 10:49:27 28360 [Note] InnoDB: Restoring possible half-written data pages 
2016-08-30 10:49:27 28360 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 6332328
2016-08-30 10:49:29 7f9dee0a4740  InnoDB: Warning: difficult to find free blocks in
InnoDB: the buffer pool (21 search iterations)!
InnoDB: 21 failed attempts to flush a page! Consider
InnoDB: increasing the buffer pool size.
InnoDB: It is also possible that in your Unix version
InnoDB: fsync is very slow, or completely frozen inside
InnoDB: the OS kernel. Then upgrading to a newer version
InnoDB: of your operating system may help. Look at the
InnoDB: number of fsyncs in diagnostic info below.
InnoDB: Pending flushes (fsync) log: 0; buffer pool: 0
InnoDB: 575 OS file reads, 56 OS file writes, 56 OS fsyncs
InnoDB: Starting InnoDB Monitor to print further
InnoDB: diagnostics to the standard output.
08:02:18 UTC - mysqld got signal 6 ;

The stacktrace

Thread 1 (Thread 0x7f9dee0a4740 (LWP 28360)):
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000000000ae8381 in my_write_core (sig=6) at /home/laurynas/mysql-server/mysys/stacktrace.c:422
#2  0x000000000074165f in handle_fatal_signal (sig=6) at /home/laurynas/mysql-server/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007f9decac5d13 in select () at ../sysdeps/unix/syscall-template.S:84
#5  0x0000000000c5e79a in os_thread_sleep (tm=100000) at /home/laurynas/mysql-server/storage/innobase/os/os0thread.cc:261
#6  0x0000000000db9788 in buf_LRU_get_free_block (buf_pool=0x2242c48) at /home/laurynas/mysql-server/storage/innobase/buf/buf0lru.cc:1355
#7  0x0000000000da31d5 in buf_page_init_for_read (err=0x7ffd286d59f4, mode=132, space=0, zip_size=0, unzip=0, tablespace_version=1, offset=1) at /home/laurynas/mysql-server/storage/innobase/buf/buf0buf.cc:3624
#8  0x0000000000dbf038 in buf_read_page_low (err=0x7ffd286d59f4, sync=true, mode=132, space=0, zip_size=0, unzip=0, tablespace_version=1, offset=1) at /home/laurynas/mysql-server/storage/innobase/buf/buf0rea.cc:163
#9  0x0000000000dbf770 in buf_read_page (space=0, zip_size=0, offset=1) at /home/laurynas/mysql-server/storage/innobase/buf/buf0rea.cc:411
#10 0x0000000000da104a in buf_page_get_gen (space=0, zip_size=0, offset=1, rw_latch=2, guess=0x0, mode=10, file=0x106dec8 "/home/laurynas/mysql-server/storage/innobase/ibuf/ibuf0ibuf.cc", line=4598, mtr=0x7ffd286d5d20) at /home/laurynas/mysql-server/storage/innobase/buf/buf0buf.cc:2712
#11 0x0000000000c1d684 in ibuf_bitmap_get_map_page_func (space=0, page_no=432, zip_size=0, file=0x106dec8 "/home/laurynas/mysql-server/storage/innobase/ibuf/ibuf0ibuf.cc", line=4598, mtr=0x7ffd286d5d20) at /home/laurynas/mysql-server/storage/innobase/ibuf/ibuf0ibuf.cc:859
#12 0x0000000000c24f59 in ibuf_merge_or_delete_for_page (block=0x7f9de8085800, space=0, page_no=432, zip_size=0, update_ibuf_bitmap=1) at /home/laurynas/mysql-server/storage/innobase/ibuf/ibuf0ibuf.cc:4598
#13 0x0000000000da4ca1 in buf_page_io_complete (bpage=0x7f9de8085800) at /home/laurynas/mysql-server/storage/innobase/buf/buf0buf.cc:4313
#14 0x0000000000dbf229 in buf_read_page_low (err=0x7ffd286d6314, sync=true, mode=132, space=0, zip_size=0, unzip=0, tablespace_version=1, offset=432) at /home/laurynas/mysql-server/storage/innobase/buf/buf0rea.cc:213
#15 0x0000000000dbf770 in buf_read_page (space=0, zip_size=0, offset=432) at /home/laurynas/mysql-server/storage/innobase/buf/buf0rea.cc:411
#16 0x0000000000da104a in buf_page_get_gen (space=0, zip_size=0, offset=432, rw_latch=2, guess=0x0, mode=10, file=0x10b1610 "/home/laurynas/mysql-server/storage/innobase/include/trx0undo.ic", line=171, mtr=0x7ffd286d65d0) at /home/laurynas/mysql-server/storage/innobase/buf/buf0buf.cc:2712
#17 0x0000000000d52080 in trx_undo_page_get (space=0, zip_size=0, page_no=432, mtr=0x7ffd286d65d0) at /home/laurynas/mysql-server/storage/innobase/include/trx0undo.ic:170
#18 0x0000000000d54610 in trx_undo_mem_create_at_db_start (rseg=0x2350228, id=0, page_no=432, mtr=0x7ffd286d65d0) at /home/laurynas/mysql-server/storage/innobase/trx/trx0undo.cc:1294
#19 0x0000000000d54dc2 in trx_undo_lists_init (rseg=0x2350228) at /home/laurynas/mysql-server/storage/innobase/trx/trx0undo.cc:1426
#20 0x0000000000d448a3 in trx_rseg_mem_create (id=127, space=0, zip_size=0, page_no=300, ib_bh=0x2306750, mtr=0x7ffd286d6c30) at /home/laurynas/mysql-server/storage/innobase/trx/trx0rseg.cc:209
#21 0x0000000000d44b8e in trx_rseg_create_instance (sys_header=0x7f9de84c0026 "", ib_bh=0x2306750, mtr=0x7ffd286d6c30) at /home/laurynas/mysql-server/storage/innobase/trx/trx0rseg.cc:287
#22 0x0000000000d44e3a in trx_rseg_array_init (sys_header=0x7f9de84c0026 "", ib_bh=0x2306750, mtr=0x7ffd286d6c30) at /home/laurynas/mysql-server/storage/innobase/trx/trx0rseg.cc:358
#23 0x0000000000d4770f in trx_sys_init_at_db_start () at /home/laurynas/mysql-server/storage/innobase/trx/trx0sys.cc:515
#24 0x0000000000d22617 in innobase_start_or_create_for_mysql () at /home/laurynas/mysql-server/storage/innobase/srv/srv0start.cc:2455
#25 0x0000000000bd6a41 in innobase_init (p=0x21ca5e0) at /home/laurynas/mysql-server/storage/innobase/handler/ha_innodb.cc:3428
#26 0x00000000006483f3 in ha_initialize_handlerton (plugin=0x21bf750) at /home/laurynas/mysql-server/sql/handler.cc:662
#27 0x000000000080b38e in plugin_initialize (plugin=0x21bf750) at /home/laurynas/mysql-server/sql/sql_plugin.cc:1138
#28 0x000000000080be87 in plugin_init (argc=0x182d568 <remaining_argc>, argv=0x2090d98, flags=0) at /home/laurynas/mysql-server/sql/sql_plugin.cc:1432
#29 0x0000000000630dbb in init_server_components () at /home/laurynas/mysql-server/sql/mysqld.cc:4884
#30 0x0000000000631d45 in mysqld_main (argc=79, argv=0x2090d98) at /home/laurynas/mysql-server/sql/mysqld.cc:5481
#31 0x0000000000626756 in main (argc=9, argv=0x7ffd286db298) at /home/laurynas/mysql-server/sql/main.cc:25

At this point, buffer pool data pages are a mix of FIL_PAGE_UNDO_LOG, FIL_PAGE_TYPE_SYS, and FIL_PAGE_TYPE_TRX_SYS pages, all buffer pool-fixed, by two MTRs started at either trx_undo_list_init, either trx_sys_init_at_db_start.

What I don't understand is why the reproduction procedure does not result in this situation every time, so there might be something else going on.

How to repeat:
An intermittent failure on parts.partition_debug_innodb. For example, make several copies of the testcase, option, and result files, then

./mtr --debug-server --do-test=partition_debug_innodb --big-test --repeat=500 --parallel=6
parts.partition_debug_innodb2            w3 [ pass ]  134226
worker[2] Trying to dump core for [mysqltest - pid: 23068, winpid: 23068]
worker[2] Trying to dump core for [mysqld.1 - pid: 28359, winpid: 28359]
parts.partition_debug_innodb3            w2 [ fail ]  timeout after 900 seconds
        Test ended at 2016-08-30 11:03:09

Test case timeout after 900 seconds
and the stacktrace as above

Suggested fix:
1) Observe that rseg does not care about ibuf in the first place, thus backporting bug 75235 fix is both an general optimisation and would reduce the buffer pool pressure here.
2) Chop up MTRs into smaller ones? Not sure how to do that safely.
[30 Aug 2016 11:07] Naga Satyanarayana Bodapati
One of the suggested solution to chop mtrs is done by Bug#79201 in 5.7. I think this bug would is already solved by the fix for Bug#79201
[30 Aug 2016 11:09] MySQL Verification Team
Hello Laurynas,

Thank you for the report.
Observed this with 5.6.32.

[30 Aug 2016 11:09] MySQL Verification Team
test results

Attachment: 82798_5.6.32.results (application/octet-stream, text), 27.37 KiB.

[30 Aug 2016 11:55] Laurynas Biveinis
Thanks, I was not aware of bug 79201 fix details. Indeed it looks like its backport would fix this issue.