Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

distsql,util: Add executor open close time into its total consume time #56236

Merged
merged 10 commits into from
Nov 18, 2024

Conversation

yibin87
Copy link
Contributor

@yibin87 yibin87 commented Sep 23, 2024

What problem does this PR solve?

Issue Number: close #56233 ref #56232

Problem Summary:
Some executors' open or close operation may take too much time, thus we'd probably record these time in execution summary.
#55957 provides an example that table reader operator's open takes much time while not included.
#50377 provides an example that limit operator's close takes much time while not included.

What changed and how does it work?

TPCH Q3 TiFlash

+--------------------------------------------------------------------+------------+---------+--------------+----------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------+---------+
| id                                                                 | estRows    | actRows | task         | access object  | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | operator info                                                                                                                                                                                                                                                                                                                                          | memory  | disk    |
+--------------------------------------------------------------------+------------+---------+--------------+----------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------+---------+
| Projection_14                                                      | 10.00      | 10      | root         |                | time:241.4ms, open:1.75ms, loops:2, RU:2571.659780, Concurrency:OFF                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           | test.lineitem.l_orderkey, Column#34, test.orders.o_orderdate, test.orders.o_shippriority                                                                                                                                                                                                                                                               | 2.52 KB | N/A     |
| └─TopN_18                                                          | 10.00      | 10      | root         |                | time:241.4ms, open:1.75ms, loops:2                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            | Column#34:desc, test.orders.o_orderdate, offset:0, count:10                                                                                                                                                                                                                                                                                            | 1.23 KB | 0 Bytes |
|   └─TableReader_92                                                 | 10.00      | 80      | root         |                | time:241.3ms, open:1.72ms, loops:3, cop_task: {num: 9, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        | MppVersion: 2, data:ExchangeSender_91                                                                                                                                                                                                                                                                                                                  | 2.97 KB | N/A     |
|     └─ExchangeSender_91                                            | 10.00      | 80      | mpp[tiflash] |                | tiflash_task:{time:237.3ms, loops:8, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | ExchangeType: PassThrough                                                                                                                                                                                                                                                                                                                              | N/A     | N/A     |
|       └─TopN_90                                                    | 10.00      | 80      | mpp[tiflash] |                | tiflash_task:{time:236.9ms, loops:8, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | Column#34:desc, test.orders.o_orderdate, offset:0, count:10                                                                                                                                                                                                                                                                                            | N/A     | N/A     |
|         └─Projection_86                                            | 756.40     | 11479   | mpp[tiflash] |                | tiflash_task:{time:236.5ms, loops:8, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | Column#34, test.orders.o_orderdate, test.orders.o_shippriority, test.lineitem.l_orderkey                                                                                                                                                                                                                                                               | N/A     | N/A     |
|           └─HashAgg_87                                             | 756.40     | 11479   | mpp[tiflash] |                | tiflash_task:{time:236.5ms, loops:8, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | group by:test.lineitem.l_orderkey, test.orders.o_orderdate, test.orders.o_shippriority, funcs:sum(Column#43)->Column#34, funcs:firstrow(test.orders.o_orderdate)->test.orders.o_orderdate, funcs:firstrow(test.orders.o_shippriority)->test.orders.o_shippriority, funcs:firstrow(test.lineitem.l_orderkey)->test.lineitem.l_orderkey, stream_count: 8 | N/A     | N/A     |
|             └─ExchangeReceiver_89                                  | 756.40     | 11479   | mpp[tiflash] |                | tiflash_task:{time:236ms, loops:8, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 | stream_count: 8                                                                                                                                                                                                                                                                                                                                        | N/A     | N/A     |
|               └─ExchangeSender_88                                  | 756.40     | 11479   | mpp[tiflash] |                | tiflash_task:{time:233.6ms, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | ExchangeType: HashPartition, Compression: FAST, Hash Cols: [name: test.lineitem.l_orderkey, collate: binary], [name: test.orders.o_orderdate, collate: binary], [name: test.orders.o_shippriority, collate: binary], stream_count: 8                                                                                                                   | N/A     | N/A     |
|                 └─HashAgg_84                                       | 756.40     | 11479   | mpp[tiflash] |                | tiflash_task:{time:232.4ms, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | group by:Column#48, Column#49, Column#50, funcs:sum(Column#47)->Column#43                                                                                                                                                                                                                                                                              | N/A     | N/A     |
|                   └─Projection_93                                  | 756.40     | 30266   | mpp[tiflash] |                | tiflash_task:{time:226.3ms, loops:97, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              | mul(test.lineitem.l_extendedprice, minus(1, test.lineitem.l_discount))->Column#47, test.lineitem.l_orderkey->Column#48, test.orders.o_orderdate->Column#49, test.orders.o_shippriority->Column#50                                                                                                                                                      | N/A     | N/A     |
|                     └─Projection_73                                | 756.40     | 30266   | mpp[tiflash] |                | tiflash_task:{time:224.2ms, loops:97, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              | test.orders.o_orderdate, test.orders.o_shippriority, test.lineitem.l_orderkey, test.lineitem.l_extendedprice, test.lineitem.l_discount                                                                                                                                                                                                                 | N/A     | N/A     |
|                       └─HashJoin_72                                | 756.40     | 30266   | mpp[tiflash] |                | tiflash_task:{time:223.6ms, loops:97, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              | inner join, equal:[eq(test.orders.o_orderkey, test.lineitem.l_orderkey)]                                                                                                                                                                                                                                                                               | N/A     | N/A     |
|                         ├─ExchangeReceiver_41(Build)               | 187.50     | 144399  | mpp[tiflash] |                | tiflash_task:{time:73.5ms, loops:14, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               |                                                                                                                                                                                                                                                                                                                                                        | N/A     | N/A     |
|                         │ └─ExchangeSender_40                      | 187.50     | 144399  | mpp[tiflash] |                | tiflash_task:{time:73.8ms, loops:24, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | ExchangeType: Broadcast, Compression: FAST                                                                                                                                                                                                                                                                                                             | N/A     | N/A     |
|                         │   └─Projection_39                        | 187.50     | 144399  | mpp[tiflash] |                | tiflash_task:{time:73.5ms, loops:24, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | test.orders.o_orderkey, test.orders.o_orderdate, test.orders.o_shippriority                                                                                                                                                                                                                                                                            | N/A     | N/A     |
|                         │     └─HashJoin_32                        | 187.50     | 144399  | mpp[tiflash] |                | tiflash_task:{time:73.5ms, loops:24, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | inner join, equal:[eq(test.customer.c_custkey, test.orders.o_custkey)]                                                                                                                                                                                                                                                                                 | N/A     | N/A     |
|                         │       ├─ExchangeReceiver_36(Build)       | 150.00     | 29752   | mpp[tiflash] |                | tiflash_task:{time:15.6ms, loops:3, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                |                                                                                                                                                                                                                                                                                                                                                        | N/A     | N/A     |
|                         │       │ └─ExchangeSender_35              | 150.00     | 29752   | mpp[tiflash] |                | tiflash_task:{time:15.4ms, loops:3, threads:8}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | ExchangeType: Broadcast, Compression: FAST                                                                                                                                                                                                                                                                                                             | N/A     | N/A     |
|                         │       │   └─TableFullScan_33             | 150.00     | 29752   | mpp[tiflash] | table:customer | tiflash_task:{time:14.8ms, loops:3, threads:8}, tiflash_scan:{mvcc_input_rows:0, mvcc_input_bytes:0, mvcc_output_rows:0, lm_skip_rows:0, local_regions:1, remote_regions:0, tot_learner_read:1ms, region_balance:{instance_num: 1, max/min: 1/1=1.000000}, delta_rows:0, delta_bytes:0, segments:1, stale_read_regions:0, tot_build_snapshot:0ms, tot_build_bitmap:0ms, tot_build_inputstream:1ms, min_local_stream:9ms, max_local_stream:10ms, dtfile:{data_scanned_rows:150000, data_skipped_rows:0, mvcc_scanned_rows:0, mvcc_skipped_rows:0, lm_filter_scanned_rows:150000, lm_filter_skipped_rows:0, tot_rs_index_check:0ms, tot_read:5ms}}              | pushed down filter:eq(test.customer.c_mktsegment, "AUTOMOBILE"), keep order:false, stats:partial[c_mktsegment:unInitialized]                                                                                                                                                                                                                           | N/A     | N/A     |
|                         │       └─TableFullScan_37(Probe)          | 521300.73  | 726007  | mpp[tiflash] | table:orders   | tiflash_task:{time:68.1ms, loops:24, threads:8}, tiflash_scan:{mvcc_input_rows:0, mvcc_input_bytes:0, mvcc_output_rows:0, lm_skip_rows:0, local_regions:1, remote_regions:0, tot_learner_read:1ms, region_balance:{instance_num: 1, max/min: 1/1=1.000000}, delta_rows:0, delta_bytes:0, segments:3, stale_read_regions:0, tot_build_snapshot:0ms, tot_build_bitmap:0ms, tot_build_inputstream:3ms, min_local_stream:60ms, max_local_stream:63ms, dtfile:{data_scanned_rows:1500000, data_skipped_rows:0, mvcc_scanned_rows:0, mvcc_skipped_rows:0, lm_filter_scanned_rows:1500000, lm_filter_skipped_rows:0, tot_rs_index_check:1ms, tot_read:51ms}}         | pushed down filter:lt(test.orders.o_orderdate, 1995-03-13 00:00:00.000000), keep order:false, stats:partial[o_orderdate:unInitialized, ID 13:unInitialized]                                                                                                                                                                                            | N/A     | N/A     |
|                         └─TableFullScan_42(Probe)                  | 2148052.67 | 3246843 | mpp[tiflash] | table:lineitem | tiflash_task:{time:193.8ms, loops:97, threads:8}, tiflash_scan:{mvcc_input_rows:0, mvcc_input_bytes:0, mvcc_output_rows:0, lm_skip_rows:0, local_regions:5, remote_regions:0, tot_learner_read:1ms, region_balance:{instance_num: 1, max/min: 5/5=1.000000}, delta_rows:0, delta_bytes:0, segments:11, stale_read_regions:0, tot_build_snapshot:0ms, tot_build_bitmap:11ms, tot_build_inputstream:31ms, min_local_stream:170ms, max_local_stream:189ms, dtfile:{data_scanned_rows:6001215, data_skipped_rows:0, mvcc_scanned_rows:0, mvcc_skipped_rows:0, lm_filter_scanned_rows:6001215, lm_filter_skipped_rows:0, tot_rs_index_check:16ms, tot_read:627ms}} | pushed down filter:gt(test.lineitem.l_shipdate, 1995-03-13 00:00:00.000000), keep order:false, stats:partial[l_shipdate:unInitialized, ID 28:unInitialized]                                                                                                                                                                                            | N/A     | N/A     |
+--------------------------------------------------------------------+------------+---------+--------------+----------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------+---------+

Check List

Tests

  • Unit test
  • Integration test
  • Manual test (add detailed scripts or steps below)
  • No need to test
    • I checked and no code files have been changed.

Side effects

  • Performance regression: Consumes more CPU
  • Performance regression: Consumes more Memory
  • Breaking backward compatibility

Documentation

  • Affects user behaviors
  • Contains syntax changes
  • Contains variable changes
  • Contains experimental features
  • Changes MySQL compatibility

Release note

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

None

@ti-chi-bot ti-chi-bot bot added release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Sep 23, 2024
Copy link

tiprow bot commented Sep 23, 2024

Hi @yibin87. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

@yibin87 yibin87 changed the title util: Add executor open close time into its total consume time distsql,util: Add executor open close time into its total consume time Sep 23, 2024
Copy link

codecov bot commented Sep 23, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 73.5566%. Comparing base (a22b842) to head (81925f2).
Report is 7 commits behind head on master.

Additional details and impacted files
@@               Coverage Diff                @@
##             master     #56236        +/-   ##
================================================
+ Coverage   72.8488%   73.5566%   +0.7078%     
================================================
  Files          1672       1672                
  Lines        462666     463743      +1077     
================================================
+ Hits         337047     341114      +4067     
+ Misses       104821     101851      -2970     
+ Partials      20798      20778        -20     
Flag Coverage Δ
integration 43.3735% <100.0000%> (?)
unit 72.3820% <100.0000%> (+0.1603%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Components Coverage Δ
dumpling 52.7673% <ø> (ø)
parser ∅ <ø> (∅)
br 45.1471% <ø> (+0.0245%) ⬆️

yibin added 6 commits November 18, 2024 14:21
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
@yibin87 yibin87 force-pushed the add_executor_open_close_time branch from ead70f8 to 0bf614c Compare November 18, 2024 06:22
yibin added 2 commits November 18, 2024 14:36
Signed-off-by: yibin <huyibin@pingcap.cn>
Signed-off-by: yibin <huyibin@pingcap.cn>
@yibin87
Copy link
Contributor Author

yibin87 commented Nov 18, 2024

/cc @windtalker

@ti-chi-bot ti-chi-bot bot requested a review from windtalker November 18, 2024 07:25
@yibin87
Copy link
Contributor Author

yibin87 commented Nov 18, 2024

/cc @guo-shaoge

@ti-chi-bot ti-chi-bot bot requested a review from guo-shaoge November 18, 2024 07:25
@ti-chi-bot ti-chi-bot bot added approved needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Nov 18, 2024
Signed-off-by: yibin <huyibin@pingcap.cn>
@ti-chi-bot ti-chi-bot bot added sig/planner SIG: Planner and removed approved labels Nov 18, 2024
@@ -430,6 +430,10 @@ func Open(ctx context.Context, e Executor) (err error) {
err = util.GetRecoverError(r)
}
}()
if e.RuntimeStats() != nil {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why not just move this into the defer function in L428

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If e.RuntimeStats() is nil, startTime won't be recorded. If move in L428, then there will be two "e.RuntimeStats() is not nil" checks, one in normal, one in defer. Not too much differences.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK

@@ -469,5 +473,9 @@ func Close(e Executor) (err error) {
err = util.GetRecoverError(r)
}
}()
if e.RuntimeStats() != nil {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ditto

Signed-off-by: yibin <huyibin@pingcap.cn>
@yibin87 yibin87 requested a review from windtalker November 18, 2024 09:36
@yibin87
Copy link
Contributor Author

yibin87 commented Nov 18, 2024

/ok-to-test

@ti-chi-bot ti-chi-bot bot added the ok-to-test Indicates a PR is ready to be tested. label Nov 18, 2024
Copy link
Contributor

@windtalker windtalker left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

@ti-chi-bot ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Nov 18, 2024
Copy link

ti-chi-bot bot commented Nov 18, 2024

[LGTM Timeline notifier]

Timeline:

  • 2024-11-18 07:39:17.848175145 +0000 UTC m=+860320.039044142: ☑️ agreed by guo-shaoge.
  • 2024-11-18 10:08:00.973553055 +0000 UTC m=+869243.164422051: ☑️ agreed by windtalker.

@yibin87
Copy link
Contributor Author

yibin87 commented Nov 18, 2024

/test pull-integration-ddl-test

Copy link

tiprow bot commented Nov 18, 2024

@yibin87: The specified target(s) for /test were not found.
The following commands are available to trigger required jobs:

  • /test fast_test_tiprow
  • /test fast_test_tiprow_ddlargsv1
  • /test tidb_parser_test

Use /test all to run the following jobs that were automatically triggered:

  • fast_test_tiprow
  • tidb_parser_test

In response to this:

/test pull-integration-ddl-test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Copy link

ti-chi-bot bot commented Nov 18, 2024

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: guo-shaoge, windtalker, winoros

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

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@ti-chi-bot ti-chi-bot bot added the approved label Nov 18, 2024
@ti-chi-bot ti-chi-bot bot merged commit e731f1b into pingcap:master Nov 18, 2024
24 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved lgtm ok-to-test Indicates a PR is ready to be tested. release-note-none Denotes a PR that doesn't merit a release note. sig/planner SIG: Planner size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Executor's total execution time doesn't include open and close time
4 participants