BR: crash during backup database and output error of `resolve lock timeout`
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## General Question
original problem addr : https://asktug.com/t/topic/996049 and https://asktug.com/t/topic/993622 (the same problem, including BR log and clinic info)
1. look at the log ,we can see `failed to send fine-grained backup` when BR was doing the range-sn=5704 backup.
```
cat full_20221116.log|grep "range-sn=5704"|less
[2022/11/16 12:44:46.368 +08:00] [INFO] [client.go:594] ["backup started"] [range-sn=5704] [startKey=7480000000000039C85F69800000000000000100] [endKey=7480000000000039C85
F698000000000000001FB] [rateLimit=0] [concurrency=4]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=6] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=50288812] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=50288813] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=4] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=50288810] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=50288809] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=50288811] ["retry time"=0]
[2022/11/16 12:44:46.369 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] [store-id=5] ["retry time"=0]
......
......
[2022/11/16 13:35:02.543 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] ["retry time"=2]
[2022/11/16 13:35:02.545 +08:00] [INFO] [client.go:1041] ["try backup"] [range-sn=5704] ["retry time"=4]
[2022/11/16 13:35:02.560 +08:00] [WARN] [client.go:922] ["reset the connection in handleFineGrained"] [range-sn=5704] [storeID=50288811]
[2022/11/16 13:35:02.560 +08:00] [ERROR] [client.go:932] ["failed to send fine-grained backup"] [range-sn=5704] [storeID=50288811] [error="failed to reset backup connection on store:50288811 please check the tikv status: context canceled"] [stack="github.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:932\ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:737"]
[2022/11/16 13:35:02.560 +08:00] [INFO] [client.go:588] ["backup range finished"] [range-sn=5704] [take=50m16.191448474s]
[2022/11/16 13:35:05.538 +08:00] [WARN] [client.go:922] ["reset the connection in handleFineGrained"] [range-sn=5704] [storeID=50288811]
[2022/11/16 13:35:05.539 +08:00] [ERROR] [client.go:932] ["failed to send fine-grained backup"] [range-sn=5704] [storeID=50288811] [error="failed to reset backup connection on store:50288811 please check the tikv status: context canceled"] [stack="github.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:932\ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:737"]
[2022/11/16 13:35:05.544 +08:00] [WARN] [client.go:922] ["reset the connection in handleFineGrained"] [range-sn=5704] [storeID=50288811]
[2022/11/16 13:35:05.544 +08:00] [ERROR] [client.go:932] ["failed to send fine-grained backup"] [range-sn=5704] [storeID=50288811] [error="failed to reset backup connection on store:50288811 please check the tikv status: context canceled"] [stack="github.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:932\ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:737"]
[2022/11/16 13:35:05.546 +08:00] [WARN] [client.go:922] ["reset the connection in handleFineGrained"] [range-sn=5704] [storeID=50288811]
[2022/11/16 13:35:05.546 +08:00] [ERROR] [client.go:932] ["failed to send fine-grained backup"] [range-sn=5704] [storeID=50288811] [error="failed to reset backup connection on store:50288811 please check the tikv status: context canceled"] [stack="github.com/pingcap/tidb/br/pkg/backup.(*Client).handleFineGrained\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:932\ngithub.com/pingcap/tidb/br/pkg/backup.(*Client).fineGrainedBackup.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/br/br/pkg/backup/client.go:737"]
```
2. and we can see the warn-log of `txnLockFast backoffer.maxSleep 80000ms is exceeded`
```
[2022/11/16 13:35:02.547 +08:00] [WARN] [backoff.go:158] ["txnLockFast backoffer.maxSleep 80000ms is exceeded, errors:\n[BR:Common:ErrUnknown]internal error at 2022-11-16T13:34:05.527343742+08:00\n[BR:Common:ErrUnknown]internal error at 2022-11-16T13:34:26.528966798+08:00\n[BR:Common:ErrUnknown]internal error at 2022-11-16T13:34:44.563046299+08:00\nlongest sleep type: txnLockFast, time: 80305ms"]
```
3. however, when i searched some tikv log in clinic, i discovered some confused things
a. some primary key locked log in the TiKV log of clinic.

