[MDEV-28926] Make ANALYZE FORMAT=JSON show time spent in the query optimizer - Jira

Sergei Petrunia created issue - 2022-06-22 12:36

Sergei Petrunia made changes - 2022-07-06 08:46

Field	Original Value	New Value
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. Sometimes query optimization itself can take a while, so we should report that time as well. (TODO: what about SHOW ANALYZE FORMAT=JSON? Does there r_query_time_in_progress_ms include the optimization time? Well in any case, ANALYZE FORMAT=JSON should report it also)	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: {code} 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) {code} 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. {code} 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" } } ] } } \| {code}

Sergei Petrunia made changes - 2022-07-06 08:49

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:
{code}
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)
{code}
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.
{code}
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"
        }
      }
    ]
  }
} |
{code}

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:
{code}
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)
{code}
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.
{code}
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"
        }
      }
    ]
  }
} |
{code}

h2. 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:
{code:json}
"query_optimization": { "r_total_time_ms": NNNN.NNN }
{code

Sergei Petrunia made changes - 2022-07-06 08:49

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:
{code}
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)
{code}
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.
{code}
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"
        }
      }
    ]
  }
} |
{code}

h2. 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:
{code:json}
"query_optimization": { "r_total_time_ms": NNNN.NNN }
{code

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:
{code}
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)
{code}
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.
{code}
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"
        }
      }
    ]
  }
} |
{code}

h2. 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:
{code:json}
"query_optimization": { "r_total_time_ms": NNNN.NNN }
{code}

Sergei Petrunia made changes - 2022-07-14 12:39

Assignee

Sergei Petrunia [ psergey ]

Sergei Petrunia made changes - 2022-07-14 12:39

Status

Open [ 1 ]

In Progress [ 3 ]

Sergei Petrunia made changes - 2022-07-14 12:40

Status

In Progress [ 3 ]

In Review [ 10002 ]

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-15 12:07

Assignee

Sergei Petrunia [ psergey ]

Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-15 15:39

Assignee

Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]

Sergei Petrunia [ psergey ]

Sergei Petrunia added a comment - 2022-07-18 09:40

Review input provided in the pull request.

Sergei Petrunia added a comment - 2022-07-18 09:40 Review input provided in the pull request.

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-18 15:48

Assignee

Sergei Petrunia [ psergey ]

Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]

Luis Eduardo Oliveira Lizardo (Inactive) added a comment - 2022-07-18 15:49

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.

Luis Eduardo Oliveira Lizardo (Inactive) added a comment - 2022-07-18 15:49 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.

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-18 15:50

Assignee	Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]	Sergei Petrunia [ psergey ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-18 15:52

Assignee

Sergei Petrunia [ psergey ]

Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-18 15:57

Status

Stalled [ 10000 ]

In Testing [ 10301 ]

Luis Eduardo Oliveira Lizardo (Inactive) added a comment - 2022-07-18 16:00

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

Luis Eduardo Oliveira Lizardo (Inactive) added a comment - 2022-07-18 16:00 Ralf told me to reassign it to you, so that you can request test for the right tester.

Luis Eduardo Oliveira Lizardo (Inactive) made changes - 2022-07-18 16:00

Assignee

Luis Eduardo Oliveira Lizardo [ JIRAUSER51996 ]

Sergei Petrunia [ psergey ]

Oleg Smirnov made changes - 2022-07-20 12:09

Link

This issue is duplicated by ~~MDEV-28638~~ [ ~~MDEV-28638~~ ]

Sergei Petrunia made changes - 2022-07-25 10:44

Status

In Testing [ 10301 ]

Stalled [ 10000 ]

Sergei Petrunia added a comment - 2022-07-25 10:48

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.

Sergei Petrunia added a comment - 2022-07-25 10:48 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.

Sergei Golubchik made changes - 2022-07-25 12:50

Status

Stalled [ 10000 ]

In Testing [ 10301 ]

Sergei Golubchik made changes - 2022-07-25 12:50

Assignee

Sergei Petrunia [ psergey ]

Elena Stepanova [ elenst ]

Sergei Petrunia added a comment - 2022-07-25 13:38

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

Sergei Petrunia added a comment - 2022-07-25 13:38 Ok, also for 10.11, it should have a test pass. Pushed into preview-10.11-mdev-28926 branch.

Elena Stepanova made changes - 2022-09-19 15:39

Link

This issue causes MDEV-29572 [ MDEV-29572 ]

Elena Stepanova made changes - 2022-09-21 12:47

Link

This issue relates to TODO-3603 [ TODO-3603 ]

Elena Stepanova added a comment - 2022-09-21 12:57 - edited

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.

Elena Stepanova added a comment - 2022-09-21 12:57 - edited 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.

Elena Stepanova made changes - 2022-09-21 12:57

Assignee	Elena Stepanova [ elenst ]	Sergei Petrunia [ psergey ]
Status	In Testing [ 10301 ]	Stalled [ 10000 ]

Sergei Golubchik made changes - 2022-09-21 17:58

Link

This issue is part of ~~MDEV-29547~~ [ ~~MDEV-29547~~ ]

Sergei Golubchik made changes - 2022-09-25 10:39

Priority

Major [ 3 ]

Critical [ 2 ]

Sergei Petrunia added a comment - 2022-10-26 06:49

Now pushed into 10.11.

Sergei Petrunia added a comment - 2022-10-26 06:49 Now pushed into 10.11.

Sergei Petrunia made changes - 2022-10-26 06:49

Fix Version/s		10.11.1 [ 28454 ]
Fix Version/s	10.11 [ 27614 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Daniel Black made changes - 2023-01-23 07:06

Link

This issue causes ~~MDEV-30411~~ [ ~~MDEV-30411~~ ]

Ralf Gebhardt made changes - 2023-03-21 10:33

Labels

optimizer optimizer-easy

Preview_10.11 optimizer optimizer-easy

Rob Schwyzer (Inactive) made changes - 2024-04-04 22:00

Remote Link

This issue links to "Page (MariaDB Confluence)" [ 36739 ]

Rob Schwyzer (Inactive) made changes - 2024-04-05 18:34

Remote Link

This issue links to "Page (MariaDB Confluence)" [ 36739 ]

MariaDB Server

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

Details

Description

How to implement

Attachments

Issue Links

Activity

People

Dates

Git Integration