[MDEV-13247] innodb_log_compressed_pages=OFF breaks crash recovery of ROW_FORMAT=COMPRESSED tables Created: 2017-07-05  Updated: 2017-09-08  Resolved: 2017-07-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.2, 10.2.0
Fix Version/s: 10.2.4, 10.1.26

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mdev13247-2.tar.gz     File mdev13247.tar.gz     File page76.trace    
Issue Links:
Duplicate
duplicates MDEV-7635 update defaults and simplify mysqld c... Closed
is duplicated by MDEV-13165 [Draft] InnoDB: Assertion failure in ... Closed
Problem/Incident
causes MDEV-13272 Document default change on parameter ... Closed
is caused by MDEV-6935 Change the default value for innodb_l... Closed

 Description   

10.1 e555540ab6b9c3e0d4fdd00af093b115a9401d0a

 
2017-07-05 18:47:52 140097648996480 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-07-05 18:47:52 140097648996480 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2202473
 
2017-07-05 18:47:52 140097648996480 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
2017-07-05 18:47:52 140097648996480 [Note] InnoDB: Starting final batch to recover 2219 pages from redo log
 
2017-07-05 18:47:52 7f6ae2ffd700  InnoDB: Assertion failure in thread 140097051678464 in file page0zip.cc line 4165
 
InnoDB: Failing assertion: !page_zip_dir_find(page_zip, page_offset(rec))


#1  0x00007f6b046203fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#2  0x00005575b6fafad4 in page_zip_clear_rec (page_zip=0x7f6ae80e82d8, rec=0x7f6aee8b96aa "j\200", index=0x7f6adbc2f178, offsets=0x7f6ae2ffc400) at /data/src/10.1/storage/xtradb/page/page0zip.cc:4165
 
#3  0x00005575b6fb06f8 in page_zip_dir_delete (page_zip=0x7f6ae80e82d8, rec=0x7f6aee8b96aa "j\200", index=0x7f6adbc2f178, offsets=0x7f6ae2ffc400, free=0x0) at /data/src/10.1/storage/xtradb/page/page0zip.cc:4455
 
#4  0x00005575b6f93aff in page_mem_free (page=0x7f6aee8b9000 "", page_zip=0x7f6ae80e82d8, rec=0x7f6aee8b96aa "j\200", index=0x7f6adbc2f178, offsets=0x7f6ae2ffc400) at /data/src/10.1/storage/xtradb/include/page0page.ic:1174
 
#5  0x00005575b6f98ce6 in page_cur_delete_rec (cursor=0x7f6ae2ffc3f0, index=0x7f6adbc2f178, offsets=0x7f6ae2ffc400, mtr=0x7f6ae2ffc8a0) at /data/src/10.1/storage/xtradb/page/page0cur.cc:2140
 
#6  0x00005575b6f9f793 in page_delete_rec_list_end (rec=0x7f6aee8b96b9 "j\200", block=0x7f6ae80e82c8, index=0x7f6adbc2f178, n_recs=18446744073709551615, size=18446744073709551615, mtr=0x7f6ae2ffc8a0) at /data/src/10.1/storage/xtradb/page/page0page.cc:1078
 
#7  0x00005575b6f9f39b in page_parse_delete_rec_list (type=43 '+', ptr=0x7f6aef0d897a "", end_ptr=0x7f6aef0d897a "", block=0x7f6ae80e82c8, index=0x7f6adbc2f178, mtr=0x7f6ae2ffc8a0) at /data/src/10.1/storage/xtradb/page/page0page.cc:969
 
#8  0x00005575b6f71b61 in recv_parse_or_apply_log_rec_body (type=43 '+', ptr=0x7f6aef0d8978 "\006\252", end_ptr=0x7f6aef0d897a "", block=0x7f6ae80e82c8, mtr=0x7f6ae2ffc8a0, space_id=76) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1236
 
#9  0x00005575b6f72d03 in recv_recover_page_func (just_read_in=1, block=0x7f6ae80e82c8) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1747
 
