Type:
Bug
Priority:
Major
Resolution:
Fixed
Affects Version/s:
10.5 , 10.6 , 10.7(EOL) , 10.8(EOL) , 10.9(EOL) , 10.10(EOL) , 10.11 , 11.0(EOL)
The test mariabackup.innodb_force_recovery occasionally failed in a 10.6 based development branch that contains a fix of MDEV-26827 and MDEV-26055 . We have some rather rare failures of the test occurring on buildbot as well, like this:
10.10 4ce6e78059c1a91765c91afa5330737bd7568d0a
mariabackup.innodb_force_recovery 'innodb' w13 [ fail ] timeout after 480 seconds
Test ended at 2022-07-28 12:27:20
Test case timeout after 480 seconds
== /buildbot/amd64-ubuntu-2004-msan/build/mysql-test/var/13/log/innodb_force_recovery.log ==
CREATE TABLE t(i INT) ENGINE INNODB;
INSERT INTO t VALUES(1);
# "innodb_force_recovery=1" should be allowed with "--prepare" only (mariabackup)
FOUND 1 /should only be used with "--prepare"/ in backup.log
# "innodb_force_recovery=1" should be allowed with "--apply-log" only (innobackupex)
FOUND 1 /should only be used with "--apply-log"/ in backup.log
# "innodb_force_recovery" should be limited to "SRV_FORCE_IGNORE_CORRUPT" (mariabackup)
FOUND 1 /innodb_force_recovery = 1/ in backup.log
# "innodb_force_recovery" should be limited to "SRV_FORCE_IGNORE_CORRUPT" (innobackupex)
FOUND 1 /innodb_force_recovery = 1/ in backup.log
# "innodb_force_recovery" should be read from "backup-my.cnf" (mariabackup)
FOUND 1 /innodb_force_recovery = 1/ in backup.log
# "innodb_force_recovery=1" should be read from "backup-my.cnf" (innobackupex)
FOUND 1 /innodb_force_recovery = 1/ in backup.log
# "innodb_force_recovery" from the command line should override "backup-my.cnf" (mariabackup)
NOT FOUND /innodb_force_recovery = 1/ in backup.log
# "innodb_force_recovery" from the command line should override "backup-my.cnf" (innobackupex)
NOT FOUND /innodb_force_recovery = 1/ in backup.log
# shutdown server
== /buildbot/amd64-ubuntu-2004-msan/build/mysql-test/var/13/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local server through socket '/buildbot/amd64-ubuntu-2004-msan/build/mysql-test/var/tmp/13/mys' (2)
This fix worked in the case that I was able to reproduce:
diff --git a/storage/innobase/srv/srv0start.cc b/storage/innobase/srv/srv0start.cc
index 5bf085079c8..4a01326047a 100644
--- a/storage/innobase/srv/srv0start.cc
+++ b/storage/innobase/srv/srv0start.cc
@@ -905,9 +905,7 @@ static lsn_t srv_prepare_to_delete_redo_log_file(bool old_exists)
{
DBUG_ENTER("srv_prepare_to_delete_redo_log_file");
- /* Disable checkpoints in the page cleaner. */
- ut_ad(!recv_sys.recovery_on);
- recv_sys.recovery_on= true;
+ ut_ad(recv_sys.recovery_on);
/* Clean the buffer pool. */
buf_flush_sync();
@@ -1589,10 +1587,10 @@ dberr_t srv_start(bool create_new_db)
}
}
- recv_sys.debug_free();
-
if (srv_operation == SRV_OPERATION_RESTORE
|| srv_operation == SRV_OPERATION_RESTORE_EXPORT) {
+ buf_flush_sync();
+ recv_sys.debug_free();
/* After applying the redo log from
SRV_OPERATION_BACKUP, flush the changes
to the data files and truncate or delete the log.
@@ -1684,6 +1682,8 @@ dberr_t srv_start(bool create_new_db)
return(srv_init_abort(err));
}
}
+
+ recv_sys.debug_free();
}
ut_ad(err == DB_SUCCESS);
The failure that I observed was caused by the fact that buf_flush_page_cleaner() took a little longer to write out the recovered modified pages, and this thread had already executed recv_sys.debug_free() , which causes the page cleaner to attempt to write checkpoint information. The failures that I observed were caused by the fact that this thread had already closed and deleted the ib_logfile0 when buf_flush_page_cleaner() unexpectedly invoked log_checkpoint_low() .
This type of failure should be caused by MDEV-23855 , which made log checkpoints the responsibility of the page cleaner thread.
Because I have no stack traces of the test case timeouts, I am unable say if the above patch would fix them.
is caused by
MDEV-23855
InnoDB log checkpointing causes regression for write-heavy OLTP
Closed
{"report":{"fcp":1172.8999996185303,"ttfb":338.5,"pageVisibility":"visible","entityId":120174,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"5a64c487-1af4-4f17-9486-6cbb688f6fcd","navigationType":0,"readyForUser":1262.5999999046326,"redirectCount":0,"resourceLoadedEnd":1303,"resourceLoadedStart":346.8999996185303,"resourceTiming":[{"duration":265.6000003814697,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":346.8999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":346.8999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":612.5,"responseStart":0,"secureConnectionStart":0},{"duration":265.69999980926514,"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":347.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":347.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":612.7999997138977,"responseStart":0,"secureConnectionStart":0},{"duration":274.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":347.2999997138977,"connectEnd":347.2999997138977,"connectStart":347.2999997138977,"domainLookupEnd":347.2999997138977,"domainLookupStart":347.2999997138977,"fetchStart":347.2999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":347.2999997138977,"responseEnd":622.0999999046326,"responseStart":622.0999999046326,"secureConnectionStart":347.2999997138977},{"duration":335.2000002861023,"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":347.3999996185303,"connectEnd":347.3999996185303,"connectStart":347.3999996185303,"domainLookupEnd":347.3999996185303,"domainLookupStart":347.3999996185303,"fetchStart":347.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":347.3999996185303,"responseEnd":682.5999999046326,"responseStart":682.5999999046326,"secureConnectionStart":347.3999996185303},{"duration":339.59999990463257,"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":347.59999990463257,"connectEnd":347.59999990463257,"connectStart":347.59999990463257,"domainLookupEnd":347.59999990463257,"domainLookupStart":347.59999990463257,"fetchStart":347.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":347.59999990463257,"responseEnd":687.1999998092651,"responseStart":687.1999998092651,"secureConnectionStart":347.59999990463257},{"duration":340.2000002861023,"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":347.7999997138977,"connectEnd":347.7999997138977,"connectStart":347.7999997138977,"domainLookupEnd":347.7999997138977,"domainLookupStart":347.7999997138977,"fetchStart":347.7999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":347.7999997138977,"responseEnd":688,"responseStart":688,"secureConnectionStart":347.7999997138977},{"duration":340.8999996185303,"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":348,"connectEnd":348,"connectStart":348,"domainLookupEnd":348,"domainLookupStart":348,"fetchStart":348,"redirectEnd":0,"redirectStart":0,"requestStart":348,"responseEnd":688.8999996185303,"responseStart":688.8999996185303,"secureConnectionStart":348},{"duration":420.59999990463257,"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":348.19999980926514,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":348.19999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":768.7999997138977,"responseStart":0,"secureConnectionStart":0},{"duration":341.7000002861023,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":348.3999996185303,"connectEnd":348.3999996185303,"connectStart":348.3999996185303,"domainLookupEnd":348.3999996185303,"domainLookupStart":348.3999996185303,"fetchStart":348.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":348.3999996185303,"responseEnd":690.0999999046326,"responseStart":690.0999999046326,"secureConnectionStart":348.3999996185303},{"duration":420.3999996185303,"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":348.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":348.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":768.8999996185303,"responseStart":0,"secureConnectionStart":0},{"duration":342.30000019073486,"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":348.69999980926514,"connectEnd":348.69999980926514,"connectStart":348.69999980926514,"domainLookupEnd":348.69999980926514,"domainLookupStart":348.69999980926514,"fetchStart":348.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":348.69999980926514,"responseEnd":691,"responseStart":691,"secureConnectionStart":348.69999980926514},{"duration":529,"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":349.5,"connectEnd":349.5,"connectStart":349.5,"domainLookupEnd":349.5,"domainLookupStart":349.5,"fetchStart":349.5,"redirectEnd":0,"redirectStart":0,"requestStart":349.5,"responseEnd":878.5,"responseStart":878.5,"secureConnectionStart":349.5},{"duration":759.2999997138977,"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":349.5,"connectEnd":349.5,"connectStart":349.5,"domainLookupEnd":349.5,"domainLookupStart":349.5,"fetchStart":349.5,"redirectEnd":0,"redirectStart":0,"requestStart":349.5,"responseEnd":1108.7999997138977,"responseStart":1108.7999997138977,"secureConnectionStart":349.5},{"duration":98.40000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":780.5999999046326,"connectEnd":780.5999999046326,"connectStart":780.5999999046326,"domainLookupEnd":780.5999999046326,"domainLookupStart":780.5999999046326,"fetchStart":780.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":780.5999999046326,"responseEnd":879,"responseStart":879,"secureConnectionStart":780.5999999046326},{"duration":232,"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":1071,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1071,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1303,"responseStart":0,"secureConnectionStart":0},{"duration":302.7999997138977,"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":1072,"connectEnd":1072,"connectStart":1072,"domainLookupEnd":1072,"domainLookupStart":1072,"fetchStart":1072,"redirectEnd":0,"redirectStart":0,"requestStart":1072,"responseEnd":1374.7999997138977,"responseStart":1374.7999997138977,"secureConnectionStart":1072}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":172,"responseStart":339,"responseEnd":345,"domLoading":344,"domInteractive":1327,"domContentLoadedEventStart":1327,"domContentLoadedEventEnd":1370,"domComplete":2490,"loadEventStart":2490,"loadEventEnd":2492,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1306},{"name":"bigPipe.sidebar-id.end","time":1306.7999997138977},{"name":"bigPipe.activity-panel-pipe-id.start","time":1307},{"name":"bigPipe.activity-panel-pipe-id.end","time":1309.5},{"name":"activityTabFullyLoaded","time":1377.5}],"measures":[],"correlationId":"89c2b7d8e9ac87","effectiveType":"4g","downlink":9.9,"rtt":0,"serverDuration":99,"dbReadsTimeInMs":14,"dbConnsTimeInMs":23,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}