*: add HTTP API to generate TiDB metric profile

[crazycs520]

What problem does this PR solve?

TiDB has thousands of metrics, it is hard to know the related metric for users. This PR try to generate a metric profile SVG to describe the total time consumption of related metric in a specified time range.

Below is an example:

curl "127.0.0.1:10080/metrics/profile?start=2020-06-29T22:00:00%2B08:00&end=2020-06-29T22:20:00%2B08:00" > profile.dot

dot -Tsvg -o profile.svg profile.dot

The start and end use to specify the time range, the time format is RFC3339(2006-01-02T15:04:05Z07:00).

The profile.svg look like as below:

From the upper profile SVG, it's easy to see the time consumption ratio of each metric and the relationship between metrics.

Explain

This profile style, color, and format are very similar to the golang pprof profile.

Node

• tidb_execute: it was the metric name, tidb_execute means the consuming time that spends on TiDB execution.
• 20924.55s (30.51%) of 64938.09s (94.68%):
  • 20924.55s(30.51%) means tidb_execute it self consumes 20924.55 seconds, take up 30.51% of the total time.
  • 64938.09s (94.68%) means tidb_execute itself and all children consume 64938.09 seconds, take up 94.68% of the total time. So, all the children of tidb_execution consume 64938.09-20924.55=44013.54 seconds.

Maybe we can add more information about the metric in this node, such as avg_P99, avg_P80,total_count ...

Edge

The edge from tidb_txn_cmd to tidb_txn_cmd.get has comment with 17311.60s, it means 17311.60 seconds was consumed after this edge.

You must found that edges such as the edge from tidb_txn_cmd to tidb_kv_request, the edge line is dotted, and there is no comment to indicate how much time was consume by its child. This is because the child such as tidb_kv_request may have multiple parents, I only know the total time consumed by tidb_kv_request, I don't know the time consumed that after the dotted edge.

Attention

Currently, the total time was the tidb_query, so the total time of tidb_query and its children consumed was 100%.

Sometimes, you may found the nodes such as tidb_kv_request , itself and its children consume time more than the tidb_query total time. this is because 1 tidb_query may have many kv requests, and those kv requests may be executed concurrently.

For some metric that the total value was less than 0.01% of the total time, the metric will not display in the profile SVG.

Example in different workload

• Calculate Cartesian join of two tables

• Too much write conflict in update

• TiKV disk io is the bottleneck when insert

What is changed and how it works?

Each node in the profile has a corresponding metric, such as the metric of tidb_query is tidb_server_handle_query_duration_seconds.

Related changes

• PR to update pingcap/docs/pingcap/docs-cn:

Check List

Tests

• Manual test (add detailed scripts or steps below)

Side effects

• No

Release note

• Add HTTP API to generate TiDB metric profile.

[codecov]

Codecov Report

Merging #18272 into master will increase coverage by 0.3034%.
The diff coverage is 74.2857%.

@@               Coverage Diff                @@
##             master     #18272        +/-   ##
================================================
+ Coverage   79.4482%   79.7517%   +0.3034%     
================================================
  Files           540        541         +1     
  Lines        144455     147598      +3143     
================================================
+ Hits         114767     117712      +2945     
- Misses        20415      20623       +208     
+ Partials       9273       9263        -10     

[crazycs520]

@wjhuang2016 @AilinKid PTAL

[wjhuang2016]

LGTM

[ti-srebot]

@wjhuang2016,Thanks for your review.

[AilinKid]

LGTM

[ti-srebot]

cherry pick to release-4.0 in PR #18531