Details
-
Task
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
Description
ANALYZE FORMAT=JSON shows r_total_time_ms field which allows one to see where the time was spent during execution.
r_total_time_ms is provided for
- query_block, aka a SELECT
- table, individual table references
- filesort node.
- ...
The issue is that for many-table join one can frequently see that
- The join itself (query_block) took a lot of time
- table access in the join add up to a fraction of time.
this leaves one puzzled re where the time is spent.
An example of such case is MDEV-20646.
Attachments
Activity
A complete example:
create table ten(a int primary key);
|
insert into ten values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
|
create table one_k(a int primary key);
|
insert into one_k select A.a + B.a* 10 + C.a * 100 from ten A, ten B, ten C;
|
analyze format=json select * from one_k A, one_k B where A.a+B.a >=1998;
|
| {
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 215.94,
|
"table": {
|
"table_name": "A",
|
"access_type": "ALL",
|
"r_loops": 1,
|
"rows": 1000,
|
"r_rows": 1000,
|
"r_total_time_ms": 10.586,
|
"filtered": 100,
|
"r_filtered": 100
|
},
|
"block-nl-join": {
|
"table": {
|
"table_name": "B",
|
"access_type": "ALL",
|
"r_loops": 1,
|
"rows": 1000,
|
"r_rows": 1000,
|
"r_total_time_ms": 7.3542,
|
"filtered": 100,
|
"r_filtered": 100
|
},
|
"buffer_type": "flat",
|
"buffer_size": "5Kb",
|
"join_type": "BNL",
|
"attached_condition": "A.a + B.a >= 1998",
|
"r_filtered": 0.0001
|
}
|
}
|
}
|
Here one can see: total select's time 215 ms, while the total time spent
reading the tables is 10.5 + 7.3 = 17.8 ms.
The same query after the patch:
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 254.33,
|
"table": {
|
"table_name": "A",
|
"access_type": "ALL",
|
"r_loops": 1,
|
"rows": 1000,
|
"r_rows": 1000,
|
"r_table_time_ms": 11.829,
|
"r_other_time_ms": 0.755,
|
"filtered": 100,
|
"r_filtered": 100
|
},
|
"block-nl-join": {
|
"table": {
|
"table_name": "B",
|
"access_type": "ALL",
|
"r_loops": 1,
|
"rows": 1000,
|
"r_rows": 1000,
|
"r_table_time_ms": 10.503,
|
"r_other_time_ms": 231.21,
|
"filtered": 100,
|
"r_filtered": 100
|
},
|
"buffer_type": "flat",
|
"buffer_size": "5Kb",
|
"join_type": "BNL",
|
"attached_condition": "A.a + B.a >= 1998",
|
"r_filtered": 0.0001
|
}
|
}
|
It's clear that the time is spent in B's r_other_time_ms. (Ideally, the time could be shown in block-nl-join node).
"Gap time tracking" patch changes "table" element's r_total_time_ms into two:
"table": {"table_name": "A","access_type": "ALL","r_loops": 1,"rows": 10,"r_rows": 10,- "r_total_time_ms": 1.5746,+ "r_table_time_ms": 1.5746,+ "r_other_time_ms": 10003,"filtered": 100,"r_filtered": 0,"attached_condition": "sleep(1) + A.a > 10"