InnoDB shutdown is effectively waiting for the rollback of recovered transactions to finish, even though the intention seems to be to only do this when a slow shutdown (innodb_fast_shutdown=0) has been requested:
ib_logf(IB_LOG_LEVEL_INFO, "Starting shutdown...");
while (srv_fast_shutdown == 0 && trx_rollback_or_clean_is_active) {
/* we should wait until rollback after recovery end
for slow shutdown */
os_thread_sleep(100000);
}
Below is the output from XtraDB shutdown with innodb_fast_shutdown=2. It shows that we are indirectly waiting for the rollback somewhere later in logs_empty_and_mark_files_at_shutdown().
170209 10:58:21 [Note] InnoDB: Starting shutdown...
4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100170209 10:58:31 [Note] InnoDB: Rollback of trx with id 1286 completed
2017-02-09 10:58:31 7fb4fed13700 InnoDB: Rollback of non-prepared transactions completed
170209 10:58:32 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
170209 10:58:32 [Note] InnoDB: MySQL has requested a very fast shutdown without flushing the InnoDB buffer pool to data files. At the next mysqld startup InnoDB will do a crash recovery!
The above is also showing a message about page_cleaner that conflicts with the last message.
The output was obtained by running the following test:
--source include/have_innodb.inc
# Embedded server tests do not support restarting
--source include/not_embedded.inc
CREATE TABLE t1(
a INT PRIMARY KEY,
b CHAR(255) NOT NULL DEFAULT '',
c CHAR(255) NOT NULL DEFAULT ''
) ENGINE=InnoDB STATS_PERSISTENT=1;
BEGIN;
INSERT INTO t1 (a) VALUES (1),(2),(3),(4),(5),(6),(7),(8);
INSERT INTO t1 (a) SELECT a+8 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+16 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+32 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+64 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+128 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+256 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+512 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+1024 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+2048 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+4096 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+8192 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+16384 FROM t1 WHERE a>0;
INSERT INTO t1 (a) SELECT a+32768 FROM t1 WHERE a>0;
--echo # Persist the state of the above incomplete transaction by
--echo # causing a redo log write for another transaction.
--connect(con1, localhost, root)
SET GLOBAL innodb_flush_log_at_trx_commit=1;
ANALYZE TABLE t1;
--disconnect con1
--connection default
--let $restart_parameters= --innodb-fast-shutdown=2
--source include/kill_and_restart_mysqld.inc
-- echo # Request very fast shutdown (should be without rollback).
-- echo # Disable the rollback of recovered transactions on startup.
--let $restart_parameters= --innodb-force-recovery=3
--source include/restart_mysqld.inc
--echo # There table should not be empty.
--echo # Currently it may be, because the shutdown waited for the rollback!
--echo # (It can be nonempty if the rollback was not persisted.)
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SELECT COUNT(*)>0 `Expected 1` FROM t1;
--let $restart_parameters=
--source include/restart_mysqld.inc
SELECT * FROM t1;
DROP TABLE t1;
I repeated the problem on the latest development versions of 10.0.30, 10.1.22, 10.2.4.
duplicates
MDEV-12091
Shutdown fails to wait for rollback of recovered transactions to finish
Closed
Marko Mäkelä
made changes -
2017-03-14 14:30
Fix Version/s
10.0.31
[ 22501
]
Fix Version/s
10.1.23
[ 22503
]
Fix Version/s
10.2.5
[ 22117
]
Resolution
Fixed
[ 1
]
Status
Open
[ 1
]
Closed
[ 6
]
Sergei Golubchik
made changes -
2021-12-06 21:44
Workflow
MariaDB v3
[ 79579
]
MariaDB v4
[ 151690
]
{"report":{"fcp":1084.2999997138977,"ttfb":336.59999990463257,"pageVisibility":"visible","entityId":60176,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"17a8eecf-2563-48ae-afaa-06c93db252fe","navigationType":0,"readyForUser":1185.3999996185303,"redirectCount":0,"resourceLoadedEnd":1222.3999996185303,"resourceLoadedStart":343.8999996185303,"resourceTiming":[{"duration":177.80000019073486,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":343.8999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":343.8999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":521.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":178,"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":344.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":344.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":522.0999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":233.60000038146973,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":344.3999996185303,"connectEnd":344.3999996185303,"connectStart":344.3999996185303,"domainLookupEnd":344.3999996185303,"domainLookupStart":344.3999996185303,"fetchStart":344.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":344.3999996185303,"responseEnd":578,"responseStart":578,"secureConnectionStart":344.3999996185303},{"duration":380,"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":344.59999990463257,"connectEnd":344.59999990463257,"connectStart":344.59999990463257,"domainLookupEnd":344.59999990463257,"domainLookupStart":344.59999990463257,"fetchStart":344.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":344.59999990463257,"responseEnd":724.5999999046326,"responseStart":724.5999999046326,"secureConnectionStart":344.59999990463257},{"duration":383.80000019073486,"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":344.7999997138977,"connectEnd":344.7999997138977,"connectStart":344.7999997138977,"domainLookupEnd":344.7999997138977,"domainLookupStart":344.7999997138977,"fetchStart":344.7999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":344.7999997138977,"responseEnd":728.5999999046326,"responseStart":728.5999999046326,"secureConnectionStart":344.7999997138977},{"duration":384.19999980926514,"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":345,"connectEnd":345,"connectStart":345,"domainLookupEnd":345,"domainLookupStart":345,"fetchStart":345,"redirectEnd":0,"redirectStart":0,"requestStart":345,"responseEnd":729.1999998092651,"responseStart":729.1999998092651,"secureConnectionStart":345},{"duration":384.90000009536743,"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":345.09999990463257,"connectEnd":345.09999990463257,"connectStart":345.09999990463257,"domainLookupEnd":345.09999990463257,"domainLookupStart":345.09999990463257,"fetchStart":345.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":345.09999990463257,"responseEnd":730,"responseStart":730,"secureConnectionStart":345.09999990463257},{"duration":387.40000009536743,"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":345.2999997138977,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":345.2999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":732.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":389,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":345.3999996185303,"connectEnd":345.3999996185303,"connectStart":345.3999996185303,"domainLookupEnd":345.3999996185303,"domainLookupStart":345.3999996185303,"fetchStart":345.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":345.3999996185303,"responseEnd":734.3999996185303,"responseStart":734.3999996185303,"secureConnectionStart":345.3999996185303},{"duration":391.09999990463257,"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":345.59999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":345.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":736.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":389.59999990463257,"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":345.69999980926514,"connectEnd":345.69999980926514,"connectStart":345.69999980926514,"domainLookupEnd":345.69999980926514,"domainLookupStart":345.69999980926514,"fetchStart":345.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":345.69999980926514,"responseEnd":735.2999997138977,"responseStart":735.2999997138977,"secureConnectionStart":345.69999980926514},{"duration":636.2999997138977,"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":346.59999990463257,"connectEnd":346.59999990463257,"connectStart":346.59999990463257,"domainLookupEnd":346.59999990463257,"domainLookupStart":346.59999990463257,"fetchStart":346.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":346.59999990463257,"responseEnd":982.8999996185303,"responseStart":982.8999996185303,"secureConnectionStart":346.59999990463257},{"duration":776.5,"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":359.7999997138977,"connectEnd":359.7999997138977,"connectStart":359.7999997138977,"domainLookupEnd":359.7999997138977,"domainLookupStart":359.7999997138977,"fetchStart":359.7999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":359.7999997138977,"responseEnd":1136.2999997138977,"responseStart":1136.2999997138977,"secureConnectionStart":359.7999997138977},{"duration":238.90000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":744.5999999046326,"connectEnd":744.5999999046326,"connectStart":744.5999999046326,"domainLookupEnd":744.5999999046326,"domainLookupStart":744.5999999046326,"fetchStart":744.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":744.5999999046326,"responseEnd":983.5,"responseStart":983.5,"secureConnectionStart":744.5999999046326},{"duration":191.89999961853027,"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":1030.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1030.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1222.3999996185303,"responseStart":0,"secureConnectionStart":0},{"duration":181,"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":1032.0999999046326,"connectEnd":1032.0999999046326,"connectStart":1032.0999999046326,"domainLookupEnd":1032.0999999046326,"domainLookupStart":1032.0999999046326,"fetchStart":1032.0999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1032.0999999046326,"responseEnd":1213.0999999046326,"responseStart":1213.0999999046326,"secureConnectionStart":1032.0999999046326},{"duration":186.90000009536743,"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":1032.5999999046326,"connectEnd":1032.5999999046326,"connectStart":1032.5999999046326,"domainLookupEnd":1032.5999999046326,"domainLookupStart":1032.5999999046326,"fetchStart":1032.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":1032.5999999046326,"responseEnd":1219.5,"responseStart":1219.5,"secureConnectionStart":1032.5999999046326},{"duration":212.5,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1074.8999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1074.8999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1287.3999996185303,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":157,"responseStart":337,"responseEnd":343,"domLoading":342,"domInteractive":1315,"domContentLoadedEventStart":1315,"domContentLoadedEventEnd":1374,"domComplete":1563,"loadEventStart":1563,"loadEventEnd":1564,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1289.7999997138977},{"name":"bigPipe.sidebar-id.end","time":1290.8999996185303},{"name":"bigPipe.activity-panel-pipe-id.start","time":1291.0999999046326},{"name":"bigPipe.activity-panel-pipe-id.end","time":1293.8999996185303},{"name":"activityTabFullyLoaded","time":1396.5}],"measures":[],"correlationId":"fe94122cf7b4be","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":111,"dbReadsTimeInMs":16,"dbConnsTimeInMs":26,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
This was fixed as part of
MDEV-12091. A normal shutdown will complete the rollback of the current being-rolled-back-transaction. If there are multiple recovered transactions, we would no longer advance to the next transaction to be rolled back if shutdown was initiated.The crash-like shutdown (innodb_fast_shutdown=2) will not wait for a current background rollback to finish, but the normal and slow shutdown will wait for the completion.