executor: add more runtime information for join executor (#19721)

[ti-srebot]

cherry-pick #19721 to release-4.0

---

What problem does this PR solve?

Add more runtime information for below join executor:

• IndexLookUpJoin:

probe:63.648004ms, inner:{total:1.390975306s, concurrency:5, task:20, construct:124.627721ms, fetch:1.20871983s, build:57.600055ms}

• IndexNestedLoopHashJoin:

inner:{total:1.400792491s, concurrency:5, task:20, construct:112.884295ms, fetch:1.177970132s, build:31.565859ms, join:109.826484ms}

• HashJoinExec:

build_hash_table:{total:61.853856ms, fetch:2.578371ms, build:59.275485ms}, probe:{concurrency:5, total:505.933645ms, probe:193.616535ms, fetch:312.31711ms}

Here is some example:

test> explain analyze select /*+ INL_JOIN(t1, t2) */ count(*) from t1,t2 where t1.a=t2.a;
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+-----------------------+------+
| id                        | estRows   | actRows | task      | access object        | execution info                                                                                                                                                    | operator info                                                              | memory                | disk |
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+-----------------------+------+
| HashAgg_10                | 1.00      | 1       | root      |                      | time:462.151078ms, loops:2, PartialConcurrency:5, FinalConcurrency:5                                                                                              | funcs:count(1)->Column#7                                                   | 0 Bytes               | N/A  |
| └─IndexJoin_28            | 298616.74 | 294220  | root      |                      | time:460.944118ms, loops:289, probe:63.648004ms, inner:{total:1.390975306s, concurrency:5, task:20, construct:124.627721ms, fetch:1.20871983s, build:57.600055ms} | inner join, inner:IndexReader_27, outer key:test.t2.a, inner key:test.t1.a | 8.67692756652832 MB   | N/A  |
|   ├─IndexReader_39(Build) | 294220.00 | 294220  | root      |                      | time:137.65813ms, loops:294, cop_task: {num: 1, max:136.403899ms, proc_keys: 294220, rpc_num: 1, rpc_time: 136.397859ms}                                          | index:IndexFullScan_38                                                     | 2.2487916946411133 MB | N/A  |
|   │ └─IndexFullScan_38    | 294220.00 | 294220  | cop[tikv] | table:t2, index:a(a) | time:127ms, loops:292                                                                                                                                             | keep order:false                                                           | N/A                   | N/A  |
|   └─IndexReader_27(Probe) | 1.00      | 5484    | root      |                      | time:20.156791ms, loops:7, cop_task: {num: 1, max:19.821621ms, proc_keys: 5484, rpc_num: 1, rpc_time: 19.816101ms}                                                | index:Selection_26                                                         | 1.13671875 KB         | N/A  |
|     └─Selection_26        | 1.00      | 294220  | cop[tikv] |                      | proc max:83ms, min:0s, p80:77ms, p95:79ms, iters:421, tasks:30                                                                                                    | not(isnull(test.t1.a))                                                     | N/A                   | N/A  |
|       └─IndexRangeScan_25 | 1.00      | 294220  | cop[tikv] | table:t1, index:a(a) | proc max:81ms, min:0s, p80:77ms, p95:77ms, iters:421, tasks:30                                                                                                    | range: decided by [eq(test.t1.a, test.t2.a)], keep order:false             | N/A                   | N/A  |
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+-----------------------+------+
7 rows in set
Time: 0.474s
test> explain analyze select /*+ INL_HASH_JOIN(t1, t2) */ count(*) from t1,t2 where t1.a=t2.a;
+---------------------------+-----------+---------+-----------+----------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+---------------------+------+
| id                        | estRows   | actRows | task      | access object        | execution info                                                                                                                                                     | operator info                                                              | memory              | disk |
+---------------------------+-----------+---------+-----------+----------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+---------------------+------+
| HashAgg_10                | 1.00      | 1       | root      |                      | time:324.291688ms, loops:2, PartialConcurrency:5, FinalConcurrency:5                                                                                               | funcs:count(1)->Column#7                                                   | 0 Bytes             | N/A  |
| └─IndexHashJoin_30        | 298616.74 | 294220  | root      |                      | time:323.834458ms, loops:292, inner:{total:1.400792491s, concurrency:5, task:20, construct:112.884295ms, fetch:1.177970132s, build:31.565859ms, join:109.826484ms} | inner join, inner:IndexReader_27, outer key:test.t2.a, inner key:test.t1.a | 8.67692756652832 MB | N/A  |
|   ├─IndexReader_39(Build) | 294220.00 | 294220  | root      |                      | time:897.651µs, loops:294, cop_task: {num: 1, max:410.941µs, proc_keys: 0, rpc_num: 1, rpc_time: 402.181µs}                                                        | index:IndexFullScan_38                                                     | 2.248779296875 MB   | N/A  |
|   │ └─IndexFullScan_38    | 294220.00 | 294220  | cop[tikv] | table:t2, index:a(a) | time:127ms, loops:292                                                                                                                                              | keep order:false                                                           | N/A                 | N/A  |
|   └─IndexReader_27(Probe) | 1.00      | 5484    | root      |                      | time:19.391111ms, loops:7, cop_task: {num: 1, max:19.043701ms, proc_keys: 5484, rpc_num: 1, rpc_time: 19.036651ms}                                                 | index:Selection_26                                                         | 1.142578125 KB      | N/A  |
|     └─Selection_26        | 1.00      | 294220  | cop[tikv] |                      | proc max:80ms, min:1ms, p80:77ms, p95:79ms, iters:421, tasks:30                                                                                                    | not(isnull(test.t1.a))                                                     | N/A                 | N/A  |
|       └─IndexRangeScan_25 | 1.00      | 294220  | cop[tikv] | table:t1, index:a(a) | proc max:79ms, min:1ms, p80:76ms, p95:79ms, iters:421, tasks:30                                                                                                    | range: decided by [eq(test.t1.a, test.t2.a)], keep order:false             | N/A                 | N/A  |
+---------------------------+-----------+---------+-----------+----------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------+---------------------+------+
7 rows in set
Time: 0.336s
explain analyze select /*+ HASH_JOIN(t1, t2) */ count(*) from t1,t2 where t1.a=t2.a;
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-----------------------+---------+
| id                        | estRows   | actRows | task      | access object        | execution info                                                                                                                                                                            | operator info                                | memory                | disk    |
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-----------------------+---------+
| HashAgg_10                | 1.00      | 1       | root      |                      | time:101.370539ms, loops:2, PartialConcurrency:5, FinalConcurrency:5                                                                                                                      | funcs:count(1)->Column#7                     | 0 Bytes               | N/A     |
| └─HashJoin_36             | 298596.44 | 294200  | root      |                      | time:100.917249ms, loops:289, build_hash_table:{total:61.853856ms, fetch:2.578371ms, build:59.275485ms}, probe:{concurrency:5, total:505.933645ms, probe:193.616535ms, fetch:312.31711ms} | inner join, equal:[eq(test.t1.a, test.t2.a)] | 2.31591796875 MB      | 0 Bytes |
|   ├─IndexReader_41(Build) | 294200.00 | 294200  | root      |                      | time:1.702651ms, loops:289, cop_task: {num: 1, max:482.39µs, proc_keys: 0, rpc_num: 1, rpc_time: 471.94µs}                                                                                | index:IndexFullScan_40                       | 2.248628616333008 MB  | N/A     |
|   │ └─IndexFullScan_40    | 294200.00 | 294200  | cop[tikv] | table:t2, index:a(a) | time:125ms, loops:292                                                                                                                                                                     | keep order:false                             | N/A                   | N/A     |
|   └─IndexReader_39(Probe) | 540884.00 | 540884  | root      |                      | time:2.131461ms, loops:530, cop_task: {num: 1, max:476.06µs, proc_keys: 0, rpc_num: 1, rpc_time: 467.58µs}                                                                                | index:IndexFullScan_38                       | 4.1338958740234375 MB | N/A     |
|     └─IndexFullScan_38    | 540884.00 | 540884  | cop[tikv] | table:t1, index:a(a) | time:235ms, loops:533                                                                                                                                                                     | keep order:false                             | N/A                   | N/A     |
+---------------------------+-----------+---------+-----------+----------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-----------------------+---------+

Related changes

• Need to cherry-pick to the release branch

Check List

Tests

• Unit test
• Manual test

Side effects

• Performance regression
  • Consumes more CPU
  • Consumes more MEM

Release note

• Add more runtime information for join executor.

[ti-srebot]

/run-all-tests

[lzmhhh123]

LGTM

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[lzmhhh123]

/run-common-test
/run-integration-common-test

[qw4990]

LGTM

[ti-srebot]

Your auto merge job has been accepted, waiting for:

• 19967
• 19967
• 19927
• 19946

[ti-srebot]

/run-all-tests

[ti-srebot]

@ti-srebot merge failed.

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[crazycs520]

/run-integration-common-test
/run-sqllogic-test-2

[crazycs520]

/run-integration-common-test