#10 0x00005575b70eb562 in buf_page_io_complete (bpage=0x7f6ae80e82c8) at /data/src/10.1/storage/xtradb/buf/buf0buf.cc:4883
 
#11 0x00005575b71639cb in fil_aio_wait (segment=2) at /data/src/10.1/storage/xtradb/fil/fil0fil.cc:6543
 
#12 0x00005575b70537ec in io_handler_thread (arg=0x5575b8472350 <n+16>) at /data/src/10.1/storage/xtradb/srv/srv0start.cc:586
 
#13 0x00007f6b06589494 in start_thread (arg=0x7f6ae2ffd700) at pthread_create.c:333
 
#14 0x00007f6b046d493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Here is a variation:

2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2136566
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:958 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:959 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:4 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:5 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:6 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:7 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:8 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:9 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 43:10 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:1 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:2 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:3 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:4 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:5 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:6 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:7 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:8 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:9 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 44:10 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:1 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:2 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:3 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:4 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:5 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:6 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:7 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:8 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:9 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 45:10 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:960 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:961 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:962 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:963 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:964 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:965 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:966 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:967 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:968 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:969 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:970 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:971 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:972 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:973 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:974 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:975 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:976 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:977 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:978 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:979 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:980 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:981 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:982 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:983 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:984 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:985 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:986 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:987 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:988 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:989 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:990 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:991 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:992 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:993 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:994 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:995 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:996 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:997 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:998 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:999 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1000 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1001 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1002 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1003 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1004 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1005 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1006 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1007 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1008 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1009 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1010 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1011 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1012 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1013 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1014 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1015 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1016 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1017 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1018 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1019 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1020 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1021 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1022 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 0:1023 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 46:1 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 46:2 from the doublewrite buffer.
 
2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 46:3 from the doublewrite buffer.


2017-07-05 19:10:26 139944868163712 [Note] InnoDB: Recovered page 46:4 from the doublewrite buffer.
 
2017-07-05 19:10:27 139944868163712 [Note] InnoDB: Starting final batch to recover 2236 pages from redo log
 
2017-07-05 19:10:28 7f47507fd700  InnoDB: Assertion failure in thread 139944269960960 in file page0zip.ic line 432
 
 
 
#5  0x00007f4771ef83fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x000055f0b9e0af66 in page_zip_parse_compress_no_data (ptr=0x7f475c5c6de8 "\006", end_ptr=0x7f475c5c6de9 "", page=0x7f475b8fb000 "", page_zip=0x7f4755678ee8, index=0x7f474942f178) at /data/src/10.1/storage/xtradb/include/page0zip.ic:432
 
#7  0x000055f0b9e0d2e3 in recv_parse_or_apply_log_rec_body (type=52 '4', ptr=0x7f475c5c6de8 "\006", end_ptr=0x7f475c5c6de9 "", block=0x7f4755678ed8, mtr=0x7f47507fc8a0, space_id=78) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1383
 
#8  0x000055f0b9e0dd03 in recv_recover_page_func (just_read_in=1, block=0x7f4755678ed8) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1747
 
#9  0x000055f0b9f86562 in buf_page_io_complete (bpage=0x7f4755678ed8) at /data/src/10.1/storage/xtradb/buf/buf0buf.cc:4883
 
#10 0x000055f0b9ffe9cb in fil_aio_wait (segment=2) at /data/src/10.1/storage/xtradb/fil/fil0fil.cc:6543
 
#11 0x000055f0b9eee7ec in io_handler_thread (arg=0x55f0bb30d350 <n+16>) at /data/src/10.1/storage/xtradb/srv/srv0start.cc:586
 
#12 0x00007f4773e61494 in start_thread (arg=0x7f47507fd700) at pthread_create.c:333
 
#13 0x00007f4771fac93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Stack traces are for the current 10.1 build, but it was reproducible on previous ones as well.

To reproduce the assertion failures, download the corresponding attached datadir, unpack it and start the 10.1 server with --innodb-file-size=4K.