b. but, after decoding the primary key, no functions from application will cross between table of primary key error and backup table(range-sn : 5704)
```
Time cluster_id component message
Nov 16, 2022 @ 13:57:56.027 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F6980000000000000020380000000000044AD lock_version: 437407783577190475 key: 7480000000000000155F698000000000000001040611FC0FCA1C004B03800000000028BEA1 lock_ttl: 3003 txn_size: 2 lock_for_update_ts: 437407783577190475 min_commit_ts: 437407783577190476"]
Nov 16, 2022 @ 13:55:02.477 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000079675F698000000000000005038000000000000002037FFFFFFFFFFFFFFF03800000000000000003800000000000001E0419AE60C97400000003800000000328A9C3 lock_version: 437407737937920025 key: 7480000000000079675F698000000000000006038000000000000002037FFFFFFFFFFFFFFF0003800000000000001E0419AE60C97400000003800000000328A9C3 lock_ttl: 3001 txn_size: 1 min_commit_ts: 437407737937920026"]
Nov 16, 2022 @ 13:53:56.028 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000003843 lock_version: 437407720662630479 key: 7480000000000000155F698000000000000001040611FC01241C004F03800000000024A218 lock_ttl: 3004 txn_size: 4 lock_for_update_ts: 437407720662630479 min_commit_ts: 437407720662630480"]
Nov 16, 2022 @ 13:47:56.018 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000175F7280000000010C0BDE lock_version: 437407626303897605 key: 7480000000000000175F7280000000010C0BDE lock_ttl: 3003 txn_size: 4 min_commit_ts: 437407626303897606"]
Nov 16, 2022 @ 13:46:56.035 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000175F728000000001156EB6 lock_version: 437407610575257606 key: 7480000000000000175F728000000001156EB6 lock_ttl: 5661 txn_size: 27 min_commit_ts: 437407610575257607"]
Nov 16, 2022 @ 13:46:56.035 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000175F728000000001156EB6 lock_version: 437407610575257606 key: 7480000000000000175F728000000001156ED7 lock_ttl: 5661 txn_size: 12 min_commit_ts: 437407610575257607"]
Nov 16, 2022 @ 13:46:56.028 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000004376 lock_version: 437407610562150456 key: 7480000000000000155F698000000000000001040611FBE7819C0038038000000000258C4F lock_ttl: 3005 txn_size: 4 lock_for_update_ts: 437407610562150456 min_commit_ts: 437407610562150457"]
Nov 16, 2022 @ 13:45:56.029 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000003C2F lock_version: 437407594833510478 key: 7480000000000000155F72800000000028C06C lock_ttl: 20001 txn_size: 2 lock_for_update_ts: 437407594833510478 min_commit_ts: 437407594833510479"]
Nov 16, 2022 @ 13:40:03.213 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000079675F69800000000000000503800000000000000203800000000000000003800000000000000003800000000000001E0419AE60C98700000003800000000328B394 lock_version: 437407502204928044 key: 7480000000000079675F69800000000000000503800000000000000203800000000000000003800000000000000003800000000000001E0419AE60C98700000003800000000328B394 lock_ttl: 3001 txn_size: 1 lock_type: Del min_commit_ts: 437407502204928045"]
Nov 16, 2022 @ 13:39:56.020 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000175F72800000000115ED65 lock_version: 437407500474777607 key: 7480000000000000175F72800000000115ED6C lock_ttl: 3360 txn_size: 5 min_commit_ts: 437407500474777608"]
Nov 16, 2022 @ 13:24:56.034 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000175F72800000000112A837 lock_version: 437407264545177607 key: 7480000000000000175F72800000000112A83F lock_ttl: 3514 txn_size: 2 min_commit_ts: 437407264545177608"]
Nov 16, 2022 @ 13:11:21.789 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000004371 lock_version: 437407048158412856 key: 7480000000000000155F72800000000028731E lock_ttl: 25945 txn_size: 66 lock_type: Del lock_for_update_ts: 437407051055104097 min_commit_ts: 437407051055104098"]
Nov 16, 2022 @ 13:11:21.765 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000004371 lock_version: 437407048158412856 key: 7480000000000000155F698000000000000001040611FB63BE5C009B03800000000028731E lock_ttl: 25945 txn_size: 2 lock_type: Del lock_for_update_ts: 437407051055104097 min_commit_ts: 437407051055104098"]
Nov 16, 2022 @ 13:11:21.122 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F6980000000000000020380000000000033D5 lock_version: 437407050897817694 key: 7480000000000000155F698000000000000001040611FB65323C0015038000000000260170 lock_ttl: 3006 txn_size: 6 lock_type: Del lock_for_update_ts: 437407050897817694 min_commit_ts: 437407050897817695"]
Nov 16, 2022 @ 13:09:36.770 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F69800000000000000203800000000000354C lock_version: 437407023477555226 key: 7480000000000000175F7280000000010EF298 lock_ttl: 20039 txn_size: 1 lock_type: Del lock_for_update_ts: 437407023490662403 min_commit_ts: 437407023490662404"]
Nov 16, 2022 @ 13:09:36.121 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F69800000000000000203800000000000354C lock_version: 437407023307161751 key: 7480000000000000155F7280000000002A6AB6 lock_ttl: 20002 txn_size: 3 lock_type: Del lock_for_update_ts: 437407023320268952 min_commit_ts: 437407023320268953"]
Nov 16, 2022 @ 13:09:36.113 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F69800000000000000203800000000000354C lock_version: 437407023307161751 key: 7480000000000000155F698000000000000001040611FB5EC104002A0380000000002A6AB6 lock_ttl: 3164 txn_size: 3 lock_type: Del lock_for_update_ts: 437407023320268952 min_commit_ts: 437407023320268953"]
Nov 16, 2022 @ 13:02:56.027 6801054821581547599 tikv [endpoint.rs:621] [error-response] [err="Key is locked (will clean up) primary_lock: 7480000000000000155F698000000000000002038000000000004371 lock_version: 437406918501990522 key: 7480000000000000155F698000000000000001040611FB461564005D038000000000258C4F lock_ttl: 3004 txn_size: 4 lock_type: Del lock_for_update_ts: 437406918501990522 min_commit_ts: 437406918501990523"]
```
so, please help us to investigate the BR backup problem.🤔
that seems caused by txnLockFast, but we couldn't find which function table conflicts with the backup table of range-sn 5047.
Contributor guide
Assessment
This issue has not been assessed yet.