execdetails: output write details in RuntimeStats #35814

sticnarf · 2022-06-29T07:05:39Z

Signed-off-by: Yilin Chen sticnarf@gmail.com

What problem does this PR solve?

Issue Number: ref #34487

What is changed and how it works?

Now, TiKV returns the detailed time breakdown of write requests. This PR outputs the returned results and output them in the runtime stats or slow query logs.

Now a slow log of a commit will contain more information, it will look like:

# Prewrite_time: 0.001431165 Get_latest_ts_time: 0.000137354 Slowest_commit_rpc_detail: {total:0.001s, region_id: 2, store: 127.0.0.1:20160, tikv_wall_time: 1.19ms, scan_detail: {get_snapshot_time: 21.3µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 9.16µs, propose_send_wait: 0s, persist_log: {total: 830.9µs, write_leader_wait: 134ns, sync_log: 807.1µs, write_memtable: 1.79µs}, commit_log: 850.1µs, apply_batch_wait: 17.7µs, apply: {total:80.2µs, mutex_lock: 230ns, write_leader_wait: 0s, write_wal: 17.7µs, write_memtable: 14.4µs}}} Write_keys: 2 Write_size: 48 Prewrite_region: 1

A new panel showing the RPC layer latency is added

Check List

Tests

Manual test (add detailed scripts or steps below)

Documentation

Changes Slow Log Format

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

Extend slow log to show time breakdown in TiKV of write requests.

ti-chi-bot · 2022-06-29T07:05:41Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

cfzjywxk
you06

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

The full list of commands accepted by this bot can be found here.

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

you06

I found the Greek letter "µ" is not well displayed when opening with less in a develop machine, not sure if this is a problem.
rest LGTM

sticnarf · 2022-07-15T07:11:41Z

I found the Greek letter "µ" is not well displayed when opening with less in a develop machine

TiDB already uses "µs" in many places, I guess it's not a big problem...

cfzjywxk · 2022-07-18T02:56:28Z

metrics/grafana/tidb.json

+          "dashLength": 10,
+          "dashes": false,
+          "datasource": "${DS_TEST-CLUSTER}",
+          "description": "Time spent on the RPC layer between TiDB and TiKV",


Better to comment it includes tidb batch client time.

cfzjywxk · 2022-07-18T03:06:37Z

@sticnarf
Another thing is that in the decoded plan details the execution details would also be used, like

 └─StreamAgg_8               cop[tikv]        1               funcs:count(1)->Column#20                                             15              tikv_task:{proc max:1.29s, min:0s, p80:1.18s, p95:1.29s, iters:9778, tasks:17}, scan_detail: {total_process_keys: 10000000, total_process_keys_size: 890000000, total_keys: 10000017, rocksdb: {delete_skipped_count: 0, key_skipped_count: 10000000, block: {cache_hit_count: 25, read_count: 14349, read_byte: 283.9 MB}}}                 N/A             N/A
            └─IndexFullScan_19        cop[tikv]        10000000        table:T_CUSTOMER, index:PRIMARY(customer_id), keep order:false        10000000        tikv_task:{proc max:1.29s, min:0s, p80:1.18s, p95:1.29s, iters:9778, tasks:17}

For the write details added for transaction commands including prewrite, pessimistic_lock, and commit, we may also need to re-design the executor execution details and make the enhanced information match the execution flow, for example how a pessimistic lock request could slow one Next or Open operation.

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

cfzjywxk · 2022-07-18T03:07:18Z

/merge

ti-chi-bot · 2022-07-18T03:07:22Z

This pull request has been accepted and is ready to merge.

Commit hash: 21c9c4a

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

sre-bot · 2022-07-18T05:16:46Z

Code Coverage Details: https://codecov.io/github/pingcap/tidb/commit/1aa1fc228b479323ded0c9ba91abe2d8e8438199

sticnarf · 2022-07-18T05:38:56Z

/merge

ti-chi-bot · 2022-07-18T05:38:59Z

This pull request has been accepted and is ready to merge.

Commit hash: 91dd09b

sticnarf · 2022-07-18T06:07:58Z

/run-check_dev_2

sticnarf · 2022-07-18T06:31:29Z

/run-check_dev_2

sre-bot · 2022-07-18T07:38:17Z

TiDB MergeCI notify

🔴 Bad News! New failing [1] after this pr merged.
These new failed integration tests seem to be caused by the current PR, please try to fix these new failed integration tests, thanks!

CI Name	Result	Duration	Compare with Parent commit
idc-jenkins-ci-tidb/integration-ddl-test	🟥 failed 2, success 4, total 6	5 min 34 sec	New failing
idc-jenkins-ci/integration-cdc-test	✅ all 36 tests passed	31 min	Fixed
idc-jenkins-ci-tidb/integration-common-test	✅ all 11 tests passed	28 min	Fixed
idc-jenkins-ci-tidb/common-test	🟢 all 12 tests passed	13 min	Existing passed
idc-jenkins-ci-tidb/sqllogic-test-1	🟢 all 26 tests passed	8 min 25 sec	Existing passed
idc-jenkins-ci-tidb/sqllogic-test-2	🟢 all 28 tests passed	6 min 30 sec	Existing passed
idc-jenkins-ci-tidb/tics-test	🟢 all 1 tests passed	6 min 5 sec	Existing passed
idc-jenkins-ci-tidb/mybatis-test	🟢 all 1 tests passed	3 min 3 sec	Existing passed
idc-jenkins-ci-tidb/integration-compatibility-test	🟢 all 1 tests passed	2 min 53 sec	Existing passed
idc-jenkins-ci-tidb/plugin-test	🟢 build success, plugin test success	4min	Existing passed

)" This reverts commit df31ac6.

