executer: add Cop_time in slow log

[crazycs520]

What problem does this PR solve?

Before this PR, TiDB Slow log only record Process_time, but it is the total process time of cop task spend on TiKV, we still don't know the related Cop_time spend in tidb, as below:

What is changed and how it works?

Add Cop_time in slow_query and slow log. The Cop_time contain the time duration as below:

• Send Cop request.
• Send request to TiKV network latency duration.
• TiKV handle cop request duration.
• Send result to TiDB network latency.
• Recieve result latency.
• If meet error, maybe retry upper steps.

mysql>select query_time,cop_time,query from `CLUSTER_SLOW_QUERY` where cop_time>0 limit 3;
+-------------+-------------+---------------------------------------------------------------------------------------------------+
| query_time  | cop_time    | query                                                                                             |
+-------------+-------------+---------------------------------------------------------------------------------------------------+
| 0.382663125 | 0.382427668 | select count(*) from t2;                                                                          |
| 0.329472658 | 0.329190264 | select count(*) from t2;                                                                          |
| 0.929105778 | 0.400684833 | select count(*) from t2 where c2 >=0 and c1 in (select c1 from t2 where c7!=now()) and c8!=now(); |
+-------------+-------------+---------------------------------------------------------------------------------------------------+

Related changes

• Need to cherry-pick to the release branch

Check List

Tests

• Unit test

Side effects

• Performance regression
  • Consumes more CPU
  • Consumes more MEM

Release note

[codecov]

Codecov Report

Merging #16873 into master will decrease coverage by 0.1124%.
The diff coverage is 90.0000%.

@@               Coverage Diff                @@
##             master     #16873        +/-   ##
================================================
- Coverage   80.4616%   80.3491%   -0.1125%     
================================================
  Files           507        507                
  Lines        137913     137409       -504     
================================================
- Hits         110967     110407       -560     
- Misses        18295      18338        +43     
- Partials       8651       8664        +13     

[crazycs520]

/rebuild

[SunRunAway]

I think that's a great approaching, would cop_time be involved in statement summary table?

[crazycs520]

@SunRunAway Ye, maybe in next PR add cop_time to statement summary table.

[qw4990]

@crazycs520 Should we cherry pick this PR to 4.0?

[crazycs520]

@qw4990 Yes, I want to cherry-pick to 4.0.

[SunRunAway]

LGTM

[SunRunAway]

@crazycs520 we should add documentation update in Related changes section.

[qw4990]

LGTM

[sre-bot]

/run-all-tests

[djshow832]

Is it compatible with the older versions?
e.g. Older version reads slow log in newer version.
Or, newer version reads slow log in older version.

[djshow832]

Did you discuss the name with PM? I think the name is confusing, I don't know whether it's time consumed in TiDB or TiKV or both by the name. I can only read the document to figure it out.

[sre-bot]

@crazycs520 merge failed.

[crazycs520]

@djshow832, It's ok, new version can still read the old version tidb slow log, and old version can read the new tidb slow log, but can't read the Cop_time field value.

[crazycs520]

/run-integration-copr-test

[crazycs520]

/run-unit-test

[sre-bot]

cherry pick to release-4.0 in PR #16904

[SunRunAway]

@crazycs520 Please update the documentation.