innodb_lock_wait_timeout doesn't work in some case

[crazycs520]

Bug Report

Please answer these questions before submitting your issue. Thanks!

The following slow SQL execution time is 147s, and the Exec_retry_time of this SQL is 145s, which is much larger than the innodb_lock_wait_timeout value 50s. It's strange why it doesn't return an Lock wait timeout exceeded error earlier.

# Time: 2024-10-16T19:10:09.403246+08:00
# Txn_start_ts: 453267124757725196
# User@Host: root[root] @ 127.0.0.1 [127.0.0.1]
# Conn_ID: 2887778316
# Exec_retry_time: 145.053953542 Exec_retry_count: 37
# Query_time: 147.971238792
# Parse_time: 0
# Compile_time: 0.000200667
# Rewrite_time: 0.00016075
# Optimize_time: 0
# Wait_TS: 0.000114125
# Cop_time: 2.808469745 Process_time: 0.086498965 Wait_time: 16.368521541 Request_count: 133 Process_keys: 90144 Total_keys: 156550 Get_snapshot_time: 0.002 Rocksdb_delete_skipped_count: 65521 Rocksdb_key_skipped_count: 214940 Rocksdb_block_cache_hit_count: 876
# DB: test
# Is_internal: false
# Digest: 5ba7e09fe737c04bf0d8931f3aaace3c6ce5f921f2b0b6e15f4c3d5dab6aec7b
# Stats: t:453267123800899585[65536;0]
# Num_cop_tasks: 133
# Cop_proc_avg: 0.000650368 Cop_proc_p90: 0.001237501 Cop_proc_max: 0.006646333 Cop_proc_addr: 127.0.0.1:20160
# Cop_wait_avg: 0.12307159 Cop_wait_p90: 0.128258666 Cop_wait_max: 0.130081417 Cop_wait_addr: 127.0.0.1:20160
# Mem_max: 142684800
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 1873.116027356
# PD_total: 0.000118334
# Backoff_total: 0
# Write_sql_response_total: 0
# Result_rows: 0
# Succ: true
# IsExplicitTxn: true
# IsSyncStatsFailed: false
# Plan: tidb_decode_plan('nRaYMAkyOF81CTAJMAlOL0EJMAl0aW1lOjJtMjcuM3MsIGxvb3BzOjM5AQokY2tfa2V5czogewUkSDgyNG1zLCByZWdpb246MTI4LCAFH0gxMzEwNzIsIHNsb3dlc3RfcnBjATMob3RhbDogMC4zOTkVNjhfaWQ6IDEyNCwgc3RvcmUBDDg3LjAuMC4xOjIwMTYwLCABahhfZGV0YWlsAUUgaWt2X3dhbGxfARg0OiAzOTFtc30sIHNjYW4ZJixnZXRfc25hcHNob3QNKRQ5Ljk2wrUBeLhvY2tzZGI6IHtibG9jazoge2NhY2hlX2hpdF9jb3VudDogMTE3OH19fSwgd3JpdB19BaMkX2JhdGNoX3dhaQEqCDAuOQVWLHByb3Bvc2Vfc2VuZA0cODBzLCBwZXJzaXN0X2xvZwG9KQIINzEuCYsJXxRsZWFkZXIdNQxzeW5jCTIENDIFXQkoNG1lbXRhYmxlOiA1ODRuAfUQY29tbWkNXQgxMjgNVhBhcHBseTKmAAw0LjI1BUkFGxWJBDM4CYcUbXV0ZXhfKQ0BtQlvQpcACRcAdyHEBDI2DWwJFBmaDDIwMS4BtAB9IT4BUiX8QDU1Ljg5MTU3MDI4cywgcnBjLWkIMjgyQT4IdHJ5DREkMX0JOS4wOSBNQkGLkAoxCTI2XzcJMAk2NTUzNglmb3IgdXBkYXRlIDAJMjQ5MDM2OAlFBwwybTFzQaBBqggyNDdJyShOL0EKMgkzMF8xMBVDNjcAFDFtNDUuNjI6ACgsIGluZGV4X3Rhc0EbJbJNQgwxbTQ4BS4EZmVBAQxoYW5kIY0VFwxidWlsQc0MMTcuNCVuSSMMMjQ3LiUTBCwgJb9OWwCgNTYuN3MsIG51bTogMTUyLCBjb25jdXJyZW5jeTogNX0sIG5leHQ6IHsBUwBfBaIYOiAxbTE0LgH4BRUJXBhsb29rdXBfDYsMMjYuMmGhRiEAKHJlc3A6IDMxLjNzIXMANDVzHDMJNDdfOChCAcwMKQkxXzF8BV8EOnQtH1w6aWR4KGlkKSwgcmFuZ2U6KDAsK2luZl2BADRlcCBvcmRlcjpmYWxzZUJxASlDiVUMMjU0NgHsAHAxFCkBXDE0LCBtYXg6IDIuMjJzLCBtaW46IDMuMwHLJGF2ZzogOTUyLjYBDghwOTUBJgAxBSYcYXhfcHJvY1+FgwwgNDA5gZAIcDk1ShYACHRvdAUWGDogOTA3LjEBSwETISgYOiAxMy40cwWXBHJfmRsQcmF0aW+BvggwMSwp6wW1CF9kdQUaAaIANHEWAYscZGlzdHNxbF8yygEEMX1J/yRpbmZvOntDb3A6AfNlJAX2XW9NV2FIhfRFkQB7AeEBXww6Mi4woUUhGyXjJRgQODQ3LjkBzRhwODA6MS41QVQhIwgxLjkBLSRpdGVyczoyOTI2QYsIc2tzAXVCPAUJhAFpCGVzcy1NHDI0NDk0NDAsDaEuHQAMX3NpeqG3FDA3Nzc1M6WxgeYVORw4MjEwNSwgZ0aSBQgxLjMFrbmRNGRlbGV0ZV9za2lwcGVkjRQIIDExBXsIa2V5PhoADDI1NzMl5gBigWtOygUMMzcyNIWMgSfZIAmjEccBHAA6MgoCGGFsX3N1c3ChzAkdEDFtMzQuQWYJOkEpERpJLgkYFGt2X3JlYcEB1aEMMW0zNWWmAHQ6ugYl4Qg1c32BqAEEYXsgNV85KFByb2JlUnsDAGtyXAONRG1aBDYyhUY2WgMENDkhxGVbCDUyNUkrQUIUIDcxNi44hbRFSBAxMjkuOEVIZWAENTQJDkHXITQt3AQxMOG3OmEDCDk0M0UmBSlhtggwM3MJESE0FDogOW0yOaVFCGNvcFZfAwAwWl8DCDUuOUUvAYZWXQOhKMFdSl4DCfoppSXSGDEwbTQxLjFiYAPhCCEbAQgpFAgzLjUlE2FbBQkUOTU6MTI3AQttWQAxEgIJYakAcwVxmlsDxcglJARhbCU3cXgAX2lbHDIyNTc0ODAxYbZ9WxA1MDM4NA5mCQBnRlsDBDk4qSB+WwMYMjMwMzk1NqG3Ql0DIDEwNzMwMjI3LGZeAxAyMjIyMeHCAGF5rQQwNBESMGJ5dGU6IDIyLjUgTUINJiV8FCAxNC43bRYkCAERdpgDADNVQ06WAwAuDlIIKRdBYQ1hVWYJGlKXAwA2RYdClgM4MG0zOHN9CU4vQQlOL0EK')
use test;
update t use index (idx) set k=k+1 where id >0;

