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":1999.2000000476837,"ttfb":438.10000014305115,"pageVisibility":"visible","entityId":62585,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"29b12a13-03ef-4807-bc30-ef67e23b4296","navigationType":0,"readyForUser":1975.2999999523163,"redirectCount":0,"resourceLoadedEnd":2370,"resourceLoadedStart":500.90000009536743,"resourceTiming":[{"duration":713.8999998569489,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":500.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":500.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1214.7999999523163,"responseStart":0,"secureConnectionStart":0},{"duration":715.1000001430511,"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":501.2999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":501.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1216.4000000953674,"responseStart":0,"secureConnectionStart":0},{"duration":769.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":501.40000009536743,"connectEnd":501.40000009536743,"connectStart":501.40000009536743,"domainLookupEnd":501.40000009536743,"domainLookupStart":501.40000009536743,"fetchStart":501.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":501.40000009536743,"responseEnd":1270.6000001430511,"responseStart":1270.6000001430511,"secureConnectionStart":501.40000009536743},{"duration":913.2999999523163,"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":501.60000014305115,"connectEnd":501.60000014305115,"connectStart":501.60000014305115,"domainLookupEnd":501.60000014305115,"domainLookupStart":501.60000014305115,"fetchStart":501.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":501.60000014305115,"responseEnd":1414.9000000953674,"responseStart":1414.9000000953674,"secureConnectionStart":501.60000014305115},{"duration":957.0999999046326,"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":502.10000014305115,"connectEnd":502.10000014305115,"connectStart":502.10000014305115,"domainLookupEnd":502.10000014305115,"domainLookupStart":502.10000014305115,"fetchStart":502.10000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":502.10000014305115,"responseEnd":1459.2000000476837,"responseStart":1459.2000000476837,"secureConnectionStart":502.10000014305115},{"duration":986.2999999523163,"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":502.2000000476837,"connectEnd":502.2000000476837,"connectStart":502.2000000476837,"domainLookupEnd":502.2000000476837,"domainLookupStart":502.2000000476837,"fetchStart":502.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":502.2000000476837,"responseEnd":1488.5,"responseStart":1488.5,"secureConnectionStart":502.2000000476837},{"duration":1046.5999999046326,"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":502.40000009536743,"connectEnd":502.40000009536743,"connectStart":502.40000009536743,"domainLookupEnd":502.40000009536743,"domainLookupStart":502.40000009536743,"fetchStart":502.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":502.40000009536743,"responseEnd":1549,"responseStart":1549,"secureConnectionStart":502.40000009536743},{"duration":1271.3999998569489,"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":502.60000014305115,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":502.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1774,"responseStart":0,"secureConnectionStart":0},{"duration":1046.5,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":503.2000000476837,"connectEnd":503.2000000476837,"connectStart":503.2000000476837,"domainLookupEnd":503.2000000476837,"domainLookupStart":503.2000000476837,"fetchStart":503.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":503.2000000476837,"responseEnd":1549.7000000476837,"responseStart":1549.7000000476837,"secureConnectionStart":503.2000000476837},{"duration":1270.7000000476837,"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":503.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":503.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1774.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":1046.5999999046326,"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":503.7000000476837,"connectEnd":503.7000000476837,"connectStart":503.7000000476837,"domainLookupEnd":503.7000000476837,"domainLookupStart":503.7000000476837,"fetchStart":503.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":503.7000000476837,"responseEnd":1550.2999999523163,"responseStart":1550.2999999523163,"secureConnectionStart":503.7000000476837},{"duration":1830.5999999046326,"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":504.7000000476837,"connectEnd":504.7000000476837,"connectStart":504.7000000476837,"domainLookupEnd":504.7000000476837,"domainLookupStart":504.7000000476837,"fetchStart":504.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":504.7000000476837,"responseEnd":2335.2999999523163,"responseStart":2335.2999999523163,"secureConnectionStart":504.7000000476837},{"duration":1853.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":516.5,"connectEnd":516.5,"connectStart":516.5,"domainLookupEnd":516.5,"domainLookupStart":516.5,"fetchStart":516.5,"redirectEnd":0,"redirectStart":0,"requestStart":516.5,"responseEnd":2370,"responseStart":2370,"secureConnectionStart":516.5},{"duration":580.7000000476837,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":1428.4000000953674,"connectEnd":1428.4000000953674,"connectStart":1428.4000000953674,"domainLookupEnd":1428.4000000953674,"domainLookupStart":1428.4000000953674,"fetchStart":1428.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":1428.4000000953674,"responseEnd":2009.1000001430511,"responseStart":2009.1000001430511,"secureConnectionStart":1428.4000000953674},{"duration":559.2000000476837,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1873.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1873.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2432.7000000476837,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":229,"responseStart":438,"responseEnd":506,"domLoading":446,"domInteractive":2434,"domContentLoadedEventStart":2434,"domContentLoadedEventEnd":2497,"domComplete":3302,"loadEventStart":3302,"loadEventEnd":3303,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":2407.2999999523163},{"name":"bigPipe.sidebar-id.end","time":2408.2000000476837},{"name":"bigPipe.activity-panel-pipe-id.start","time":2408.4000000953674},{"name":"bigPipe.activity-panel-pipe-id.end","time":2411.5},{"name":"activityTabFullyLoaded","time":2509.2000000476837}],"measures":[],"correlationId":"e7c9cda7b91484","effectiveType":"4g","downlink":9.6,"rtt":0,"serverDuration":105,"dbReadsTimeInMs":14,"dbConnsTimeInMs":23,"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