2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Completed initialization of buffer pool
|
2017-08-10 17:48:57 140404724037376 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Trx id counter is 7424
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Upgrading redo log: 2*50331648 bytes; LSN=9779797
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Starting to delete and rewrite log files.
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
|
2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
|
2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
|
2017-08-10 17:48:58 140405466861632 [Note] InnoDB: New log files created, LSN=9779797
|
2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2017-08-10 17:48:58 140405466861632 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Rolling back trx with id 6568, 1 rows to undo
|
2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
mysqld: /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918: void trx_commit_low(trx_t*, mtr_t*): Assertion `!mtr == !trx->has_logged()' failed.
|
170810 17:48:58 [ERROR] mysqld got signal 6 ;
|
|
10.3 73297f532fba89e33785460448e93f87478c2505
|
#3 0x00007f3ff87f7ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
|
#4 0x0000565165cfad75 in trx_commit_low (trx=0x7f3ff5406878, mtr=0x7f3fce337470) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918
|
#5 0x0000565165cfafcc in trx_commit (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:2018
|
#6 0x0000565165cee5c2 in trx_rollback_finish (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:1147
|
#7 0x0000565165cecf5b in trx_rollback_active (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:689
|
#8 0x0000565165ced427 in trx_rollback_resurrected (trx=0x7f3ff5406878, all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:773
|
#9 0x0000565165ced6d6 in trx_rollback_or_clean_recovered (all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:841
|
#10 0x0000565165ced889 in trx_rollback_or_clean_all_recovered (arg=0x0) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:881
|
#11 0x00007f3ffa73c494 in start_thread (arg=0x7f3fce338700) at pthread_create.c:333
|
#12 0x00007f3ff88b493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
|
The attached datadir was created as a part of MDEV-13269 workflow.
- 10.2 server (86f9b7714791) was started with --innodb-change-buffering=none --innodb-page-size=8K --innodb-compression-algorithm=zlib, otherwise defaults;
- a number of tables was created and concurrent DML was executed in 4 threads for about a minute;
- the server was SIGKILL-ed;
- the server was started again with the same options plus --innodb-force-recovery=3;
- the server was shut down normally.
Now, to reproduce the reported assertion failure, start 10.3 server on the provided datadir with --innodb-change-buffering=none --innodb-page-size=8K --innodb-compression-algorithm=zlib, the failure happens upon startup.
10.2 starts all right on this datadir.
Note: in the initial scenario, there was an intermediate step when the 10.3 server is started on the datadir with --innodb-read-only and then gets shut down normally. It starts all right, but the step does not change the outcome when the server is finally restarted in a normal mode, so it's omitted above.
{"report":{"fcp":939.2999999523163,"ttfb":238.20000004768372,"pageVisibility":"visible","entityId":62585,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"0e82ac5d-61c9-4a5f-8d8f-77d60f2d4bdd","navigationType":0,"readyForUser":1037.3999999761581,"redirectCount":0,"resourceLoadedEnd":761.7999999523163,"resourceLoadedStart":245.39999997615814,"resourceTiming":[{"duration":103.10000002384186,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":245.39999997615814,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":245.39999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":348.5,"responseStart":0,"secureConnectionStart":0},{"duration":103.29999995231628,"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":245.60000002384186,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":245.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":348.89999997615814,"responseStart":0,"secureConnectionStart":0},{"duration":150.60000002384186,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":245.79999995231628,"connectEnd":245.79999995231628,"connectStart":245.79999995231628,"domainLookupEnd":245.79999995231628,"domainLookupStart":245.79999995231628,"fetchStart":245.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":344.10000002384186,"responseEnd":396.39999997615814,"responseStart":360.89999997615814,"secureConnectionStart":245.79999995231628},{"duration":308.10000002384186,"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":246,"connectEnd":246,"connectStart":246,"domainLookupEnd":246,"domainLookupStart":246,"fetchStart":246,"redirectEnd":0,"redirectStart":0,"requestStart":354.2999999523163,"responseEnd":554.1000000238419,"responseStart":389.5,"secureConnectionStart":246},{"duration":146.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":246.20000004768372,"connectEnd":246.20000004768372,"connectStart":246.20000004768372,"domainLookupEnd":246.20000004768372,"domainLookupStart":246.20000004768372,"fetchStart":246.20000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":354.2999999523163,"responseEnd":392.7999999523163,"responseStart":391.7000000476837,"secureConnectionStart":246.20000004768372},{"duration":144.5,"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":246.39999997615814,"connectEnd":246.39999997615814,"connectStart":246.39999997615814,"domainLookupEnd":246.39999997615814,"domainLookupStart":246.39999997615814,"fetchStart":246.39999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":354.5,"responseEnd":390.89999997615814,"responseStart":390.2000000476837,"secureConnectionStart":246.39999997615814},{"duration":146.89999997615814,"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":246.60000002384186,"connectEnd":246.60000002384186,"connectStart":246.60000002384186,"domainLookupEnd":246.60000002384186,"domainLookupStart":246.60000002384186,"fetchStart":246.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":354.60000002384186,"responseEnd":393.5,"responseStart":393,"secureConnectionStart":246.60000002384186},{"duration":107.60000002384186,"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":246.79999995231628,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":246.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":354.39999997615814,"responseStart":0,"secureConnectionStart":0},{"duration":147.5,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":246.89999997615814,"connectEnd":246.89999997615814,"connectStart":246.89999997615814,"domainLookupEnd":246.89999997615814,"domainLookupStart":246.89999997615814,"fetchStart":246.89999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":354.60000002384186,"responseEnd":394.39999997615814,"responseStart":393.7000000476837,"secureConnectionStart":246.89999997615814},{"duration":107.5,"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":247.10000002384186,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":247.10000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":354.60000002384186,"responseStart":0,"secureConnectionStart":0},{"duration":156.19999992847443,"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":247.20000004768372,"connectEnd":247.20000004768372,"connectStart":247.20000004768372,"domainLookupEnd":247.20000004768372,"domainLookupStart":247.20000004768372,"fetchStart":247.20000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":354.7000000476837,"responseEnd":403.39999997615814,"responseStart":394.39999997615814,"secureConnectionStart":247.20000004768372},{"duration":444.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":260.5,"connectEnd":260.5,"connectStart":260.5,"domainLookupEnd":260.5,"domainLookupStart":260.5,"fetchStart":260.5,"redirectEnd":0,"redirectStart":0,"requestStart":464.10000002384186,"responseEnd":705.2999999523163,"responseStart":698.2000000476837,"secureConnectionStart":260.5},{"duration":492,"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":269.7999999523163,"connectEnd":269.7999999523163,"connectStart":269.7999999523163,"domainLookupEnd":269.7999999523163,"domainLookupStart":269.7999999523163,"fetchStart":269.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":747.5,"responseEnd":761.7999999523163,"responseStart":761.2000000476837,"secureConnectionStart":269.7999999523163},{"duration":256.60000002384186,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":580.8999999761581,"connectEnd":580.8999999761581,"connectStart":580.8999999761581,"domainLookupEnd":580.8999999761581,"domainLookupStart":580.8999999761581,"fetchStart":580.8999999761581,"redirectEnd":0,"redirectStart":0,"requestStart":800.6000000238419,"responseEnd":837.5,"responseStart":836.7999999523163,"secureConnectionStart":580.8999999761581}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":64,"responseStart":238,"responseEnd":268,"domLoading":242,"domInteractive":1131,"domContentLoadedEventStart":1131,"domContentLoadedEventEnd":1192,"domComplete":2033,"loadEventStart":2033,"loadEventEnd":2034,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1102.5},{"name":"bigPipe.sidebar-id.end","time":1103.2999999523163},{"name":"bigPipe.activity-panel-pipe-id.start","time":1103.3999999761581},{"name":"bigPipe.activity-panel-pipe-id.end","time":1106.2000000476837},{"name":"activityTabFullyLoaded","time":1208.7999999523163}],"measures":[],"correlationId":"38c2e2c77694f7","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":105,"dbReadsTimeInMs":15,"dbConnsTimeInMs":25,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Major
MDEV-12288 Reset DB_TRX_ID when the history is removed, to speed up MVCC
The crash happens in the rollback of a recovered transaction:
2017-08-11 11:22:34 140736992429824 [Note] InnoDB: Rolling back trx with id 6568, 1 rows to undo…#3 0x00007ffff6550f12 in __GI___assert_fail (assertion=0x10140f5f3 "!mtr == !trx->has_logged()",file=0x10140e758 "/mariadb/10.3/storage/innobase/trx/trx0trx.cc",line=1918,function=0x101411a00 <trx_commit_low(trx_t*, mtr_t*)::__PRETTY_FUNCTION__> "void trx_commit_low(trx_t*, mtr_t*)") at assert.c:101#4 0x0000000100d1dc77 in trx_commit_low (trx=0x7ffff03dc888,mtr=0x7fffe270b410) at /mariadb/10.3/storage/innobase/trx/trx0trx.cc:1918#5 0x0000000100d1deca in trx_commit (trx=0x7ffff03dc888)at /mariadb/10.3/storage/innobase/trx/trx0trx.cc:2018#6 0x0000000100d10822 in trx_rollback_finish (trx=0x7ffff03dc888)at /mariadb/10.3/storage/innobase/trx/trx0roll.cc:1147#7 0x0000000100d0f143 in trx_rollback_active (trx=0x7ffff03dc888)at /mariadb/10.3/storage/innobase/trx/trx0roll.cc:689#8 0x0000000100d0f63a in trx_rollback_resurrected (trx=0x7ffff03dc888, all=1)at /mariadb/10.3/storage/innobase/trx/trx0roll.cc:773#9 0x0000000100d0f91e in trx_rollback_or_clean_recovered (all=1)at /mariadb/10.3/storage/innobase/trx/trx0roll.cc:841InnoDB implements ROLLBACK by first applying the undo log backwards, and then committing the transaction. The crash occurs in the commit.
The assertion fails because mtr!=NULL (because trx->has_logged_or_recovered() holds in trx_commit()) but trx->has_logged() does not hold.
This distinction was made in
MDEV-12288:/** @return whether any undo log has been generated */bool has_logged() const{return(has_logged_persistent() || rsegs.m_noredo.undo);}/** @return whether any undo log has been generated orrecovered */bool has_logged_or_recovered() const{return(has_logged() || rsegs.m_redo.old_insert);}Because the rollback happens after upgrade, we indeed have insert_undo log attached to the transaction. This is a too strict debug assertion; it should check for has_logged_or_recovered() instead of has_logged().
After relaxing the assertion, we hit another problem for this transaction: trx->rsegs.m_redo.undo is NULL, causing a SIGSEGV when it is being dereferenced:
#0 0x0000000100cf5478 in trx_purge_add_update_undo_to_history (trx=0x7ffff03dc888,undo_page=0x7fffea8b2000 "E\026", <incomplete sequence \330>,mtr=0x7fffe270b410) at /mariadb/10.3/storage/innobase/trx/trx0purge.cc:252#1 0x0000000100d1c354 in trx_write_serialisation_history (trx=0x7ffff03dc888, mtr=0x7fffe270b410)at /mariadb/10.3/storage/innobase/trx/trx0trx.cc:1451#2 0x0000000100d1dd36 in trx_commit_low (trx=0x7ffff03dc888,mtr=0x7fffe270b410) at /mariadb/10.3/storage/innobase/trx/trx0trx.cc:1948#3 0x0000000100d1deca in trx_commit (trx=0x7ffff03dc888)at /mariadb/10.3/storage/innobase/trx/trx0trx.cc:2018#4 0x0000000100d10822 in trx_rollback_finish (trx=0x7ffff03dc888)at /mariadb/10.3/storage/innobase/trx/trx0roll.cc:1147