1. Minimal reproduce step (Required)

1. create a TiDB cluster with following TiDB config:

[tikv-client]
copr-cache.capacity-mb = 0

1. prepare data:

create table t (id int auto_increment, k int,c varchar(255), d int, e int, f int, g int,i int, h int, unique index idx(id), index(c), index(d), index(e), index(f), index(g), index(i),index (h));
insert into t (k,c) values (1,'qwertyuiopasdfghjklzxcvbnm,.1230984576pjlksajdflkjoerjtfalkjsdalfkjlkdsjflksjadflkjlkdsajflkjdsalkfjdsalkjfkljdsakljlkdsajflkdsajfdsalasdfasdf');
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t;
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
insert into t (k,c) select k,c from t
update t set c=id,d=id,e=id,f=id,g=id,h=id,i=id;
split table t between (0) and (135536) regions 130;

set @@global.tidb_mem_quota_query=3221225472;
set @@global.tidb_multi_statement_mode='ON';

3. Run the following SQL loop, in session-1:

begin;
update t use index (idx) set k=k+1 where id >131000;
commit;

You can use loadgen tool to implement this:

loadgen bench --sql="begin;update t use index (idx) set k=k+1 where id >131000;commit;" --thread=1

2. Run the following SQL loop, in session-2:

begin;
update t use index (idx) set k=k+1 where id > 0;
commit;

loadgen bench --sql="begin;update t use index (idx) set k=k+1 where id >0;commit;" --thread=1

4. Run the following SQL loop, concurrently in 100 sessions.

select count(*),sum(k),sum(c),sum(d),sum(e),count(i),sum(g) from t where id > 0;

loadgen bench --sql="select count(*),sum(k),sum(c),sum(d),sum(e),count(i),sum(g) from t where id > #rand-val" --valmin=0 --valmax=100000 --thread=100

2. What did you expect to see? (Required)

The slowest execution time of SQL update t use index (idx) set k=k+1 where id > 0; should be around 50s.

3. What did you see instead (Required)

The slowest execution time of SQL update t use index (idx) set k=k+1 where id > 0; is much larger than the innodb_lock_wait_timeout value 50s. It's strange why it doesn't return an Lock wait timeout exceeded error earlier.

4. What is your TiDB version? (Required)

nightly: 3df0f2e

[cfzjywxk]

In rare case the request is retired and write conflict error is returned, the lock wati timeout would not be checked in time.
The lock wait timeout could be checked when write conflict error is returned, as write conflict error also indicates the lock is not acquired successfully.

[seiya-annie]

/report customer