[MDEV-28926] Make ANALYZE FORMAT=JSON show time spent in the query optimizer Created: 2022-06-22  Updated: 2023-03-21  Resolved: 2022-10-26

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Fix Version/s: 10.11.1

Type: Task Priority: Critical
Reporter: Sergei Petrunia Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: Preview_10.11, optimizer, optimizer-easy

Issue Links:
Duplicate
is duplicated by MDEV-28638 ANALYZE FORMAT=JSON should print time... Closed
PartOf
is part of MDEV-29547 prepare 10.11.0 preview releases Closed
Problem/Incident
causes MDEV-29572 Time reported as spent in optimizer e... Open
causes MDEV-30411 main.explain_json_format_partitions f... Closed
Relates

 Description   

ANALYZE FORMAT=JSON shows r_total_time_ms. This is the time spent executing the query. It doesn't include the time spent doing query optimization.

Here's an example: The query execution takes 30 seconds, and I've stopped it in the optimizer for 50 seconds:

MariaDB [j1]> analyze format=json select sleep(10) from t1 where a<=3;
 
| ANALYZE                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                      | {
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "r_total_time_ms": 30056.17521,
 
    "nested_loop": [
 
      {
 
        "table": {
 
          "table_name": "t1",
 
          "access_type": "ALL",
 
          "r_loops": 1,
 
          "rows": 1000,
 
          "r_rows": 1000,
 
          "r_table_time_ms": 9.739445325,
 
          "r_other_time_ms": 30046.39758,
 
          "filtered": 100,
 
          "r_filtered": 0.3,
 
          "attached_condition": "t1.a <= 3"
 
        }
 
      }
 
    ]
 
  }
 
} |
 
1 row in set (1 min 20.511 sec)

Note the client show the query took 1 min 20 sec, while query_block.r_total_time_ms=20 sec.

In some cases, query optimization itself can take a while, so we should report that time as well.

Note

Starting from 10.9, there is SHOW ANALYZE FORMAT=JSON. It has r_query_time_in_progress_ms which counts the query execution time from the start of the query.

MariaDB [j1]> show analyze format=json for 6;
 
| {
 
  "r_query_time_in_progress_ms": 60499,
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "nested_loop": [
 
      {
 
        "table": {
 
          "table_name": "t1",
 
          "access_type": "ALL",
 
          "r_loops": 1,
 
          "rows": 1000,
 
          "r_rows": 1,
 
          "r_table_time_ms": 0.156016501,
 
          "r_other_time_ms": 0,
 
          "filtered": 100,
 
          "r_filtered": 100,
 
          "attached_condition": "t1.a <= 3"
 
        }
 
      }
 
    ]
 
  }
 
} |

How to implement

  • Let's define "query optimization time" as the time spent between the calls to Explain_query::Explain_query() and Explain_query::query_plan_ready().
  • Time can be tracked by using an Exec_time_tracker object. Make it a member of Explain_query.
  • Do not track the time if the statement is not an ANALYZE statement (like it's done in other counters).
  • JSON to be emitted: 

     "query_optimization": {  "r_total_time_ms": NNNN.NNN }



 Comments   
Comment by Sergei Petrunia [ 2022-07-18 ]

Review input provided in the pull request.

Comment by Luis Eduardo Oliveira Lizardo [ 2022-07-18 ]

Merged the PR https://github.com/MariaDB/server/pull/2193 into 10.10 after addressing all review requests.
Thank you psergei for the review and guiding during the development.

Comment by Luis Eduardo Oliveira Lizardo [ 2022-07-18 ]

Ralf told me to reassign it to you, so that you can request test for the right tester.

Comment by Sergei Petrunia [ 2022-07-25 ]

Following the decision to not put this into 10.10

  • Reverted the patch in 10.10
  • Pushed it into 10.11.

Now, jira doesn't allow to close with fixVersion=10.11. Will close this MDEV when the fixVersion check is fixed.

Comment by Sergei Petrunia [ 2022-07-25 ]

Ok, also for 10.11, it should have a test pass. Pushed into preview-10.11-mdev-28926 branch.

Comment by Elena Stepanova [ 2022-09-21 ]

In my opinion, preview-10.11-mdev-28926 as of 81f857928da103a63ec9663038b8671b43921123 is okay to push into 10.11 main and release with 10.11.1.
The branch is quite old and would normally require a rebase before testing, but given the nature of the feature, it didn't seem necessary in this case.

A minor issue MDEV-29572 has been filed; but even if it's confirmed, I don't think a perfect accuracy of the reported value is important for practical purposes, and it cannot be reliably verified anyway. The only reason why it can be essential would be if it reveals a systematic underlying problem with calculation, but it seems unlikely.

Comment by Sergei Petrunia [ 2022-10-26 ]

Now pushed into 10.11.

Generated at Thu Feb 08 10:04:31 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.