[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 ]

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) 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) 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 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 ]

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 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 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