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
-
Activity
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.
Ralf told me to reassign it to you, so that you can request test for the right tester.
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.
Ok, also for 10.11, it should have a test pass. Pushed into preview-10.11-mdev-28926 branch.
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.
Review input provided in the pull request.