Primary lock exception during regression test

[yibin87]

Error 1105 (HY000): other error for mpp stream: Code: 0, e.displayText() = DB::Exception: primary_lock: "t\200\000\000\000
\000\000\000r_r\003\200\000\000\000\000\000\000?\003\200\000\000\000\000\000\000\002"
lock_version: 454344339710803970
key: "t\200\000\000\000\000\000\000r_r\003\200\000\000\000\000\000\000?\003\200\000\000\000\000\000\000\002"
lock_ttl: 50000
txn_size: 1
lock_for_update_ts: 454344339723911177
use_async_commit: true
min_commit_ts: 454344339723911179
secondaries: "t\200\000\000\000\000\000\000x_r\003\200\000\000\000\000\000\000?\003\200\000\000\000\000\000\000\002\003\20
0\000\000\000\000\000\020\036"

[yibin87]

Tidb logs:

169056:[2024/12/03 08:35:20.386 +08:00] [INFO] [2pc.go:1314] ["send TxnHeartBeat"] [startTS=454344339710803970] [newTTL=30000] [isPipelinedTxn=false]
169063:[2024/12/03 08:35:30.387 +08:00] [INFO] [2pc.go:1314] ["send TxnHeartBeat"] [startTS=454344339710803970] [newTTL=40000] [isPipelinedTxn=false]
169091:[2024/12/03 08:35:40.387 +08:00] [INFO] [2pc.go:1314] ["send TxnHeartBeat"] [startTS=454344339710803970] [newTTL=50000] [isPipelinedTxn=false]
169094:[2024/12/03 08:35:43.333 +08:00] [WARN] [prewrite.go:415] ["async commit cannot proceed since the returned minCommitTS is zero, fallback to normal path"] [conn=3890217304] [session_alias=] [startTS=454344339710803970]

TiFlash logs:

tiflash-1/server.log:[2024/12/03 08:35:22.733 +08:00] [INFO] [RemoteRequest.cpp:34] ["Start to build remote request for 1 regions (1467) for table 114"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=346]

tiflash-1/server.log:[2024/12/03 08:35:22.982 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 20801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:23.075 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 20801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:23.234 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 20801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:23.442 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 20801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:23.971 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 18801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:25.160 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 19550ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:26.712 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 17550ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:29.708 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 21650ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:32.337 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 17801ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:34.735 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 19550ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:37.553 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 17550ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:39.941 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 19600ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:42.704 +08:00] [INFO] [<unknown>] ["get lock and sleep for a while, sleep time is 18600ms."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]

-- 08:35:45 错误超过 backoff，abort 查询
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [ERROR] [<unknown>] ["coprocessor meets error, error message: {}, error code: {}"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [INFO] [<unknown>] ["cop task exit because already meet error"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> pingcap/coprocessor"] [thread_id=4076]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [WARN] [CoprocessorReaderSourceOp.cpp:78] ["coprocessor reader meets error: primary_lock: \"t\\200\\000\\000\\000\\000\\000\\000r_r\\003\\200\\000\\000\\000\\000\\000\\000?\\003\\200\\000\\000\\000\\000\\000\\000\\002\"\nlock_version: 454344339710803970\nkey: \"t\\200\\000\\000\\000\\000\\000\\000r_r\\003\\200\\000\\000\\000\\000\\000\\000?\\003\\200\\000\\000\\000\\000\\000\\000\\002\"\nlock_ttl: 50000\ntxn_size: 1\nlock_for_update_ts: 454344339723911177\nuse_async_commit: true\nmin_commit_ts: 454344339723911179\nsecondaries:..."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=11]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [WARN] [Task.cpp:128] ["error occurred and cancel the query"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> 0"] [thread_id=11]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [WARN] [PipelineExecutorContext.cpp:104] ["error primary_lock: \"t\\200\\000\\000\\000\\000\\000\\000r_r\\003\\200\\000\\000\\000\\000\\000\\000?\\003\\200\\000\\000\\000\\000\\000\\000\\002\"\nlock_version: 454344339710803970\nkey: \"t\\200\\000\\000\\000\\000\\000\\000r_r\\003\\200\\000\\000\\000\\000\\000\\000?\\003\\200\\000\\000\\000\\000\\000\\000\\002\"\nlock_ttl: 50000\ntxn_size: 1\nlock_for_update_ts: 454344339723911177\nuse_async_commit: true\nmin_commit_ts: 454344339723911179... occured and cancel the query"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=11]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [INFO] [EstablishCall.cpp:254] ["async connection for tunnel2+-1 cost 22479 ms, including 0 ms to wait task."] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2> tunnel2+-1"] [thread_id=918]
tiflash-1/server.log:[2024/12/03 08:35:45.210 +08:00] [INFO] [MPPTask.cpp:581] ["mpp task finish execute, is_success: false, status: RUNNING"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=346]
tiflash-1/server.log:[2024/12/03 08:35:45.212 +08:00] [WARN] [MPPTask.cpp:751] ["Begin abort task: MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>, abort type: ONCANCELLATION"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=143]
tiflash-1/server.log:[2024/12/03 08:35:45.212 +08:00] [WARN] [MPPTask.cpp:780] ["Finish abort task from running"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=143]
tiflash-1/server.log:[2024/12/03 08:35:45.212 +08:00] [INFO] [MPPTask.cpp:155] ["finish MPPTask: MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [source="MPP<gather_id:1, query_ts:1733186122728528755, local_query_id:361, server_id:862, start_ts:454344342948282369,task_id:2>"] [thread_id=346]

[JaySon-Huang]

similar logic for retrying in tidb : https://github.com/pingcap/tidb/blob/f347b9d334495c72d27c53532dfef522213dbaac/pkg/store/copr/coprocessor.go#L1660