sticnarf mentioned this pull request Jun 29, 2022

*: set write and time details in RPC responses tikv/tikv#12900

Merged

ti-chi-bot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Jul 4, 2022

sticnarf force-pushed the more-write-detail branch from 1fb16e5 to 9c1aad7 Compare July 7, 2022 05:59

ti-chi-bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Jul 7, 2022

sticnarf force-pushed the more-write-detail branch 2 times, most recently from 2ce3416 to 5684893 Compare July 7, 2022 06:28

sticnarf force-pushed the more-write-detail branch from 2fa2f95 to 6240bf6 Compare July 14, 2022 07:29

ti-chi-bot removed the do-not-merge/needs-linked-issue label Jul 14, 2022

sticnarf changed the title ~~[DNM] execdetails: add write details from TiKV~~ execdetails: output write details in RuntimeStats Jul 14, 2022

ti-chi-bot added release-note Denotes a PR that will be considered when it comes time to generate release notes. and removed release-note-none Denotes a PR that doesn't merit a release note. labels Jul 14, 2022

sticnarf force-pushed the more-write-detail branch from 6240bf6 to 22120b8 Compare July 14, 2022 08:08

execdetails: output write details in RuntimeStats

60b28d5

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

sticnarf force-pushed the more-write-detail branch from 22120b8 to 60b28d5 Compare July 14, 2022 09:15

sticnarf requested a review from you06 July 14, 2022 09:26

sticnarf marked this pull request as ready for review July 14, 2022 09:26

ti-chi-bot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Jul 14, 2022

you06 reviewed Jul 15, 2022

View reviewed changes

Merge branch 'master' into more-write-detail

21c9c4a

you06 approved these changes Jul 15, 2022

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Jul 15, 2022

cfzjywxk approved these changes Jul 18, 2022

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Jul 18, 2022

sticnarf added 2 commits July 18, 2022 11:06

comment that the time includes batch client time

35407d4

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

Merge remote-tracking branch 'upstream/master' into more-write-detail

2a42324

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 18, 2022

sticnarf force-pushed the more-write-detail branch from 017e2a4 to 2a42324 Compare July 18, 2022 03:08

ti-chi-bot removed the status/can-merge Indicates a PR has been approved by a committer. label Jul 18, 2022

sticnarf added 2 commits July 18, 2022 11:47

Put write detail to lock rpc detail

5c93cf2

Signed-off-by: Yilin Chen <sticnarf@gmail.com>

Merge branch 'master' into more-write-detail

91dd09b

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 18, 2022

Merge branch 'master' into more-write-detail

16e923a

Merge branch 'master' into more-write-detail

f0663ce

Merge branch 'master' into more-write-detail

1aa1fc2

ti-chi-bot merged commit df31ac6 into pingcap:master Jul 18, 2022

sticnarf mentioned this pull request Jul 21, 2022

GetExecDetailsV2 may waste lots of CPU to format error #36395

Closed

lcwangchao added a commit to lcwangchao/tidb that referenced this pull request Aug 8, 2022

Revert "execdetails: output write details in RuntimeStats (pingcap#35814

5e30088

)" This reverts commit df31ac6.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

execdetails: output write details in RuntimeStats #35814

execdetails: output write details in RuntimeStats #35814

sticnarf commented Jun 29, 2022 •

edited

Loading

ti-chi-bot commented Jun 29, 2022 •

edited

Loading

you06 left a comment

sticnarf commented Jul 15, 2022

cfzjywxk Jul 18, 2022

cfzjywxk commented Jul 18, 2022 •

edited

Loading

cfzjywxk commented Jul 18, 2022

ti-chi-bot commented Jul 18, 2022

sre-bot commented Jul 18, 2022 •

edited

Loading

sticnarf commented Jul 18, 2022

ti-chi-bot commented Jul 18, 2022

sticnarf commented Jul 18, 2022

sticnarf commented Jul 18, 2022

sre-bot commented Jul 18, 2022

execdetails: output write details in RuntimeStats #35814

execdetails: output write details in RuntimeStats #35814

Conversation

sticnarf commented Jun 29, 2022 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Jun 29, 2022 • edited Loading

you06 left a comment

Choose a reason for hiding this comment

sticnarf commented Jul 15, 2022

cfzjywxk Jul 18, 2022

Choose a reason for hiding this comment

cfzjywxk commented Jul 18, 2022 • edited Loading

cfzjywxk commented Jul 18, 2022

ti-chi-bot commented Jul 18, 2022

sre-bot commented Jul 18, 2022 • edited Loading

sticnarf commented Jul 18, 2022

ti-chi-bot commented Jul 18, 2022

sticnarf commented Jul 18, 2022

sticnarf commented Jul 18, 2022

sre-bot commented Jul 18, 2022

TiDB MergeCI notify

sticnarf commented Jun 29, 2022 •

edited

Loading

ti-chi-bot commented Jun 29, 2022 •

edited

Loading

cfzjywxk commented Jul 18, 2022 •

edited

Loading

sre-bot commented Jul 18, 2022 •

edited

Loading