pingcap / pingcap/tidb

BR: crash during backup database and output error of `resolve lock timeout`

Open
#39,256 1 comment 0 reactions 0 assignees View on GitHub
type/question
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.
![image](https://user-images.githubusercontent.com/76909042/202898377-c713674d-9ca0-45ce-a1d7-b0510680337d.png)

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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.