pingcap / pingcap/tidb

Slow log's Backoff_total item is inconsistent with backoff details

Open
#58,756 1 comment 0 reactions 1 assignee Claimed by @yibin87 View on GitHub
affects-6.1 affects-6.5 affects-7.1 affects-7.5 affects-8.1 affects-8.5 report/customer severity/moderate sig/execution type/bug
Dominant language
Go
Stars
40.5k
Forks
6.2k
PR merge metrics
PR metrics pending

Description

1. In the slow log file, the Backoff_total item is less than the Cop_backoff_regionMiss_total_time item, which is unexpected:
Cop_backoff_regionMiss_total_times: 907407 Cop_backoff_regionMiss_total_time: 2290.796 Cop_backoff_regionMiss_max_time: 8.01 Cop_backoff_regionMiss_max_addr: 214.170.4.81:20161 Cop_backoff_regionMiss_avg_time: 0.002532962 Cop_backoff_regionMiss_p90_time: 0.002
Backoff_total: 1892.664

From the client-go code, it seems the bo's context lacks "util.ExecDetailsKey" in some situation:
https://github.com/tikv/client-go/blob/2eba2f614b38e2905cc46ea8f0fc6d40ed6a0ccf/config/retry/backoff.go#L207-L218

BTW, checked that tidb coprocessor won't lose bo info when error happened: tidb coprocessor will update the bo and rpcCtx info even when error happened:
https://github.com/pingcap/tidb/blob/a847b740641bbcd7f9703f276acac23afda92611/pkg/store/copr/coprocessor.go#L1433
And this info will be used when selectResult is closed:
https://github.com/pingcap/tidb/blob/a847b740641bbcd7f9703f276acac23afda92611/pkg/distsql/select_result.go#L607-L615
One suspicious issue that may cause backoff info lost is: https://github.com/pingcap/tidb/issues/60271

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.