Details
-
Task
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
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
- causes
-
MDEV-29572 Time reported as spent in optimizer exceeds total query time
-
- Open
-
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- is part of
-
-
- Closed
-