need to change TIME_COP_PROCESS to TIME_COP_WAIT · pingcap/tidb#7044

2018-07-12T15:55:24.000Z

Take this log as an example: ```sql 2018/07/12 23:40:03.287 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:11.9717251s txn_start_ts:401449940753055943 region_id:2 store_addr:10.0.1.5:20160 kv_process_ms:1702 scan_total_write:692145 scan_processed_write:692144 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0 kv_wait_ms:10264 ``` - `kv_wait_ms`: 10264ms - `kv_process_ms`: 1702ms `kv_wait_ms` is far more larger than `kv_process_ms` and this slow coprocessor task is mainly caused by the wait, but we still printed the `TIME_COP_PROCESS`. The source code to log this entry is here in file **store/tikv/coprocessor.go**: ```go 659 if waitMs > minLogKVWaitTime { 660 logStr += fmt.Sprintf(" kv_wait_ms:%d", waitMs) 661 if processMs `kv_process_ms`

(7 留言) (0 反應) (0 負責人)Go (40,090 star) (6,186 fork)batch import

epic/slow-querygood first issuehelp wantedsig/executiontype/enhancement

描述

Take this log as an example:

2018/07/12 23:40:03.287 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:11.9717251s txn_start_ts:401449940753055943 region_id:2 store_addr:10.0.1.5:20160 kv_process_ms:1702 scan_total_write:692145 scan_processed_write:692144 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0 kv_wait_ms:10264

kv_wait_ms: 10264ms
kv_process_ms: 1702ms

kv_wait_ms is far more larger than kv_process_ms and this slow coprocessor task is mainly caused by the wait, but we still printed the TIME_COP_PROCESS.

The source code to log this entry is here in file store/tikv/coprocessor.go:

659         if waitMs > minLogKVWaitTime {
660             logStr += fmt.Sprintf(" kv_wait_ms:%d", waitMs)
661             if processMs <= minLogKVProcessTime {
662                 logStr = strings.Replace(logStr, "TIME_COP_PROCESS", "TIME_COP_WAIT", 1)
663             }
664         }

We should change TIME_COP_PROCESS to TIME_COP_WAIT when kv_wait_ms > kv_process_ms

貢獻者指南

技術棧: go
領域: backenddatabase
議題類型: bug
難度: 2
預計時間: under 1 hour
活動狀態: stale
清晰度: clear
前置要求: basic Go knowledge
新手友善度: 70
研究方向: Modify the condition in store/tikv/coprocessor.go at line 661 to change TIME COP PROCESS to TIME COP WAIT when kv wait ms exceeds kv process ms. Currently, the log shows TIME COP PROCESS even when wait time dominates. The fix requires adjusting the log string replacement logic to reflect the dominant factor.