Type:
Priority:
Resolution:
Fixed
Affects Version/s:
10.5
While testing MDEV-33383 mleich provided an rr replay trace for a lock order inversion in ibuf_remove_free_page() , which was invoked by ibuf_free_excess_pages() and doing the following:
10.5 1d74927c58cea438c135a95886a9224405819a96 ibuf0ibuf.cc
1913
log_free_check();
1914
1915
mtr_start(&mtr);
1916
/* Acquire the fsp latch before the ibuf header, obeying the latching
1917
order */
1918
1919
mtr_x_lock_space(fil_system.sys_space, &mtr);
1920
header_page = ibuf_header_page_get(&mtr);
1921
1922
/* Prevent pessimistic inserts to insert buffer trees for a while */
1923
ibuf_enter(&mtr);
1924
mutex_enter(&ibuf_pessimistic_insert_mutex);
At the start of this code, the thread is not holding any latches. The complaint is about lock order inversion between ibuf_pessimistic_insert_mutex and fil_system.sys_space.latch . Starting with 10.6 there will be no such warning, because the debug code was removed as part of MDEV-24142 MDEV-21452 ibuf_insert_low() will acquire ibuf_pessimistic_insert_mutex first, and then descend into the tree (btr_pcur_open() for performing the multi-page insert.
However, because this is a change buffer operation, it looks like any new pages would have been preallocated, to be delivered by btr_page_alloc_for_ibuf() . Normal page allocation would acquire fil_system.sys_space.latch , which would be a genuine lock order inversion.
The crash report looked like this:
10.5-MDEV-33383 cbb55ca3ce41d71907a9e0ee66767e829416925e
#5 0x000055abe43f1aeb in ut_dbg_assertion_failed (
expr=expr@entry=0x55abe49d8df0 "latches->empty() || level == SYNC_LEVEL_VARYING || level == SYNC_NO_ORDER_CHECK || latches->back().get_level() == SYNC_NO_ORDER_CHECK || latches->back().m_latch->get_level() == SYNC_LEVEL_VARYING || l"..., file=file@entry=0x55abe49d80e0 "/data/Server/10.5-MDEV-33383/storage/innobase/sync/sync0debug.cc", line=line@entry=215) at /data/Server/10.5-MDEV-33383/storage/innobase/ut/ut0dbg.cc:60
#6 0x000055abe43aad95 in LatchDebug::lock_validate (this=this@entry=0x55abe66dcc00, latch=latch@entry=0x7f70c00619b0, level=SYNC_IBUF_PESS_INSERT_MUTEX) at /data/Server/10.5-MDEV-33383/storage/innobase/sync/sync0debug.cc:215
#7 0x000055abe43a781d in sync_check_lock_validate (latch=latch@entry=0x7f70c00619b0) at /data/Server/10.5-MDEV-33383/storage/innobase/sync/sync0debug.cc:1038
#8 0x000055abe41acfb1 in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=this@entry=0x55abe591f830 <ibuf_pessimistic_insert_mutex+16>, mutex=...,
filename=filename@entry=0x55abe499c290 "/data/Server/10.5-MDEV-33383/storage/innobase/ibuf/ibuf0ibuf.cc", line=line@entry=1924) at /data/Server/10.5-MDEV-33383/storage/innobase/include/sync0types.h:383
#9 0x000055abe41ad6fe in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55abe591f820 <ibuf_pessimistic_insert_mutex>, n_spins=30, n_delay=4,
name=0x55abe499c290 "/data/Server/10.5-MDEV-33383/storage/innobase/ibuf/ibuf0ibuf.cc", line=1924) at /data/Server/10.5-MDEV-33383/storage/innobase/include/ib0mutex.h:588
#10 0x000055abe420ea50 in ibuf_remove_free_page () at /data/Server/10.5-MDEV-33383/storage/innobase/ibuf/ibuf0ibuf.cc:1924
#11 0x000055abe420f445 in ibuf_free_excess_pages () at /data/Server/10.5-MDEV-33383/storage/innobase/ibuf/ibuf0ibuf.cc:2026
#12 0x000055abe42f6850 in row_ins_sec_index_entry (index=index@entry=0x7f70ac0bfce0, entry=entry@entry=0x7f70ac066578, thr=thr@entry=0x7f70ac0c4820, check_foreign=check_foreign@entry=true)
at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0ins.cc:3374
#13 0x000055abe42f6982 in row_ins_index_entry (index=0x7f70ac0bfce0, entry=0x7f70ac066578, thr=thr@entry=0x7f70ac0c4820) at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0ins.cc:3414
#14 0x000055abe42f6ae5 in row_ins_index_entry_step (node=node@entry=0x7f70ac0c44f8, thr=thr@entry=0x7f70ac0c4820) at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0ins.cc:3580
#15 0x000055abe42f6bd5 in row_ins (node=node@entry=0x7f70ac0c44f8, thr=thr@entry=0x7f70ac0c4820) at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0ins.cc:3717
#16 0x000055abe42f76f5 in row_ins_step (thr=thr@entry=0x7f70ac0c4820) at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0ins.cc:3860
#17 0x000055abe431a539 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x7f70ac0c0318 "\377ilfq", ' ' <repeats 56 times>, "\021)", prebuilt=0x7f70ac0c3f70, ins_mode=<optimized out>)
at /data/Server/10.5-MDEV-33383/storage/innobase/row/row0mysql.cc:1394
#18 0x000055abe4199038 in ha_innobase::write_row (this=0x7f70ac0c3730, record=0x7f70ac0c0318 "\377ilfq", ' ' <repeats 56 times>, "\021)") at /data/Server/10.5-MDEV-33383/storage/innobase/handler/ha_innodb.cc:7685
To me, this would seem to be a bogus report about a potential hang.
The change buffer was disabled by default in MDEV-27734
{"report":{"fcp":817.3999998569489,"ttfb":167.5,"pageVisibility":"visible","entityId":127841,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":1,"journeyId":"79c5c4ad-9318-47f9-ae62-2346a7d875c2","navigationType":0,"readyForUser":943.8999998569489,"redirectCount":0,"resourceLoadedEnd":979.7000000476837,"resourceLoadedStart":173.09999990463257,"resourceTiming":[{"duration":221.40000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":173.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":173.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":394.5,"responseStart":0,"secureConnectionStart":0},{"duration":221.20000004768372,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":173.39999985694885,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":173.39999985694885,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":394.59999990463257,"responseStart":0,"secureConnectionStart":0},{"duration":230.20000004768372,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":173.5,"connectEnd":173.5,"connectStart":173.5,"domainLookupEnd":173.5,"domainLookupStart":173.5,"fetchStart":173.5,"redirectEnd":0,"redirectStart":0,"requestStart":173.5,"responseEnd":403.7000000476837,"responseStart":403.7000000476837,"secureConnectionStart":173.5},{"duration":317,"initiatorType":"script","name":"https://jira.mariadb.org/s/099b33461394b8015fc36c0a4b96e19f-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":173.5,"connectEnd":173.5,"connectStart":173.5,"domainLookupEnd":173.5,"domainLookupStart":173.5,"fetchStart":173.5,"redirectEnd":0,"redirectStart":0,"requestStart":173.5,"responseEnd":490.5,"responseStart":490.5,"secureConnectionStart":173.5},{"duration":320.69999980926514,"initiatorType":"script","name":"https://jira.mariadb.org/s/94c15bff32baef80f4096a08aceae8bc-CDN/lu2bu7/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":173.70000004768372,"connectEnd":173.70000004768372,"connectStart":173.70000004768372,"domainLookupEnd":173.70000004768372,"domainLookupStart":173.70000004768372,"fetchStart":173.70000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":173.70000004768372,"responseEnd":494.39999985694885,"responseStart":494.39999985694885,"secureConnectionStart":173.70000004768372},{"duration":321.09999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":173.70000004768372,"connectEnd":173.70000004768372,"connectStart":173.70000004768372,"domainLookupEnd":173.70000004768372,"domainLookupStart":173.70000004768372,"fetchStart":173.70000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":173.70000004768372,"responseEnd":494.7999999523163,"responseStart":494.7999999523163,"secureConnectionStart":173.70000004768372},{"duration":321.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":173.79999995231628,"connectEnd":173.79999995231628,"connectStart":173.79999995231628,"domainLookupEnd":173.79999995231628,"domainLookupStart":173.79999995231628,"fetchStart":173.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":173.79999995231628,"responseEnd":495.09999990463257,"responseStart":495.09999990463257,"secureConnectionStart":173.79999995231628},{"duration":321.59999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2bu7/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":174,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":174,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":495.59999990463257,"responseStart":0,"secureConnectionStart":0},{"duration":321.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":174,"connectEnd":174,"connectStart":174,"domainLookupEnd":174,"domainLookupStart":174,"fetchStart":174,"redirectEnd":0,"redirectStart":0,"requestStart":174,"responseEnd":495.59999990463257,"responseStart":495.59999990463257,"secureConnectionStart":174},{"duration":321.90000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2bu7/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":174.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":174.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":496,"responseStart":0,"secureConnectionStart":0},{"duration":321.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/3339d87fa2538a859872f2df449bf8d0-CDN/lu2bu7/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":174.29999995231628,"connectEnd":174.29999995231628,"connectStart":174.29999995231628,"domainLookupEnd":174.29999995231628,"domainLookupStart":174.29999995231628,"fetchStart":174.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":174.29999995231628,"responseEnd":496.09999990463257,"responseStart":496.09999990463257,"secureConnectionStart":174.29999995231628},{"duration":617.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":175.09999990463257,"connectEnd":175.09999990463257,"connectStart":175.09999990463257,"domainLookupEnd":175.09999990463257,"domainLookupStart":175.09999990463257,"fetchStart":175.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":175.09999990463257,"responseEnd":792.8999998569489,"responseStart":792.7999999523163,"secureConnectionStart":175.09999990463257},{"duration":804.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":175.20000004768372,"connectEnd":175.20000004768372,"connectStart":175.20000004768372,"domainLookupEnd":175.20000004768372,"domainLookupStart":175.20000004768372,"fetchStart":175.20000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":175.20000004768372,"responseEnd":979.7000000476837,"responseStart":979.7000000476837,"secureConnectionStart":175.20000004768372},{"duration":233.90000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":559.7999999523163,"connectEnd":559.7999999523163,"connectStart":559.7999999523163,"domainLookupEnd":559.7999999523163,"domainLookupStart":559.7999999523163,"fetchStart":559.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":559.7999999523163,"responseEnd":793.7000000476837,"responseStart":793.7000000476837,"secureConnectionStart":559.7999999523163},{"duration":180.5,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":810.5999999046326,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":810.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":991.0999999046326,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":35,"responseStart":167,"responseEnd":171,"domLoading":170,"domInteractive":1003,"domContentLoadedEventStart":1003,"domContentLoadedEventEnd":1044,"domComplete":1904,"loadEventStart":1904,"loadEventEnd":1905,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":991.5},{"name":"bigPipe.sidebar-id.end","time":992.3999998569489},{"name":"bigPipe.activity-panel-pipe-id.start","time":992.5},{"name":"bigPipe.activity-panel-pipe-id.end","time":995},{"name":"activityTabFullyLoaded","time":1055.3999998569489}],"measures":[],"correlationId":"8c20dee0bb9f4c","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":75,"dbReadsTimeInMs":14,"dbConnsTimeInMs":21,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Major
MDEV-27734 Set innodb_change_buffering=none by default
