Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-13247

innodb_log_compressed_pages=OFF breaks crash recovery of ROW_FORMAT=COMPRESSED tables

    Details

      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
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: