Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28926

Make ANALYZE FORMAT=JSON show time spent in the query optimizer

    XMLWordPrintable

    Details

      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 }
        

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              psergei Sergei Petrunia
              Reporter:
              psergei Sergei Petrunia
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated:

                  Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.