If you want to repeat the whole thing, including creating the datadir on 10.1.20,

git clone https://github.com/elenst/rqg --branch mdev13247 mdev13247
 
cd mdev13247
 
BASEDIR_OLD=<10.1.20 basedir> BASEDIR=<current basedir> ./mdev13247.cmd  # to reproduce the first variation
 
# or
 
BASEDIR_OLD=<10.1.20 basedir> BASEDIR=<current basedir> ./mdev13247-2.cmd # to reproduce the second variation

Note: 10.2 does not crash, it produces the error message and refuses to proceed (I believe it's expected behavior):

2017-07-05 19:39:50 140486519435328 [ERROR] InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10.2.2. Please follow the instructions at http://dev.mysql.com/doc/refman/5.7/en/upgrading.html

Upd: Error log and stack trace corresponding to the attached page76.trace, same revision:

2017-07-05 20:55:50 140136681267328 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-07-05 20:55:50 140136681267328 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2028932
 
2017-07-05 20:55:50 140136681267328 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
innobase_init: ib_log: scan 2028932: multi-log rec 1 len 7 page 40:0
 
...
 
innobase_init: ib_log: apply 7732398: 2 len 3 page 0:979
 
2017-07-05 20:55:52 140136681267328 [Note] InnoDB: Starting final batch to recover 2279 pages from redo log
 
2017-07-05 20:55:52 7f73f97fd700  InnoDB: Assertion failure in thread 140136083871488 in file page0zip.cc line 4165
 
InnoDB: Failing assertion: !page_zip_dir_find(page_zip, page_offset(rec))
 
InnoDB: We intentionally generate a memory trap.


#1  0x00007f741ae333fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#2  0x00005633105edad4 in page_zip_clear_rec (page_zip=0x7f73fe895298, rec=0x7f7404fb16aa "j\200", index=0x7f73f242f178, offsets=0x7f73f97fc400) at /data/src/10.1/storage/xtradb/page/page0zip.cc:4165
 
#3  0x00005633105ee6f8 in page_zip_dir_delete (page_zip=0x7f73fe895298, rec=0x7f7404fb16aa "j\200", index=0x7f73f242f178, offsets=0x7f73f97fc400, free=0x0) at /data/src/10.1/storage/xtradb/page/page0zip.cc:4455
 
#4  0x00005633105d1aff in page_mem_free (page=0x7f7404fb1000 "", page_zip=0x7f73fe895298, rec=0x7f7404fb16aa "j\200", index=0x7f73f242f178, offsets=0x7f73f97fc400) at /data/src/10.1/storage/xtradb/include/page0page.ic:1174
 
#5  0x00005633105d6ce6 in page_cur_delete_rec (cursor=0x7f73f97fc3f0, index=0x7f73f242f178, offsets=0x7f73f97fc400, mtr=0x7f73f97fc8a0) at /data/src/10.1/storage/xtradb/page/page0cur.cc:2140
 
#6  0x00005633105dd793 in page_delete_rec_list_end (rec=0x7f7404fb16b9 "j\200", block=0x7f73fe895288, index=0x7f73f242f178, n_recs=18446744073709551615, size=18446744073709551615, mtr=0x7f73f97fc8a0) at /data/src/10.1/storage/xtradb/page/page0page.cc:1078
 
#7  0x00005633105dd39b in page_parse_delete_rec_list (type=43 '+', ptr=0x7f74057d297a "", end_ptr=0x7f74057d297a "", block=0x7f73fe895288, index=0x7f73f242f178, mtr=0x7f73f97fc8a0) at /data/src/10.1/storage/xtradb/page/page0page.cc:969
 
#8  0x00005633105afb61 in recv_parse_or_apply_log_rec_body (type=43 '+', ptr=0x7f74057d2978 "\006\252", end_ptr=0x7f74057d297a "", block=0x7f73fe895288, mtr=0x7f73f97fc8a0, space_id=76) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1236
 
#9  0x00005633105b0d03 in recv_recover_page_func (just_read_in=1, block=0x7f73fe895288) at /data/src/10.1/storage/xtradb/log/log0recv.cc:1747
 
#10 0x0000563310729562 in buf_page_io_complete (bpage=0x7f73fe895288) at /data/src/10.1/storage/xtradb/buf/buf0buf.cc:4883
 
#11 0x00005633107a19cb in fil_aio_wait (segment=2) at /data/src/10.1/storage/xtradb/fil/fil0fil.cc:6543
 
#12 0x00005633106917ec in io_handler_thread (arg=0x563311ab0350 <n+16>) at /data/src/10.1/storage/xtradb/srv/srv0start.cc:586
 
#13 0x00007f741cd9c494 in start_thread (arg=0x7f73f97fd700) at pthread_create.c:333
 
#14 0x00007f741aee793f in clone () from /lib/x86_64-linux-gnu/libc.so.6



 Comments   
Comment by Elena Stepanova [ 2017-07-05 ]

marko, FYI.

Comment by Jan Lindström (Inactive) [ 2017-07-06 ]

Marko is more familiar with row_format=COMPRESSED stuff.

Comment by Marko Mäkelä [ 2017-07-06 ]

With the attached mdev13247-2.tar.gz and 10.1 commit e555540ab6b9c3e0d4fdd00af093b115a9401d0a, for me the crash occurs when applying a MLOG_ZIP_PAGE_COMPRESS_NO_DATA record to tablespace 78, page 21:

	/* If page compression fails then there must be something wrong
 
	because a compress log record is logged only if the compression
 
	was successful. Crash in this case. */
 
 
 
	if (page
 
	    && !page_zip_compress(page_zip, page, index, level, NULL)) {
 
		ut_error;
 
	}

There could be several problems with the recovery. Because redo log is being applied when asynchronous reads for the dirty data pages complete, the order in which we encounter problematic pages may vary.
The --debug=d,ib_log output filtered for this page number is below:

innobase_init: ib_log: scan 11484786: multi-log rec 29 len 3 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 51 len 102 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 50 len 13 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 51 len 1991 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11484786: multi-log rec 43 len 13 page 78:21
 
innobase_init: ib_log: scan 11488866: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11488866: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11489169: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11489497: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11489907: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11490527: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11491148: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11494886: multi-log rec 38 len 24 page 78:21
 
innobase_init: ib_log: scan 11498551: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11505683: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11511703: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11512286: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11512572: multi-log rec 38 len 35 page 78:21
 
innobase_init: ib_log: scan 11513216: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11513532: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11514486: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11514798: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11516320: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11516654: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11517941: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11518257: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11519845: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11520856: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11521149: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11524911: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11526093: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11526421: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11527406: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11528690: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11529935: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11530222: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11530560: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11531518: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11532403: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11534032: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11537085: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11538000: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11538932: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11539234: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11539876: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11540806: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11542054: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11542676: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11544213: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11544505: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11544829: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11546139: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11546759: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11547518: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11548522: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11549124: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11550383: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11551385: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11551685: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11551984: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11552971: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11553634: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11554249: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11554561: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11554561: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11554885: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11555795: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11556478: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11558158: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11558489: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11558801: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11559499: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11560264: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11560929: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11560929: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11561230: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11561904: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11563605: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11564213: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11565890: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11566487: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11567461: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11568658: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11570201: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11570484: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11570825: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11572104: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11572442: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11574054: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11575411: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11575712: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11576927: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11576927: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11579571: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11580804: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11581736: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11582363: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11584880: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11587561: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11589730: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11592259: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11593361: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11595474: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11597936: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11598530: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11598830: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11598830: multi-log rec 38 len 24 page 78:21
 
innobase_init: ib_log: scan 11599157: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11599711: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11600885: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11601192: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11601791: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11602765: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11602765: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11603073: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11603366: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11603366: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11604646: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11604646: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11605272: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11605272: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11605272: multi-log rec 52 len 12 page 78:21
 
innobase_init: ib_log: scan 11605893: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11605893: multi-log rec 52 len 12 page 78:21
 
innobase_init: ib_log: scan 11606613: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11606613: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11606613: multi-log rec 43 len 13 page 78:21
 
innobase_init: ib_log: scan 11606613: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11606613: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11609062: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11609996: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11613087: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11614694: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11616238: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11617485: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11618120: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11618692: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11619664: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11622929: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11623215: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11623515: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11625928: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11627094: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11628319: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11631481: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11639012: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11640936: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11641803: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11642126: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11643026: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11645045: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11645348: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11653575: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11654237: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11655140: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11656446: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11658418: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11660116: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11662070: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11663912: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11665152: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11668316: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11668765: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11669725: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11670063: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11670357: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11671624: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11673741: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11675604: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11678502: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11680077: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11681925: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11682216: multi-log rec 38 len 24 page 78:21
 
innobase_init: ib_log: scan 11684934: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11685226: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11685528: multi-log rec 38 len 24 page 78:21
 
innobase_init: ib_log: scan 11685814: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11686124: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11687409: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11688060: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11690379: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11690733: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11691065: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11692316: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11692316: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11692968: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11694746: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11695467: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11696065: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11699025: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11700341: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11701348: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11704922: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11708497: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11708825: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11709545: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11713659: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11715662: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11716574: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11717820: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11718462: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11719442: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11719745: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11724919: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11725531: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11728030: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11731335: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11732613: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11733220: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11733818: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11735344: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11735344: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11739678: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11740370: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11742058: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11743327: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11743611: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11747303: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11747941: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11748226: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11748904: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11749224: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11750442: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11752027: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11752027: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11753103: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11753417: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11754474: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11754818: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11756353: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11756353: multi-log rec 38 len 26 page 78:21
 
innobase_init: ib_log: scan 11758472: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11760692: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11761884: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11761884: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11762169: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11762169: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11768889: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11768889: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11768889: multi-log rec 52 len 12 page 78:21
 
innobase_init: ib_log: scan 11772710: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11772710: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11772710: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11772710: multi-log rec 50 len 9 page 78:21
 
innobase_init: ib_log: scan 11772710: multi-log rec 43 len 13 page 78:21
 
innobase_init: ib_log: scan 11797394: multi-log rec 53 len 12 page 78:21
 
innobase_init: ib_log: scan 11797394: multi-log rec 38 len 25 page 78:21
 
innobase_init: ib_log: scan 11798040: multi-log rec 38 len 25 page 78:21

The first record for this page is MLOG_INIT_FILE_PAGE (29), which means that the redo log alone will determine the contents of this page. This is good.
If we strip the LSN, the distinct log record types and lengths are as follows:

Number Type Length
1 29 (MLOG_INIT_FILE_PAGE) 3
4 38 (MLOG_COMP_REC_INSERT) 24
160 38 (MLOG_COMP_REC_INSERT) 25
49 38 (MLOG_COMP_REC_INSERT) 26
1 38 (MLOG_COMP_REC_INSERT) 35
3 43 (MLOG_COMP_LIST_END_DELETE) 13
1 50 (MLOG_ZIP_WRITE_HEADER) 13
11 50 (MLOG_ZIP_WRITE_HEADER) 9
1 51 (MLOG_ZIP_PAGE_COMPRESS) 102
1 51 (MLOG_ZIP_PAGE_COMPRESS) 1991
3 52 (MLOG_ZIP_PAGE_COMPRESS_NO_DATA) 12
17 53 (MLOG_ZIP_PAGE_REORGANIZE) 12

The MLOG_ZIP_PAGE_COMPRESS_NO_DATA operation was added to MySQL 5.6 by a Facebook contribution. There was a hard-to-trace correctness problem with it, and the code (and the associated option innodb_log_compressed_pages) was disabled in the 5.6.10 GA release and later improved and enabled in the 5.6.11 release. Maybe there still is some flaw with it.

At least there is the known design problem, which I think should be documented somewhere: If crash recovery replays MLOG_ZIP_COMPRESS_NO_DATA and the server is using a different version of zlib than the one that wrote the record, the deflate() operation with the same parameters could fail, or it could cause the compressed page to be restored differently from what was originally written. Which exact version of zlib was used when creating the dataset? With which parameters was it compiled?

Also in page76.trace there are a few MLOG_ZIP_PAGE_COMPRESS_NO_DATA operations for the page. If the deflate() call on redo log apply makes the compressed data any bigger than what was originally written, then subsequent redo log apply operations on that page may fail. If those redo log records refer to byte offsets in the compressed page, they would be wrong. This is a design problem, and it is also the reason why my original ROW_FORMAT=COMPRESSED design and implementation in the InnoDB Plugin for MySQL 5.1 always wrote the full compressed page image to the redo log.

Workaround (possibly also fix): Set innodb_log_compressed_pages=OFF. Maybe this should be the default setting?

elenst, if you can reproduce this failure by using the exactly same zlib on both the generating and recovering version of MariaDB (they can be the same version), then I believe that we have no choice than to set innodb_log_compressed_pages=OFF by default.

Comment by Marko Mäkelä [ 2017-07-06 ]

A small amendment to my comment: In page76.trace, there were some MLOG_ZIP_PAGE_COMPRESS_NO_DATA (type=52) records for the tablespace for which applying a MLOG_COMP_LIST_END_DELETE (type=43) operation failed. I do not know the page number of the failed operation, so I cannot know for sure if the failure was caused by a prior MLOG_ZIP_PAGE_COMPRESS_NO_DATA record. For pages 76:14, 76:23 to 76:31 and 76:42 to 76:53 there is only a MLOG_COMP_LIST_END_DELETE record but no MLOG_ZIP_PAGE_COMPRESS_NO_DATA. There are 6 pages for which my explanation is possible: 76:21, 76:22, 76:32, 76:38, 76:39, 76:41.

By the way, the probability of these failures can be improved by adding #define UNIV_ZIP_COPY to univ.i. I would also recommend #define UNIV_ZIP_DEBUG.

Comment by Marko Mäkelä [ 2017-07-06 ]

If any claims in the MDEV-6935 commit message are incorrect, perhaps that change should be reverted.

Comment by Elena Stepanova [ 2017-07-06 ]

Indeed, the test was using different versions of zlib before and after recovery (1.2.3 vs 1.2.8 according to the error log).
It happened because 10.1.20 was represented by a release tarball, which has zlib linked statically, while the current 10.1 server under test was built locally and linked dynamically with the library on my machine. I expect different kinds of library changes to happen in real life as well, as it's been extensively discussed on the channel.

I tried to reproduce the same problem with the exact same zlib library before/after recovery and was not able to:
release bintar 10.1.20 (for glibc 2.14+) => release bintar 10.1.25 (for glibc 2.14+)
release bintar 10.1.20 (for glibc 2.14+) => release bintar 10.1.25 (for old glibc)
local build of 10.1.20 => local build of current server

Also, it didn't crash for me when i tried
local build of 10.1.20 => release bintar 10.1.25 , which have different zlib versions, but the other way round, 1.2.8 => 1.2.3

Additionally I tried to run the same test as before, on the combination of zlib versions which led to a crash, but with --innodb_log_compressed_pages=on, it doesn't crash either.

Comment by Marko Mäkelä [ 2017-07-06 ]

I think that the safest and simplest solution is to revert the default value to innodb_log_compressed_pages=ON. Users are free to override it, but they must understand the impact (ensure that the server is shut down cleanly before upgrading the server or a dynamically linked libz.so).

Comment by Marko Mäkelä [ 2017-07-07 ]

MDEV-7635 restored the safe default value in MariaDB 10.2.4.
The unsafe default value innodb_log_compressed_pages=OFF was used in MariaDB 10.1.2 to 10.1.25 and MariaDB 10.2.0 to MariaDB 10.2.3.

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