origin/10.6 92abdcca5a5324f0727112ab2417d10c7a8d5094 2021-01-07T09:08:09+02:00
|
Workflow:
|
1. Start the server
|
2. Run a DDL/DML mix by 9 sessions
|
3. During 2. is ongoing kill the server
|
4. The attempt to restart the server fails with
|
mysqld:storage/innobase/log/log0recv.cc:274: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed.
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00007d171d43c859 in __GI_abort () at abort.c:79
|
#2 0x00007d171d43c729 in __assert_fail_base (fmt=0x7d171d5d2588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()",
|
file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274, function=<optimized out>) at assert.c:92
|
#3 0x00007d171d44df36 in __GI___assert_fail (assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()", file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274,
|
function=0x564bea837d40 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101
|
#4 0x0000564be906714e in log_phys_t::apply (this=0x6400003b2740, block=..., last_offset=@0x608001af92e4: 0) at /Server/10.6E/storage/innobase/log/log0recv.cc:274
|
#5 0x0000564be905473c in recv_recover_page (block=0x6400000e8360, mtr=..., Traceback (most recent call last):
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1522, in __call__
|
return self.lookup[basename].invoke(val)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1459, in invoke
|
return self.function(self.name, value)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 649, in __init__
|
self.link_type = nodetype.pointer()
|
AttributeError: 'NoneType' object has no attribute 'pointer'
|
p=
|
..., space=0x613000000c98, init=0x6070000117f0) at /Server/10.6E/storage/innobase/log/log0recv.cc:2316
|
#6 0x0000564be906f5c6 in recv_sys_t::recover_low (this=0x564bebab2da0 <recv_sys>, page_id=..., Traceback (most recent call last):
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1522, in __call__
|
return self.lookup[basename].invoke(val)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1459, in invoke
|
return self.function(self.name, value)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 649, in __init__
|
self.link_type = nodetype.pointer()
|
AttributeError: 'NoneType' object has no attribute 'pointer'
|
p=
|
..., mtr=..., b=0x6400000e8360) at /Server/10.6E/storage/innobase/log/log0recv.cc:2590
|
#7 0x0000564be905753b in recv_sys_t::apply (this=0x564bebab2da0 <recv_sys>, last_batch=true) at /Server/10.6E/storage/innobase/log/log0recv.cc:2705
|
#8 0x0000564be92efde0 in srv_start (create_new_db=false) at /Server/10.6E/storage/innobase/srv/srv0start.cc:1470
|
#9 0x0000564be8e6c164 in innodb_init (p=0x615000002898) at /Server/10.6E/storage/innobase/handler/ha_innodb.cc:3689
|
#10 0x0000564be8350be1 in ha_initialize_handlerton (plugin=0x621000033010) at /Server/10.6E/sql/handler.cc:645
|
#11 0x0000564be7b895b4 in plugin_initialize (tmp_root=0x7ffe97cc90a0, plugin=0x621000033010, argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, options_only=false) at /Server/10.6E/sql/sql_plugin.cc:1459
|
#12 0x0000564be7b8b542 in plugin_init (argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, flags=0) at /Server/10.6E/sql/sql_plugin.cc:1751
|
#13 0x0000564be784466b in init_server_components () at /Server/10.6E/sql/mysqld.cc:4950
|
#14 0x0000564be784665e in mysqld_main (argc=28, argv=0x615000000e08) at /Server/10.6E/sql/mysqld.cc:5539
|
#15 0x0000564be783014d in main (argc=27, argv=0x7ffe97ccb7d8) at /Server/10.6E/sql/main.cc:25
|
(rr)
|
|
pluto:/data/Results/1610366087/CR-20/dev/shm/vardir/1610366087/50/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0 # Fate of the server till SIGKILL
|
_RR_TRACE_DIR="." rr replay --mark-stdio # The failing restart
|
|
|
|
RQG
|
====
|
git clone https://github.com/mleich1/rqg --branch experimental RQG
|
|
perl rqg.pl \
|
--no-mask \
|
--seed=1610366105 \
|
--duration=300 \
|
--engine=InnoDB \
|
--queries=100000000 \
|
--mysqld=--loose_innodb_use_native_aio=1 \
|
--reporters=Backtrace,ErrorLog,Deadlock1,CrashRecovery1 \
|
--mysqld=--innodb_undo_tablespaces=3 \
|
--mysqld=--innodb_immediate_scrub_data_uncompressed=1 \
|
--mysqld=--innodb_file_per_table=0 \
|
--restart_timeout=600 \
|
--max_gd_duration=1200 \
|
--mysqld=--innodb_page_size=8K \
|
--mysqld=--innodb-buffer-pool-size=8M \
|
--mysqld=--log_output=none \
|
--sqltrace=MarkErrors \
|
--grammar=conf/mariadb/innodb_compression_encryption.yy \
|
--gendata=conf/mariadb/innodb_compression_encryption.zz \
|
--mysqld=--plugin-load-add=file_key_management.so \
|
--mysqld=--loose-file-key-management-filename=$RQG/conf/mariadb/encryption_keys.txt \
|
--threads=9 \
|
--duration=300 \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--basedir2=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Extended \
|
--rr_options=--chaos
|
|
You will need several attempts for replaying the bug once.
|
{"report":{"fcp":1588.7999999523163,"ttfb":407,"pageVisibility":"visible","entityId":95824,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"9bc94f2c-8471-42a6-b0d9-1a7bf788e40b","navigationType":0,"readyForUser":1699.2000000476837,"redirectCount":0,"resourceLoadedEnd":1870.5,"resourceLoadedStart":412.09999990463257,"resourceTiming":[{"duration":625.1000001430511,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":412.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":412.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1037.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":625.0999999046326,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":412.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":412.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1037.5,"responseStart":0,"secureConnectionStart":0},{"duration":635,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":412.59999990463257,"connectEnd":412.59999990463257,"connectStart":412.59999990463257,"domainLookupEnd":412.59999990463257,"domainLookupStart":412.59999990463257,"fetchStart":412.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":412.59999990463257,"responseEnd":1047.5999999046326,"responseStart":1047.5999999046326,"secureConnectionStart":412.59999990463257},{"duration":692.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":412.7999999523163,"connectEnd":412.7999999523163,"connectStart":412.7999999523163,"domainLookupEnd":412.7999999523163,"domainLookupStart":412.7999999523163,"fetchStart":412.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":412.7999999523163,"responseEnd":1105,"responseStart":1105,"secureConnectionStart":412.7999999523163},{"duration":696.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":413,"connectEnd":413,"connectStart":413,"domainLookupEnd":413,"domainLookupStart":413,"fetchStart":413,"redirectEnd":0,"redirectStart":0,"requestStart":413,"responseEnd":1109.2999999523163,"responseStart":1109.2999999523163,"secureConnectionStart":413},{"duration":696.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":413.5,"connectEnd":413.5,"connectStart":413.5,"domainLookupEnd":413.5,"domainLookupStart":413.5,"fetchStart":413.5,"redirectEnd":0,"redirectStart":0,"requestStart":413.5,"responseEnd":1109.7000000476837,"responseStart":1109.7000000476837,"secureConnectionStart":413.5},{"duration":696.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":413.59999990463257,"connectEnd":413.59999990463257,"connectStart":413.59999990463257,"domainLookupEnd":413.59999990463257,"domainLookupStart":413.59999990463257,"fetchStart":413.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":413.59999990463257,"responseEnd":1110.0999999046326,"responseStart":1110.0999999046326,"secureConnectionStart":413.59999990463257},{"duration":797.4000000953674,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":413.7999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":413.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1211.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":696.5999999046326,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":414,"connectEnd":414,"connectStart":414,"domainLookupEnd":414,"domainLookupStart":414,"fetchStart":414,"redirectEnd":0,"redirectStart":0,"requestStart":414,"responseEnd":1110.5999999046326,"responseStart":1110.5999999046326,"secureConnectionStart":414},{"duration":797.2000000476837,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":414.2000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":414.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1211.4000000953674,"responseStart":0,"secureConnectionStart":0},{"duration":696.9000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":414.2999999523163,"connectEnd":414.2999999523163,"connectStart":414.2999999523163,"domainLookupEnd":414.2999999523163,"domainLookupStart":414.2999999523163,"fetchStart":414.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":414.2999999523163,"responseEnd":1111.2000000476837,"responseStart":1111.2000000476837,"secureConnectionStart":414.2999999523163},{"duration":900.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":421.2000000476837,"connectEnd":421.2000000476837,"connectStart":421.2000000476837,"domainLookupEnd":421.2000000476837,"domainLookupStart":421.2000000476837,"fetchStart":421.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":421.2000000476837,"responseEnd":1322,"responseStart":1322,"secureConnectionStart":421.2000000476837},{"duration":1318,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":433.7999999523163,"connectEnd":433.7999999523163,"connectStart":433.7999999523163,"domainLookupEnd":433.7999999523163,"domainLookupStart":433.7999999523163,"fetchStart":433.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":433.7999999523163,"responseEnd":1751.7999999523163,"responseStart":1751.7999999523163,"secureConnectionStart":433.7999999523163},{"duration":110.19999980926514,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":1232.4000000953674,"connectEnd":1232.4000000953674,"connectStart":1232.4000000953674,"domainLookupEnd":1232.4000000953674,"domainLookupStart":1232.4000000953674,"fetchStart":1232.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":1232.4000000953674,"responseEnd":1342.5999999046326,"responseStart":1342.5999999046326,"secureConnectionStart":1232.4000000953674},{"duration":312.59999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1538,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1538,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1850.5999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":331.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/e65b778d185daf5aee24936755b43da6/_/download/contextbatch/js/browser-metrics-plugin.contrib,-_super,-project.issue.navigator,-jira.view.issue,-atl.general/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1539,"connectEnd":1539,"connectStart":1539,"domainLookupEnd":1539,"domainLookupStart":1539,"fetchStart":1539,"redirectEnd":0,"redirectStart":0,"requestStart":1539,"responseEnd":1870.5,"responseStart":1870.5,"secureConnectionStart":1539},{"duration":339.19999980926514,"initiatorType":"script","name":"https://jira.mariadb.org/s/097ae97cb8fbec7d6ea4bbb1f26955b9-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/js/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":1539.4000000953674,"connectEnd":1539.4000000953674,"connectStart":1539.4000000953674,"domainLookupEnd":1539.4000000953674,"domainLookupStart":1539.4000000953674,"fetchStart":1539.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":1539.4000000953674,"responseEnd":1878.5999999046326,"responseStart":1878.5,"secureConnectionStart":1539.4000000953674},{"duration":356.7000000476837,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1582.2999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1582.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1939,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":187,"responseStart":407,"responseEnd":433,"domLoading":410,"domInteractive":1873,"domContentLoadedEventStart":1873,"domContentLoadedEventEnd":1937,"domComplete":2523,"loadEventStart":2524,"loadEventEnd":2524,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1797.0999999046326},{"name":"bigPipe.sidebar-id.end","time":1798.0999999046326},{"name":"bigPipe.activity-panel-pipe-id.start","time":1798.2999999523163},{"name":"bigPipe.activity-panel-pipe-id.end","time":1808.2000000476837},{"name":"activityTabFullyLoaded","time":1959.5}],"measures":[],"correlationId":"e90b04f2cb9db9","effectiveType":"4g","downlink":9,"rtt":0,"serverDuration":140,"dbReadsTimeInMs":19,"dbConnsTimeInMs":29,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
The index ID mismatch after recovery could happen because a freed page was still attached to some other table. The key here seems to be innodb_file_per_table=0.
ssh sdp
_RR_TRACE_DIR=/home/mleich/RQG_O/storage/1610556037/tmp1/dev/shm/vardir/1610556037/232/1/rr rr replay
The PAGE_INDEX_ID was initialized here:
(rr) when
Current event: 129184
(rr) bt
#0 0x00005558f85d14a3 in mtr_t::write<8u, (mtr_t::write_type)0, unsigned long>
(this=0x61a0000576a8, block=..., ptr=0x17994ce6a042, val=116)
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:209
#1 0x00005558f88e2f1c in PageBulk::init (this=0x61a000057698)
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:101
#2 0x00005558f88e6334 in BtrBulk::insert (this=0x607000e851f8,
tuple=0x6310000648d0, level=0)
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:1031
#3 0x00005558f865053a in BtrBulk::insert (this=0x607000e851f8,
tuple=0x6310000648d0)
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/btr0bulk.h:301
#4 0x00005558f86bf0c1 in row_merge_insert_index_tuples (index=0x61700003bca0,
…
#26 0x00005558f701ec98 in mysql_parse (thd=0x62b00007e218,
rawbuf=0x62b000085238 "OPTIMIZE TABLE `test`.`t6`", length=26,
parser_state=0x50d457e7a7c0, is_com_multi=false, is_next_command=false)
at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
No earlier contents of this page 116 is available in the buffer pool. Earlier, the memory was used for buffering redo log records during recovery.
The OPTIMIZE TABLE that is rebuilding the table t6 is reusing the page 116 for a PRIMARY key page of the rebuilt table. But, the GEN_CLUST_INDEX of table E is pointing to this page in purge, even though the page was already reused by the OPTIMIZE TABLE of another table:
#6 0x00005558f87461f6 in row_search_on_row_ref (pcur=0x61f000000540, mode=2,
table=0x618000040920, ref=0x625001a1fdc0, mtr=0x233825740060)
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0row.cc:1213
#7 0x00005558f872edfd in row_purge_reposition_pcur (mode=2, node=0x61f0000004a0,
mtr=0x233825740060)
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0purge.cc:78
In the root page of that clustered index (page 92), we have PAGE_LEVEL=1 and we do have a record (DB_ROW_ID,page)=(69657,116).
We will have to find out when the allocation status of page 116 changed, in the allocation bitmap page (page 0 in the system tablespace):
(rr) find_page_105 0 0
$25 = (buf_block_t *) 0x17994c6655e8
(rr) display/x $25.frame[150+24+116*2/8]
At the end of the last recovery batch, these bits are 0xef. As expected, the least significant bit will be cleared (the byte will first be changed to 0xee) during our OPTIMIZE TABLE:
#0 mtr_t::write<1u, (mtr_t::write_type)0, unsigned char> (this=0x50d457e72280,
block=..., ptr=0x17994cccc0cb, val=238 '\356')
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:211
#1 0x00005558f8ae15af in xdes_set_free<false> (block=..., descr=0x17994cccc096 "",
offset=116, mtr=0x50d457e72280)
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:164
#2 0x00005558f8ad3654 in fsp_alloc_from_free_frag (header=0x17994c6655e8,
xdes=0x17994c6655e8, descr=0x17994cccc096 "", bit=116, mtr=0x50d457e72280)
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:1016
#3 0x00005558f8ad432b in fsp_alloc_free_page (space=0x615000003518, hint=0,
mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:1162
#4 0x00005558f8ad9fd8 in fseg_alloc_free_page_low (space=0x615000003518,
seg_inode=0x17994ce1e172 "", iblock=0x17994c674390, hint=0, direction=111 'o',
has_done_reservation=true, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2084
#5 0x00005558f8adb0ba in fseg_alloc_free_page_general (seg_header=0x17994c85004a "",
hint=0, direction=111 'o', has_done_reservation=true, mtr=0x50d457e72280,
init_mtr=0x61a0000576a8)
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2215
#6 0x00005558f88bb007 in btr_page_alloc_low (index=0x61700003bca0, hint_page_no=0,
file_direction=111 'o', level=0, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:536
#7 0x00005558f88bb07f in btr_page_alloc (index=0x61700003bca0, hint_page_no=0,
file_direction=111 'o', level=0, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:569
#8 0x00005558f88e2a02 in PageBulk::init (this=0x61a000057698)
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:73
I will have to check when the page was freed before the server was killed, and why it happened while table E still exists. My guess is an old problem: DDL is not actually safe in InnoDB. We would invoke btr_free() already while delete-marking the record in SYS_INDEXES, before that transaction is actually committed (to be fixed in
MDEV-18518). Soon we will see if my guess is right.