mleich produced an rr replay trace of a MDEV-35049 development branch that features this same error, but without the involvement of OPTIMIZE TABLE. Initially, I was suspecting that this failure is something specific to that branch, because the branch includes a rewrite of how keys are being searched for in B-tree pages.
In the end, this seems to be a race condition. It took me a while to figure out how to debug this. In the end, I set a hardware data watchpoint on the clustered index record (DB_ROW_ID=0x4b7) in the buffer pool, specifically on the last 4 bytes of the DB_ROLL_PTR field and the 4 bytes of the problematic col_int_key field, to catch what is going on. I also set a watchpoint on the delete-mark flag of the secondary index record (col_int_key,DB_ROW_ID)=(5,0x4b7).
The hardware data watchpoint on the clustered index record was being hit by the following:
During the execution of the second UPDATE (transaction 0x1e, just a little too new to be included in purge_sys.view), the purge of the first UPDATE was blocked in the following:
#17 log_free_check () at /data/Server/10.6-MDEV-35049E/storage/innobase/log/log0log.cc:956
#18 0x000063a8330d1a61 in row_purge_remove_sec_if_poss_tree (node=node@entry=0x63a8354a62b8, index=index@entry=0x7d1998069e78, entry=entry@entry=0x7d19a402df88, page_max_trx_id=page_max_trx_id@entry=0x1e)
at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:767
#19 0x000063a8330d2925 in row_purge_remove_sec_if_poss (node=node@entry=0x63a8354a62b8, index=0x7d1998069e78, entry=0x7d19a402df88) at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:991
#20 0x000063a8330d31c6 in row_purge_upd_exist_or_extern_func (thr=thr@entry=0x63a8354a6218, node=node@entry=0x63a8354a62b8, undo_rec=undo_rec@entry=0x7d19c51abdda ">\b\f\202\267\022")
at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:1157
#21 0x000063a8330d36a6 in row_purge_record_func (node=node@entry=0x63a8354a62b8, undo_rec=undo_rec@entry=0x7d19c51abdda ">\b\f\202\267\022", thr=thr@entry=0x63a8354a6218, updated_extern=0x0)
at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:1548
#22 0x000063a8330d3baa in row_purge (node=node@entry=0x63a8354a62b8, undo_rec=undo_rec@entry=0x7d19c51abdda ">\b\f\202\267\022", thr=thr@entry=0x63a8354a6218)
at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:1587
#23 0x000063a8330d3c09 in row_purge_step (thr=thr@entry=0x63a8354a6218) at /data/Server/10.6-MDEV-35049E/storage/innobase/row/row0purge.cc:1650
During this blockage, the second UPDATE had updated both the clustered index record and removed the delete-mark on the secondary index record (5,0x4b7) which had been delete-marked by the first UPDATE. Then, purge would report an error and hit ut_ad(0), crashing the debug instrumented build:
2024-11-21 13:14:38 0 [ERROR] InnoDB: tried to purge non-delete-marked record in index `col_int_key` of table `test`.`table10000_innodb`: tuple: TUPLE (info_bits=0, 2 fields): {[4] (0x80000005),[6] (0x0000000004B7)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x80000005),[6] (0x0000000004B7)}
The problem turns out to be that MDEV-34515 introduced an unsafe optimization: If the PAGE_MAX_TRX_ID did not change between row_purge_remove_sec_if_poss_leaf() and row_purge_remove_sec_if_poss_tree(), a call to row_purge_poss_sec() would be skipped.
A more correct condition would be the following: If the PAGE_MAX_TRX_ID was not changed and it did not belong to an active transaction when row_purge_remove_sec_if_poss_leaf() was holding the secondary index leaf page latch, the check would be redundant.
As far as I can tell, the impact of this bug is limited to some error log "spam" and the debug assertion failure. This should not cause any actual corruption.
CREATETABLE t(a INTPRIMARYKEY, b INTNOTNULL, INDEX(b)) ENGINE=InnoDB;
SET STATEMENT unique_checks=0,foreign_key_checks=0 FOR
INSERTINTO t SELECT seq, seq from seq_1_to_10000;
--disable_query_log
let $N=30;
while ($N)
{
UPDATE t SET b=a+1; UPDATE t SET b=a;
dec $N;
}
--enable_query_log
SETGLOBAL innodb_max_purge_lag_wait=0;
DROPTABLE t;
./mtr --parallel=5 main.m-MDEV-35508{,,,,}
10.6 9ba18d1aa049603b8e865e6616e26a4da8b1ecce
main.m-MDEV-35508 w3 [ pass ] 13148
main.m-MDEV-35508 w4 [ fail ] Found warnings/errors in server log file!
Test ended at 2024-11-27 11:24:14
line
2024-11-27 11:24:06 0 [ERROR] InnoDB: tried to purge non-delete-marked record in index `b` of table `test`.`t`: tuple: TUPLE (info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}
Marko Mäkelä
added a comment - The following test reproduces this rather easily:
--source include/have_innodb.inc
--source include/have_sequence.inc
CREATE TABLE t(a INT PRIMARY KEY , b INT NOT NULL , INDEX (b)) ENGINE=InnoDB;
SET STATEMENT unique_checks=0,foreign_key_checks=0 FOR
INSERT INTO t SELECT seq, seq from seq_1_to_10000;
--disable_query_log
let $N=30;
while ($N)
{
UPDATE t SET b=a+1; UPDATE t SET b=a;
dec $N;
}
--enable_query_log
SET GLOBAL innodb_max_purge_lag_wait=0;
DROP TABLE t;
. /mtr --parallel=5 main.m-MDEV-35508{,,,,}
10.6 9ba18d1aa049603b8e865e6616e26a4da8b1ecce
main.m-MDEV-35508 w3 [ pass ] 13148
main.m-MDEV-35508 w4 [ fail ] Found warnings/errors in server log file!
Test ended at 2024-11-27 11:24:14
line
2024-11-27 11:24:06 0 [ERROR] InnoDB: tried to purge non-delete-marked record in index `b` of table `test`.`t`: tuple: TUPLE (info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}
marko, mleich It is great that we could catch the issue. I completely agree that the issue is caused by MDEV-34515 PAGE_MAX_TRX_ID related optimization. I think the issue is more serious and could affect release build too possibly corrupting secondary index. To understand the issue effectively I could create a debug_sync test that repeats the issue consistently every time. Please find attached 10.6_test_repeat.patch.
Here is what I find from analyzing the issue.
1. The assert could still be hit with the current fix and needs to be improved. Essentially, the transaction ID is the start point and there could be many transaction running with ID smaller than PAGE_MAX_TRX_ID set by some transaction that is already committed. A transaction with ID smaller than PAGE_MAX_TRX_ID is not going to update the page. So, the condition needs to be stricter following the same logic that we apply while checking for implicit lock for secondary index page i.e. checking for all active transaction equal or smaller than the PAGE_MAX_TRX_ID. I have attached the patch that fixes the issue - 10.6_fix.patch
2. Since it is also possible another transaction to further delete mark the key (after being unmarked), the purge could actually successfully delete the secondary index which it should not. This could affect several cases including MVCC where a transaction may miss reading a record, Rollback not able to find the older record for removing delete mark eventually leading to missing entries in secondary index. I will test some more trying to simulate other scenarios.
Debarun Banerjee
added a comment - - edited marko , mleich It is great that we could catch the issue. I completely agree that the issue is caused by MDEV-34515 PAGE_MAX_TRX_ID related optimization. I think the issue is more serious and could affect release build too possibly corrupting secondary index. To understand the issue effectively I could create a debug_sync test that repeats the issue consistently every time. Please find attached 10.6_test_repeat.patch.
Here is what I find from analyzing the issue.
1. The assert could still be hit with the current fix and needs to be improved. Essentially, the transaction ID is the start point and there could be many transaction running with ID smaller than PAGE_MAX_TRX_ID set by some transaction that is already committed. A transaction with ID smaller than PAGE_MAX_TRX_ID is not going to update the page. So, the condition needs to be stricter following the same logic that we apply while checking for implicit lock for secondary index page i.e. checking for all active transaction equal or smaller than the PAGE_MAX_TRX_ID. I have attached the patch that fixes the issue - 10.6_fix.patch
2. Since it is also possible another transaction to further delete mark the key (after being unmarked), the purge could actually successfully delete the secondary index which it should not. This could affect several cases including MVCC where a transaction may miss reading a record, Rollback not able to find the older record for removing delete mark eventually leading to missing entries in secondary index. I will test some more trying to simulate other scenarios.
debarun, thank you for 10.6_test_repeat.patch. If I disable the failing debug assertion, the test would trigger a write of the message to the server error log, but neither CHECK TABLE nor CHECK TABLE…EXTENDED would report any error.
Nevertheless, I can imagine a scenario where a secondary index record is being constantly delete-marked and delete-unmarked by a flow of DML operations, and a purge operation would prematurely delete the record, without showing any warning message. That is, a more complex test case could demonstrate actual corruption of a secondary index.
Marko Mäkelä
added a comment - debarun , thank you for 10.6_test_repeat.patch . If I disable the failing debug assertion, the test would trigger a write of the message to the server error log, but neither CHECK TABLE nor CHECK TABLE…EXTENDED would report any error.
Nevertheless, I can imagine a scenario where a secondary index record is being constantly delete-marked and delete-unmarked by a flow of DML operations, and a purge operation would prematurely delete the record, without showing any warning message. That is, a more complex test case could demonstrate actual corruption of a secondary index.
I checked for further impacts for the two cases I mentioned in last comment.
1. MVCC: By changing the attached test case to delete the record again by another transaction, and creating a read only transaction between Update and Delete, missing data read could be simulated. After purge incorrectly purges the delete marked row, SELECT using secondary index for the read only transaction returns no rows. The same SELECT would correctly show the record secondary index is not used in scan.
# Correct - One record fetched
SELECT * FROM t1 IGNORE INDEX (k1);
col1 col2
1 100
# Incorrect - No records fetched
SELECT * FROM t1 FORCE INDEX (k1);
col1 col2
2. Rollback: After the delete marked record is purged, rollback resulted in following error in server log. Fortunately, it looks like the rollback operation is able to re-insert back the correct record/key after facing the issue. So, things are in correct state after rollback and no corruption is observed.
2024-11-28 13:08:14 4 [Warning] InnoDB: Record in index `k1` of table `test`.`t1` was not found on rollback, trying to insert: TUPLE (info_bits=0, 2 fields): {[4] d(0x80000064),[4] (0x80000001)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x696E66696D756D00)}
Debarun Banerjee
added a comment - I checked for further impacts for the two cases I mentioned in last comment.
1. MVCC: By changing the attached test case to delete the record again by another transaction, and creating a read only transaction between Update and Delete, missing data read could be simulated. After purge incorrectly purges the delete marked row, SELECT using secondary index for the read only transaction returns no rows. The same SELECT would correctly show the record secondary index is not used in scan.
# Correct - One record fetched
SELECT * FROM t1 IGNORE INDEX (k1);
col1 col2
1 100
# Incorrect - No records fetched
SELECT * FROM t1 FORCE INDEX (k1);
col1 col2
2. Rollback: After the delete marked record is purged, rollback resulted in following error in server log. Fortunately, it looks like the rollback operation is able to re-insert back the correct record/key after facing the issue. So, things are in correct state after rollback and no corruption is observed.
2024-11-28 13:08:14 4 [Warning] InnoDB: Record in index `k1` of table `test`.`t1` was not found on rollback, trying to insert: TUPLE (info_bits=0, 2 fields): {[4] d(0x80000064),[4] (0x80000001)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x696E66696D756D00)}
Note that the fix of this moved some duplicated error reporting to a new function row_purge_del_mark_error(), which also includes a debug assertion ut_ad(0). Previously, such a debug assertion was only present in row_purge_remove_sec_if_poss_tree(), not in the function row_purge_remove_sec_if_poss_leaf(). Therefore, after this fix, we will get more corruption-related crashes in debug instrumented builds.
Marko Mäkelä
added a comment - Note that the fix of this moved some duplicated error reporting to a new function row_purge_del_mark_error() , which also includes a debug assertion ut_ad(0) . Previously, such a debug assertion was only present in row_purge_remove_sec_if_poss_tree() , not in the function row_purge_remove_sec_if_poss_leaf() . Therefore, after this fix, we will get more corruption-related crashes in debug instrumented builds.
People
Marko Mäkelä
Marko Mäkelä
Votes:
0Vote for this issue
Watchers:
2Start watching this issue
Dates
Created:
Updated:
Resolved:
Git Integration
Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.
{"report":{"fcp":1095.6999998092651,"ttfb":332,"pageVisibility":"visible","entityId":131778,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"8a822180-67aa-43d6-afd9-9df257ac5f7e","navigationType":0,"readyForUser":1228.1999998092651,"redirectCount":0,"resourceLoadedEnd":796.9000000953674,"resourceLoadedStart":355.90000009536743,"resourceTiming":[{"duration":112.69999980926514,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":355.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":355.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":468.59999990463257,"responseStart":0,"secureConnectionStart":0},{"duration":112.90000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/2bf333562ca6724060a9d5f1535471f6/_/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":356.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":356.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":469,"responseStart":0,"secureConnectionStart":0},{"duration":295.2999997138977,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":356.40000009536743,"connectEnd":356.40000009536743,"connectStart":356.40000009536743,"domainLookupEnd":356.40000009536743,"domainLookupStart":356.40000009536743,"fetchStart":356.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":473.19999980926514,"responseEnd":651.6999998092651,"responseStart":490.69999980926514,"secureConnectionStart":356.40000009536743},{"duration":440.40000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/2bf333562ca6724060a9d5f1535471f6/_/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":356.5,"connectEnd":356.5,"connectStart":356.5,"domainLookupEnd":356.5,"domainLookupStart":356.5,"fetchStart":356.5,"redirectEnd":0,"redirectStart":0,"requestStart":473.40000009536743,"responseEnd":796.9000000953674,"responseStart":492.69999980926514,"secureConnectionStart":356.5},{"duration":141.5,"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":356.69999980926514,"connectEnd":356.69999980926514,"connectStart":356.69999980926514,"domainLookupEnd":356.69999980926514,"domainLookupStart":356.69999980926514,"fetchStart":356.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":474.90000009536743,"responseEnd":498.19999980926514,"responseStart":494.69999980926514,"secureConnectionStart":356.69999980926514},{"duration":141.59999990463257,"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":356.90000009536743,"connectEnd":356.90000009536743,"connectStart":356.90000009536743,"domainLookupEnd":356.90000009536743,"domainLookupStart":356.90000009536743,"fetchStart":356.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":475.09999990463257,"responseEnd":498.5,"responseStart":496.59999990463257,"secureConnectionStart":356.90000009536743},{"duration":145.59999990463257,"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":357.09999990463257,"connectEnd":357.09999990463257,"connectStart":357.09999990463257,"domainLookupEnd":357.09999990463257,"domainLookupStart":357.09999990463257,"fetchStart":357.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":484.30000019073486,"responseEnd":502.69999980926514,"responseStart":501,"secureConnectionStart":357.09999990463257},{"duration":126.19999980926514,"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":357.30000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":357.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":483.5,"responseStart":0,"secureConnectionStart":0},{"duration":150.7999997138977,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":357.40000009536743,"connectEnd":357.40000009536743,"connectStart":357.40000009536743,"domainLookupEnd":357.40000009536743,"domainLookupStart":357.40000009536743,"fetchStart":357.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":486.69999980926514,"responseEnd":508.19999980926514,"responseStart":503.69999980926514,"secureConnectionStart":357.40000009536743},{"duration":126.40000009536743,"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":357.59999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":357.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":484,"responseStart":0,"secureConnectionStart":0},{"duration":151.10000038146973,"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":357.69999980926514,"connectEnd":357.69999980926514,"connectStart":357.69999980926514,"domainLookupEnd":357.69999980926514,"domainLookupStart":357.69999980926514,"fetchStart":357.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":487.59999990463257,"responseEnd":508.80000019073486,"responseStart":506.19999980926514,"secureConnectionStart":357.69999980926514},{"duration":401,"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":371.69999980926514,"connectEnd":371.69999980926514,"connectStart":371.69999980926514,"domainLookupEnd":371.69999980926514,"domainLookupStart":371.69999980926514,"fetchStart":371.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":624.5999999046326,"responseEnd":772.6999998092651,"responseStart":768,"secureConnectionStart":371.69999980926514},{"duration":386.90000009536743,"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":391.69999980926514,"connectEnd":391.69999980926514,"connectStart":391.69999980926514,"domainLookupEnd":391.69999980926514,"domainLookupStart":391.69999980926514,"fetchStart":391.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":748.9000000953674,"responseEnd":778.5999999046326,"responseStart":775.8000001907349,"secureConnectionStart":391.69999980926514},{"duration":160.69999980926514,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":784.5,"connectEnd":784.5,"connectStart":784.5,"domainLookupEnd":784.5,"domainLookupStart":784.5,"fetchStart":784.5,"redirectEnd":0,"redirectStart":0,"requestStart":900.0999999046326,"responseEnd":945.1999998092651,"responseStart":943.8000001907349,"secureConnectionStart":784.5},{"duration":276.40000009536743,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1089.5999999046326,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1089.5999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1366,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":89,"responseStart":332,"responseEnd":391,"domLoading":340,"domInteractive":1302,"domContentLoadedEventStart":1302,"domContentLoadedEventEnd":1362,"domComplete":1865,"loadEventStart":1865,"loadEventEnd":1866,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1271.1999998092651},{"name":"bigPipe.sidebar-id.end","time":1271.9000000953674},{"name":"bigPipe.activity-panel-pipe-id.start","time":1272.0999999046326},{"name":"bigPipe.activity-panel-pipe-id.end","time":1275.4000000953674},{"name":"activityTabFullyLoaded","time":1379}],"measures":[],"correlationId":"ab0e85b9ec4fba","effectiveType":"4g","downlink":9.3,"rtt":0,"serverDuration":139,"dbReadsTimeInMs":15,"dbConnsTimeInMs":24,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
The following test reproduces this rather easily:
--source include/have_innodb.inc
--source include/have_sequence.inc
--disable_query_log
let $N=30;
while ($N)
{
}
--enable_query_log
10.6 9ba18d1aa049603b8e865e6616e26a4da8b1ecce
main.m-MDEV-35508 w3 [ pass ] 13148
main.m-MDEV-35508 w4 [ fail ] Found warnings/errors in server log file!
Test ended at 2024-11-27 11:24:14
line
2024-11-27 11:24:06 0 [ERROR] InnoDB: tried to purge non-delete-marked record in index `b` of table `test`.`t`: tuple: TUPLE (info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4] "?(0x8000223F),[4] ">(0x8000223E)}