Details
-
Bug
-
Status: Open (View Workflow)
-
Minor
-
Resolution: Unresolved
-
N/A
-
None
Description
ANALYZE FORMAT=JSON on the original dataset and query from MDEV-28073 (the branch is based on old 10.10 and doesn't contain the full fix MDEV-28852 yet, so the query spends a lot of time in optimization).
|
preview-10.11-mdev-28926 81f857928 non-debug |
| {
|
"query_optimization": { |
"r_total_time_ms": 1199082.822 |
},
|
"query_block": { |
"select_id": 1, |
"r_loops": 1, |
"r_total_time_ms": 38.21517253, |
...
|
1 row in set (19 min 58.541 sec) |
So, even the query optimization time alone (1199082.822), not counting the query block time, already exceeds the total execution time reported by the client (19 min 58.541 sec = 1198541).
The difference here is negligible, but the mere fact that it can occur raises a question about possible bigger discrepancies.
Faster achievable with the same data/query under optimizer_search_depth=15:
| {
|
"query_optimization": { |
"r_total_time_ms": 23634.83577 |
},
|
"query_block": { |
"select_id": 1, |
"r_loops": 1, |
"r_total_time_ms": 0.099659582, |
...
|
1 row in set (23.626 sec) |
Attachments
Issue Links
- is caused by
-
MDEV-28926 Make ANALYZE FORMAT=JSON show time spent in the query optimizer
-
- Closed
-
Activity
| Field | Original Value | New Value |
|---|---|---|
| Link |
This issue is caused by |
| Link | This issue relates to TODO-3603 [ TODO-3603 ] |
| Description |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} so, according to {{r_total_time_ms}}, it is at least {{1199082.822 + 38.21517253 = 1199121.03717}}, while according to the client it is {{19 min 58.541 sec = 1198541}}, that is a half of a second less. |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} so, according to {{r_total_time_ms}}, So, even the reported query optimization time alone ({{1199082.822}}), not counting the query time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). |
| Summary | Sum of time reported as spent in optimizer and execution exceeds total time | Time reported as spent in optimizer exceeds total query time |
| Description |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} so, according to {{r_total_time_ms}}, So, even the reported query optimization time alone ({{1199082.822}}), not counting the query time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} even the query optimization time alone ({{1199082.822}}), not counting the query block time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). |
| Description |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} even the query optimization time alone ({{1199082.822}}), not counting the query block time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} So, even the query optimization time alone ({{1199082.822}}), not counting the query block time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). The difference here is negligible, but the mere fact that it can occur raises a question about possible bigger discrepancies. |
| Description |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} So, even the query optimization time alone ({{1199082.822}}), not counting the query block time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). The difference here is negligible, but the mere fact that it can occur raises a question about possible bigger discrepancies. |
ANALYZE FORMAT=JSON on the original dataset and query from {code:sql|title=preview-10.11-mdev-28926 81f857928 non-debug} | { "query_optimization": { "r_total_time_ms": 1199082.822 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 38.21517253, ... 1 row in set (19 min 58.541 sec) {code} So, even the query optimization time alone ({{1199082.822}}), not counting the query block time, already exceeds the total execution time reported by the client ({{19 min 58.541 sec = 1198541}}). The difference here is negligible, but the mere fact that it can occur raises a question about possible bigger discrepancies. Faster achievable with the same data/query under {{optimizer_search_depth=15}}: {code:sql} | { "query_optimization": { "r_total_time_ms": 23634.83577 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 0.099659582, ... 1 row in set (23.626 sec) {code} |