Using the mtr test case that thiru provided, I was able to produce an rr replay trace of this. I got an OPT_PAGE_CHECKSUM failure (MDEV-18976); these records are something that is being written in debug builds. The failure occurred for the following OPT_PAGE_CHECKSUM record:
I found the corresponding mini-transaction in the rr replay trace of the server that was intentionally killed by the test. The page was being marked as freed by the following:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
#3 0x00005598517b44a2 in buf_page_free (space=space@entry=0x5598545749f8, page=page@entry=494, mtr=mtr@entry=0x7e813d744a70) at /mariadb/10.6m/storage/innobase/buf/buf0buf.cc:2157
at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2767
#5 0x00005598517ed72c in fseg_free_step (header=0x19806e90c04a "", mtr=mtr@entry=0x7e813d744a70, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2831
#6 0x00005598517f450c in btr_free_but_not_root (block=block@entry=0x19806e4542f0, log_mode=MTR_LOG_ALL, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1142
#7 0x00005598517f6fb2 in btr_free_if_exists (space=space@entry=0x5598545749f8, page=page@entry=313, index_id=<optimized out>, mtr=mtr@entry=0x7e813d745150)
at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1229
#8 0x0000559851870d44 in dict_drop_index_tree (pcur=pcur@entry=0x5598545d15e0, trx=trx@entry=0x0, mtr=mtr@entry=0x7e813d745150) at /mariadb/10.6m/storage/innobase/dict/dict0crea.cc:905
#9 0x000055985198a455 in row_purge_remove_clust_if_poss_low (node=node@entry=0x5598545d1540, mode=mode@entry=BTR_MODIFY_LEAF) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:166
#10 0x000055985198aea9 in row_purge_remove_clust_if_poss (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:259
#11 0x000055985198b043 in row_purge_del_mark (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:635
#12 0x000055985198b799 in row_purge_record_func (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0, updated_extern=false)
at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1215
#13 0x000055985198b90e in row_purge (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1276
This is the purge of delete-marking a SYS_INDEXES record corresponding to DROP TABLE t1 in the system tablespace.
This mini-transaction (at LSN=9388592) failed to write any FREE_PAGE record. At mtr_t::commit(), m_memo would comprise 69 latches, and 80 bytes of log would have been written: WRITE, MEMSET and MEMMOVE records and two OPT_PAGE_CHECKSUM for other pages than this freed page.
The oldest_modification of the page was 8407829 (which is before the recovery checkpoint LSN) at the time when it was cleared by the page cleaner.
I think that the problem is that there was no FREE_PAGE record written for this page 494 (0x1ee). We do have it for some neighbours, in mlog_init at the time the recovery catches the error:
…
[{m_id = 446}] = {lsn = 9388941, created = false},
[{m_id = 447}] = {lsn = 9388900, created = false},
[{m_id = 512}] = {lsn = 9390540, created = false},
[{m_id = 513}] = {lsn = 9392084, created = false},
…
The test case that I used is as follows:
--source include/have_innodb.inc
--source include/have_sequence.inc
SETGLOBAL INNODB_FILE_PER_TABLE= 0;
CREATETABLE t1(f1 INTNOTNULL, f2 INTNOTNULL,
f3 INTNOTNULL, INDEX(f1),
INDEX(f2), INDEX(f3))ENGINE=InnoDB;
INSERTINTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
INSERTINTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
INSERTINTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
DROPTABLE t1;
SETGLOBAL innodb_max_purge_lag_wait=0;
let $shutdown_timeout=0;
--source include/restart_mysqld.inc
This would seem to fail reliably when not using rr. I produced my rr trace as follows:
while ./mtr --rr=-h --parallel=auto name_of_test{,,,,,,,,,,,,,,,,}; do :; done
Marko Mäkelä
added a comment - Using the mtr test case that thiru provided, I was able to produce an rr replay trace of this. I got an OPT_PAGE_CHECKSUM failure ( MDEV-18976 ); these records are something that is being written in debug builds. The failure occurred for the following OPT_PAGE_CHECKSUM record:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
(rr) p *this
$2 = {<log_rec_t> = {next = 0x7f1871570dc8, lsn = 8448794}, start_lsn = 8448769}
In that page, we had FIL_PAGE_LSN of 6281382, which is too old. The recovery had started like this:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
2023-09-14 11:08:03 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8415203,9398815
2023-09-14 11:08:03 0 [Note] InnoDB: To recover: 260 pages
2023-09-14 11:08:04 0 [ERROR] InnoDB: OPT_PAGE_CHECKSUM mismatch on [page id: space=0, page number=494]
I found the corresponding mini-transaction in the rr replay trace of the server that was intentionally killed by the test. The page was being marked as freed by the following:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
#3 0x00005598517b44a2 in buf_page_free (space=space@entry=0x5598545749f8, page=page@entry=494, mtr=mtr@entry=0x7e813d744a70) at /mariadb/10.6m/storage/innobase/buf/buf0buf.cc:2157
#4 0x00005598517eb685 in fseg_free_extent (seg_inode=seg_inode@entry=0x19806e8cf872 "", iblock=0x19806e4535f0, space=space@entry=0x5598545749f8, page=448, mtr=mtr@entry=0x7e813d744a70, ahi=ahi@entry=false)
at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2767
#5 0x00005598517ed72c in fseg_free_step (header=0x19806e90c04a "", mtr=mtr@entry=0x7e813d744a70, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2831
#6 0x00005598517f450c in btr_free_but_not_root (block=block@entry=0x19806e4542f0, log_mode=MTR_LOG_ALL, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1142
#7 0x00005598517f6fb2 in btr_free_if_exists (space=space@entry=0x5598545749f8, page=page@entry=313, index_id=<optimized out>, mtr=mtr@entry=0x7e813d745150)
at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1229
#8 0x0000559851870d44 in dict_drop_index_tree (pcur=pcur@entry=0x5598545d15e0, trx=trx@entry=0x0, mtr=mtr@entry=0x7e813d745150) at /mariadb/10.6m/storage/innobase/dict/dict0crea.cc:905
#9 0x000055985198a455 in row_purge_remove_clust_if_poss_low (node=node@entry=0x5598545d1540, mode=mode@entry=BTR_MODIFY_LEAF) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:166
#10 0x000055985198aea9 in row_purge_remove_clust_if_poss (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:259
#11 0x000055985198b043 in row_purge_del_mark (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:635
#12 0x000055985198b799 in row_purge_record_func (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0, updated_extern=false)
at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1215
#13 0x000055985198b90e in row_purge (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1276
This is the purge of delete-marking a SYS_INDEXES record corresponding to DROP TABLE t1 in the system tablespace.
This mini-transaction (at LSN=9388592) failed to write any FREE_PAGE record. At mtr_t::commit() , m_memo would comprise 69 latches, and 80 bytes of log would have been written: WRITE , MEMSET and MEMMOVE records and two OPT_PAGE_CHECKSUM for other pages than this freed page.
The oldest_modification of the page was 8407829 (which is before the recovery checkpoint LSN) at the time when it was cleared by the page cleaner.
I think that the problem is that there was no FREE_PAGE record written for this page 494 (0x1ee). We do have it for some neighbours, in mlog_init at the time the recovery catches the error:
…
[{m_id = 446}] = {lsn = 9388941, created = false},
[{m_id = 447}] = {lsn = 9388900, created = false},
[{m_id = 512}] = {lsn = 9390540, created = false},
[{m_id = 513}] = {lsn = 9392084, created = false},
…
The test case that I used is as follows:
--source include/have_innodb.inc
--source include/have_sequence.inc
SET GLOBAL INNODB_FILE_PER_TABLE= 0;
CREATE TABLE t1(f1 INT NOT NULL , f2 INT NOT NULL ,
f3 INT NOT NULL , INDEX (f1),
INDEX (f2), INDEX (f3))ENGINE=InnoDB;
INSERT INTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
INSERT INTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
INSERT INTO t1 SELECT seq, seq, seq FROM seq_1_to_16384;
DROP TABLE t1;
SET GLOBAL innodb_max_purge_lag_wait=0;
let $shutdown_timeout=0;
--source include/restart_mysqld.inc
This would seem to fail reliably when not using rr . I produced my rr trace as follows:
while . /mtr --rr=-h --parallel=auto name_of_test{,,,,,,,,,,,,,,,,}; do :; done
This was with the test case but not the code change of of my 10.5 fix.
Marko Mäkelä
added a comment - I was able to reproduce this on 10.5 as well:
10.5 cb1965bd9d840665b2ea52216985d88c39a8a9f9
mariadbd: /mariadb/10.5/storage/innobase/log/log0recv.cc:273: 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.
mariadbd: /mariadb/10.5/storage/innobase/log/log0recv.cc:273: 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.
This was with the test case but not the code change of of my 10.5 fix .
People
Marko Mäkelä
Sergei Golubchik
Votes:
0Vote for this issue
Watchers:
4Start watching this issue
Dates
Created:
Updated:
Resolved:
Git Integration
Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.
{"report":{"fcp":1091.1999999284744,"ttfb":232.10000002384186,"pageVisibility":"visible","entityId":125039,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"e252de52-9a32-48e5-a61a-c9e7387780c5","navigationType":0,"readyForUser":1164.6000000238419,"redirectCount":0,"resourceLoadedEnd":816.5,"resourceLoadedStart":237.69999992847443,"resourceTiming":[{"duration":30.600000023841858,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":237.69999992847443,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":237.69999992847443,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":268.2999999523163,"responseStart":0,"secureConnectionStart":0},{"duration":31.199999928474426,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":238,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":238,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":269.1999999284744,"responseStart":0,"secureConnectionStart":0},{"duration":328,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":238.19999992847443,"connectEnd":238.19999992847443,"connectStart":238.19999992847443,"domainLookupEnd":238.19999992847443,"domainLookupStart":238.19999992847443,"fetchStart":238.19999992847443,"redirectEnd":0,"redirectStart":0,"requestStart":273.2999999523163,"responseEnd":566.1999999284744,"responseStart":301.5,"secureConnectionStart":238.19999992847443},{"duration":550.1000000238419,"initiatorType":"script","name":"https://jira.mariadb.org/s/099b33461394b8015fc36c0a4b96e19f-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":238.29999995231628,"connectEnd":238.29999995231628,"connectStart":238.29999995231628,"domainLookupEnd":238.29999995231628,"domainLookupStart":238.29999995231628,"fetchStart":238.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":279.39999997615814,"responseEnd":788.3999999761581,"responseStart":317.6999999284744,"secureConnectionStart":238.29999995231628},{"duration":74.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/94c15bff32baef80f4096a08aceae8bc-CDN/lu2bu7/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":238.5,"connectEnd":238.5,"connectStart":238.5,"domainLookupEnd":238.5,"domainLookupStart":238.5,"fetchStart":238.5,"redirectEnd":0,"redirectStart":0,"requestStart":280.1999999284744,"responseEnd":313,"responseStart":307.5,"secureConnectionStart":238.5},{"duration":74.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":238.60000002384186,"connectEnd":238.60000002384186,"connectStart":238.60000002384186,"domainLookupEnd":238.60000002384186,"domainLookupStart":238.60000002384186,"fetchStart":238.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":280.2999999523163,"responseEnd":313.1999999284744,"responseStart":308.7999999523163,"secureConnectionStart":238.60000002384186},{"duration":74.60000002384186,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":238.79999995231628,"connectEnd":238.79999995231628,"connectStart":238.79999995231628,"domainLookupEnd":238.79999995231628,"domainLookupStart":238.79999995231628,"fetchStart":238.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":280.60000002384186,"responseEnd":313.39999997615814,"responseStart":311,"secureConnectionStart":238.79999995231628},{"duration":35.700000047683716,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2bu7/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":238.89999997615814,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":238.89999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":274.60000002384186,"responseStart":0,"secureConnectionStart":0},{"duration":74.5,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":239,"connectEnd":239,"connectStart":239,"domainLookupEnd":239,"domainLookupStart":239,"fetchStart":239,"redirectEnd":0,"redirectStart":0,"requestStart":280.7999999523163,"responseEnd":313.5,"responseStart":311.60000002384186,"secureConnectionStart":239},{"duration":37.799999952316284,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2bu7/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":239.10000002384186,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":239.10000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":276.89999997615814,"responseStart":0,"secureConnectionStart":0},{"duration":75.80000007152557,"initiatorType":"script","name":"https://jira.mariadb.org/s/3339d87fa2538a859872f2df449bf8d0-CDN/lu2bu7/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":239.19999992847443,"connectEnd":239.19999992847443,"connectStart":239.19999992847443,"domainLookupEnd":239.19999992847443,"domainLookupStart":239.19999992847443,"fetchStart":239.19999992847443,"redirectEnd":0,"redirectStart":0,"requestStart":282,"responseEnd":315,"responseStart":313.6999999284744,"secureConnectionStart":239.19999992847443},{"duration":569.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":246,"connectEnd":246,"connectStart":246,"domainLookupEnd":246,"domainLookupStart":246,"fetchStart":246,"redirectEnd":0,"redirectStart":0,"requestStart":294.5,"responseEnd":815.2999999523163,"responseStart":804.2999999523163,"secureConnectionStart":246},{"duration":570.3000000715256,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":246.19999992847443,"connectEnd":246.19999992847443,"connectStart":246.19999992847443,"domainLookupEnd":246.19999992847443,"domainLookupStart":246.19999992847443,"fetchStart":246.19999992847443,"redirectEnd":0,"redirectStart":0,"requestStart":302.5,"responseEnd":816.5,"responseStart":807,"secureConnectionStart":246.19999992847443},{"duration":258.7999999523163,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":720.1000000238419,"connectEnd":720.1000000238419,"connectStart":720.1000000238419,"domainLookupEnd":720.1000000238419,"domainLookupStart":720.1000000238419,"fetchStart":720.1000000238419,"redirectEnd":0,"redirectStart":0,"requestStart":911.1000000238419,"responseEnd":978.8999999761581,"responseStart":947.1000000238419,"secureConnectionStart":720.1000000238419}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":31,"responseStart":232,"responseEnd":239,"domLoading":236,"domInteractive":1240,"domContentLoadedEventStart":1240,"domContentLoadedEventEnd":1305,"domComplete":2371,"loadEventStart":2371,"loadEventEnd":2372,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1200.3999999761581},{"name":"bigPipe.sidebar-id.end","time":1201.1999999284744},{"name":"bigPipe.activity-panel-pipe-id.start","time":1201.2999999523163},{"name":"bigPipe.activity-panel-pipe-id.end","time":1204.8999999761581},{"name":"activityTabFullyLoaded","time":1321.1999999284744}],"measures":[],"correlationId":"5b82899246b29b","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":131,"dbReadsTimeInMs":14,"dbConnsTimeInMs":24,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Critical
MDEV-28699 Shrink temporary tablespaces without restart
Using the mtr test case that thiru provided, I was able to produce an rr replay trace of this. I got an OPT_PAGE_CHECKSUM failure (
MDEV-18976); these records are something that is being written in debug builds. The failure occurred for the following OPT_PAGE_CHECKSUM record:10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
(rr) p *this$2 = {<log_rec_t> = {next = 0x7f1871570dc8, lsn = 8448794}, start_lsn = 8448769}In that page, we had FIL_PAGE_LSN of 6281382, which is too old. The recovery had started like this:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
2023-09-14 11:08:03 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8415203,93988152023-09-14 11:08:03 0 [Note] InnoDB: To recover: 260 pages2023-09-14 11:08:04 0 [ERROR] InnoDB: OPT_PAGE_CHECKSUM mismatch on [page id: space=0, page number=494]I found the corresponding mini-transaction in the rr replay trace of the server that was intentionally killed by the test. The page was being marked as freed by the following:
10.6 0f9acce3f2fd8d8f6334e10b08f9b5a031d40fdf
#3 0x00005598517b44a2 in buf_page_free (space=space@entry=0x5598545749f8, page=page@entry=494, mtr=mtr@entry=0x7e813d744a70) at /mariadb/10.6m/storage/innobase/buf/buf0buf.cc:2157#4 0x00005598517eb685 in fseg_free_extent (seg_inode=seg_inode@entry=0x19806e8cf872 "", iblock=0x19806e4535f0, space=space@entry=0x5598545749f8, page=448, mtr=mtr@entry=0x7e813d744a70, ahi=ahi@entry=false)at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2767#5 0x00005598517ed72c in fseg_free_step (header=0x19806e90c04a "", mtr=mtr@entry=0x7e813d744a70, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/fsp/fsp0fsp.cc:2831#6 0x00005598517f450c in btr_free_but_not_root (block=block@entry=0x19806e4542f0, log_mode=MTR_LOG_ALL, ahi=ahi@entry=false) at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1142#7 0x00005598517f6fb2 in btr_free_if_exists (space=space@entry=0x5598545749f8, page=page@entry=313, index_id=<optimized out>, mtr=mtr@entry=0x7e813d745150)at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:1229#8 0x0000559851870d44 in dict_drop_index_tree (pcur=pcur@entry=0x5598545d15e0, trx=trx@entry=0x0, mtr=mtr@entry=0x7e813d745150) at /mariadb/10.6m/storage/innobase/dict/dict0crea.cc:905#9 0x000055985198a455 in row_purge_remove_clust_if_poss_low (node=node@entry=0x5598545d1540, mode=mode@entry=BTR_MODIFY_LEAF) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:166#10 0x000055985198aea9 in row_purge_remove_clust_if_poss (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:259#11 0x000055985198b043 in row_purge_del_mark (node=node@entry=0x5598545d1540) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:635#12 0x000055985198b799 in row_purge_record_func (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0, updated_extern=false)at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1215#13 0x000055985198b90e in row_purge (node=node@entry=0x5598545d1540, undo_rec=undo_rec@entry=0x5c8478084070 "", thr=thr@entry=0x5598545d14a0) at /mariadb/10.6m/storage/innobase/row/row0purge.cc:1276This is the purge of delete-marking a SYS_INDEXES record corresponding to DROP TABLE t1 in the system tablespace.
This mini-transaction (at LSN=9388592) failed to write any FREE_PAGE record. At mtr_t::commit(), m_memo would comprise 69 latches, and 80 bytes of log would have been written: WRITE, MEMSET and MEMMOVE records and two OPT_PAGE_CHECKSUM for other pages than this freed page.
The oldest_modification of the page was 8407829 (which is before the recovery checkpoint LSN) at the time when it was cleared by the page cleaner.
I think that the problem is that there was no FREE_PAGE record written for this page 494 (0x1ee). We do have it for some neighbours, in mlog_init at the time the recovery catches the error:
…[{m_id = 446}] = {lsn = 9388941, created = false},[{m_id = 447}] = {lsn = 9388900, created = false},[{m_id = 512}] = {lsn = 9390540, created = false},[{m_id = 513}] = {lsn = 9392084, created = false},…The test case that I used is as follows:
--source include/have_innodb.inc--source include/have_sequence.inclet $shutdown_timeout=0;This would seem to fail reliably when not using rr. I produced my rr trace as follows: