Workflow of RQG test
|
|
1. Create DB server and start it
|
2. One session starts to run some SQL stream against this server
|
3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM).
|
4. Make some copy of the data content+logs etc. of the killed server.
|
5. Try to restart the killed server.
|
|
5. fails with
|
2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ...
|
...
|
2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931
|
2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore.
|
2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record:
|
<some data>
|
2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error
|
...
|
2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
|
|
RQG
|
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1
|
origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00
|
|
MariaDB
|
origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00
|
build with debug
|
|
perl rqg.pl \
|
--duration=120 \
|
--queries=10000000 \
|
--threads=1 \
|
--no_mask \
|
--seed=random \
|
--gendata=conf/engines/many_indexes.zz \
|
--rpl_mode=none \
|
--engine=InnoDB \
|
--mysqld=--innodb_stats_persistent=off \
|
--mysqld=--lock-wait-timeout=86400 \
|
--mysqld=--log-output=none \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
|
--mysqld=--log_bin_trust_function_creators=1 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--innodb_page_size=32K \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--loose_innodb_use_native_aio=1 \
|
--mysqld=--log-bin \
|
--mysqld=--net_read_timeout=30 \
|
--reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \
|
--validators=None \
|
--grammar=c00000.yy \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<path to MariaDB binaries> \
|
--script_debug=_nix
|
There might be several replay attempts required.
|
- is caused by
-
MDEV-12353
Efficient InnoDB redo log record format
-
-
Closed
{"report":{"fcp":1175.8000001907349,"ttfb":428.80000019073486,"pageVisibility":"visible","entityId":84946,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"1ec9df31-3b14-49cc-95b3-dcb3af10e2dd","navigationType":0,"readyForUser":1327.8000001907349,"redirectCount":0,"resourceLoadedEnd":1361.8000001907349,"resourceLoadedStart":437.69999980926514,"resourceTiming":[{"duration":219.40000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":437.69999980926514,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":437.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":657.0999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":221.59999990463257,"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":438,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":438,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":659.5999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":275.90000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":438.19999980926514,"connectEnd":438.19999980926514,"connectStart":438.19999980926514,"domainLookupEnd":438.19999980926514,"domainLookupStart":438.19999980926514,"fetchStart":438.19999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":438.19999980926514,"responseEnd":714.0999999046326,"responseStart":714.0999999046326,"secureConnectionStart":438.19999980926514},{"duration":349.8999996185303,"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":438.80000019073486,"connectEnd":438.80000019073486,"connectStart":438.80000019073486,"domainLookupEnd":438.80000019073486,"domainLookupStart":438.80000019073486,"fetchStart":438.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":438.80000019073486,"responseEnd":788.6999998092651,"responseStart":788.6999998092651,"secureConnectionStart":438.80000019073486},{"duration":353.40000009536743,"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":439,"connectEnd":439,"connectStart":439,"domainLookupEnd":439,"domainLookupStart":439,"fetchStart":439,"redirectEnd":0,"redirectStart":0,"requestStart":439,"responseEnd":792.4000000953674,"responseStart":792.4000000953674,"secureConnectionStart":439},{"duration":353.7000002861023,"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":439.09999990463257,"connectEnd":439.09999990463257,"connectStart":439.09999990463257,"domainLookupEnd":439.09999990463257,"domainLookupStart":439.09999990463257,"fetchStart":439.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":439.09999990463257,"responseEnd":792.8000001907349,"responseStart":792.8000001907349,"secureConnectionStart":439.09999990463257},{"duration":353.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":439.30000019073486,"connectEnd":439.30000019073486,"connectStart":439.30000019073486,"domainLookupEnd":439.30000019073486,"domainLookupStart":439.30000019073486,"fetchStart":439.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":439.30000019073486,"responseEnd":793.1999998092651,"responseStart":793.1999998092651,"secureConnectionStart":439.30000019073486},{"duration":417.2999997138977,"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":439.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":439.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":856.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":354,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":439.59999990463257,"connectEnd":439.59999990463257,"connectStart":439.59999990463257,"domainLookupEnd":439.59999990463257,"domainLookupStart":439.59999990463257,"fetchStart":439.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":439.59999990463257,"responseEnd":793.5999999046326,"responseStart":793.5999999046326,"secureConnectionStart":439.59999990463257},{"duration":417.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":439.80000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":439.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":856.9000000953674,"responseStart":0,"secureConnectionStart":0},{"duration":354.19999980926514,"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":440,"connectEnd":440,"connectStart":440,"domainLookupEnd":440,"domainLookupStart":440,"fetchStart":440,"redirectEnd":0,"redirectStart":0,"requestStart":440,"responseEnd":794.1999998092651,"responseStart":794.1999998092651,"secureConnectionStart":440},{"duration":683.3999996185303,"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":448.80000019073486,"connectEnd":448.80000019073486,"connectStart":448.80000019073486,"domainLookupEnd":448.80000019073486,"domainLookupStart":448.80000019073486,"fetchStart":448.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":448.80000019073486,"responseEnd":1132.1999998092651,"responseStart":1132.1999998092651,"secureConnectionStart":448.80000019073486},{"duration":743.0999999046326,"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":454.09999990463257,"connectEnd":454.09999990463257,"connectStart":454.09999990463257,"domainLookupEnd":454.09999990463257,"domainLookupStart":454.09999990463257,"fetchStart":454.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":454.09999990463257,"responseEnd":1197.1999998092651,"responseStart":1197.1999998092651,"secureConnectionStart":454.09999990463257},{"duration":264.2999997138977,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":868.3000001907349,"connectEnd":868.3000001907349,"connectStart":868.3000001907349,"domainLookupEnd":868.3000001907349,"domainLookupStart":868.3000001907349,"fetchStart":868.3000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":868.3000001907349,"responseEnd":1132.5999999046326,"responseStart":1132.5999999046326,"secureConnectionStart":868.3000001907349},{"duration":203.30000019073486,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1166.1999998092651,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1166.1999998092651,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1369.5,"responseStart":0,"secureConnectionStart":0},{"duration":155.90000009536743,"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":1205.9000000953674,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1205.9000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1361.8000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":74.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":1206.8000001907349,"connectEnd":1206.8000001907349,"connectStart":1206.8000001907349,"domainLookupEnd":1206.8000001907349,"domainLookupStart":1206.8000001907349,"fetchStart":1206.8000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":1206.8000001907349,"responseEnd":1281.3000001907349,"responseStart":1281.3000001907349,"secureConnectionStart":1206.8000001907349},{"duration":90.40000009536743,"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":1207.4000000953674,"connectEnd":1207.4000000953674,"connectStart":1207.4000000953674,"domainLookupEnd":1207.4000000953674,"domainLookupStart":1207.4000000953674,"fetchStart":1207.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":1207.4000000953674,"responseEnd":1297.8000001907349,"responseStart":1297.8000001907349,"secureConnectionStart":1207.4000000953674}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":252,"responseStart":429,"responseEnd":454,"domLoading":432,"domInteractive":1418,"domContentLoadedEventStart":1418,"domContentLoadedEventEnd":1464,"domComplete":1673,"loadEventStart":1673,"loadEventEnd":1673,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1378.0999999046326},{"name":"bigPipe.sidebar-id.end","time":1378.8000001907349},{"name":"bigPipe.activity-panel-pipe-id.start","time":1379},{"name":"bigPipe.activity-panel-pipe-id.end","time":1381},{"name":"activityTabFullyLoaded","time":1482.1999998092651}],"measures":[],"correlationId":"1a30ca7a58e060","effectiveType":"4g","downlink":9.4,"rtt":0,"serverDuration":107,"dbReadsTimeInMs":16,"dbConnsTimeInMs":26,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Does the following patch fix it?
diff --git a/storage/innobase/include/mtr0log.h b/storage/innobase/include/mtr0log.h
index d07fa069dfd..ee823caf6cb 100644
--- a/storage/innobase/include/mtr0log.h
+++ b/storage/innobase/include/mtr0log.h
@@ -427,7 +427,7 @@ inline byte *mtr_t::log_write(const page_id_t id, const buf_page_t *bpage,
if (oend + len > &log_ptr[16])
{
len+= oend - log_ptr - 15;
- if (len >= MIN_3BYTE)
+ if (len >= MIN_3BYTE - 1)
len+= 2;
else if (len >= MIN_2BYTE)
len++;
@@ -448,7 +448,7 @@ inline byte *mtr_t::log_write(const page_id_t id, const buf_page_t *bpage,
else if (len >= 3 && end + len > &log_ptr[16])
{
len+= end - log_ptr - 15;
- if (len >= MIN_3BYTE)
+ if (len >= MIN_3BYTE - 1)
len+= 2;
else if (len >= MIN_2BYTE)
The record with the unfortunate value len == MIN_3BYTE - 1 was written by btr_page_reorganize_low().
This bug is only possible with innodb_page_size=32k or innodb_page_size=64k. For smaller page sizes, we can never have that long redo log records, because for the length of a single record we have the constraint that log_phys_t::alloc_size(length) must not exceed innodb_page_size.