*: record execute runtime information in slow log (#17573)

[ti-srebot]

cherry-pick #17573 to release-4.0

---

Signed-off-by: crazycs crazycs520@gmail.com

What problem does this PR solve?

Close #15009

Record execute runtime information in slow log plan, such as below:

1. Enable collect runtime execute information first:

set tidb_enable_collect_execution_info=1;

2. Then when TiDB output the slow-log, the Plan field value will like below, It will contain the plan runtime execute information.

# Plan: tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2ggaW4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZTo2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==')

3. Decode the plan

test> select  tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2gga
   -> W4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZTo2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5Nj |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       HashAgg_8               root    1       funcs:count(1)->Column#50                                               1       time:766.09976ms, loops:2, PartialConcurrency:4, FinalConcurrency:4     10.740005493164062 MB   N/A                                                            |
|       └─Selection_11          root    8000    eq(Column#31, 0)                                                        76140   time:765.359648ms, loops:76                                             1.9096031188964844 MB   N/A                                                            |
|         └─MemTableScan_12     root    10000   table:SLOW_QUERY, only search in the current 'tidb-slow.log' file       76469   time:651.899403ms, loops:77                                             N/A                     N/A                                                            |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

As you see, the execute information was contain in the slow-log Plan field now. Since the decode plan field was become too many, we had better add some header column name to more readable, such as below, but we can do this in next PR:

test> select  tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2ggaW4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZ
   -> To2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5Nj |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       id                      task    estRows operator info                                                           actRows execution info                                                          memory                  disk                                                       |
|       HashAgg_8               root    1       funcs:count(1)->Column#50                                               1       time:766.09976ms, loops:2, PartialConcurrency:4, FinalConcurrency:4     10.740005493164062 MB   N/A                                                        |
|       └─Selection_11          root    8000    eq(Column#31, 0)                                                        76140   time:765.359648ms, loops:76                                             1.9096031188964844 MB   N/A                                                        |
|         └─MemTableScan_12     root    10000   table:SLOW_QUERY, only search in the current 'tidb-slow.log' file       76469   time:651.899403ms, loops:77                                             N/A                     N/A                                                        |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

What is changed and how it works?

Related changes

• PR to update pingcap/docs/pingcap/docs-cn:
• Need to cherry-pick to the release branch

Check List

Tests

• Unit test(ing)
• Manual test (add detailed scripts or steps below)

Side effects

• Performance regression
  • Consumes more CPU
  • Consumes more MEM

Release note

• record execute runtime information in slow log.

[ti-srebot]

/run-all-tests

[ti-srebot]

@crazycs520 please accept the invitation then you can push to the cherry-pick pull requests.
https://github.com/ti-srebot/tidb/invitations

[crazycs520]

wait #18073 merge first.

[crazycs520]

/run-all-tests

[crazycs520]

/run-integration-ddl-test

[wjhuang2016]

LGTM

[crazycs520]

/run-integration-br-test

[qw4990]

LGTM

[ti-srebot]

Sorry @qw4990, you don't have permission to trigger auto merge event on this branch.

[crazycs520]

/run-unit-tests