1
0
mirror of https://github.com/MariaDB/server.git synced 2025-08-01 03:47:19 +03:00

MDEV-20854: ANALYZE for statements: not clear where the time is spent

Count the "gap" time between table accesses and display it as
r_other_time_ms in the "table" element.

* The advantage of this approach is that it doesn't add any new
  my_timer_cycles() calls.
* The disadvantage is that the definition of what is done during
  "other time" is not that clear: it includes checking the WHERE
  (for this table), constructing index lookup tuple (for the next table)
  writing to GROUP BY temporary table (as we dont account for that time
  separately [yet], etc)
This commit is contained in:
Sergei Petrunia
2019-11-09 21:03:23 +03:00
parent 0117d0e65a
commit 68ed3a81f2
27 changed files with 448 additions and 206 deletions

View File

@ -15,7 +15,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 30,
"attached_condition": "t0.a < 3"
@ -43,7 +44,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 0,
"attached_condition": "t0.a > 9 and t0.a is not null"
@ -83,7 +85,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"attached_condition": "t0.a is not null"
@ -99,7 +102,8 @@ ANALYZE
"r_loops": 10,
"rows": 1,
"r_rows": 1,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 40,
"attached_condition": "t1.b < 4"
@ -125,7 +129,8 @@ ANALYZE
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 20,
"attached_condition": "tbl1.b < 20"
@ -137,7 +142,8 @@ ANALYZE
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 60,
"attached_condition": "tbl2.b < 60"
@ -163,7 +169,8 @@ ANALYZE
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 20,
"attached_condition": "tbl1.b < 20"
@ -175,7 +182,8 @@ ANALYZE
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 60,
"attached_condition": "tbl2.b < 60"
@ -210,7 +218,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"attached_condition": "t1.a is not null"
@ -226,7 +235,8 @@ ANALYZE
"r_loops": 10,
"rows": 2,
"r_rows": 0.2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"using_index": true
@ -260,7 +270,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 50,
"attached_condition": "test.t1.a < 5"
@ -317,7 +328,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 50,
"index_condition": "t1.pk < 10",
@ -382,7 +394,8 @@ ANALYZE
"r_loops": 1,
"rows": 5,
"r_rows": 5,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
},
@ -405,7 +418,8 @@ ANALYZE
"r_loops": 5,
"rows": 1010,
"r_rows": 203.8,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 98.135
}
@ -441,7 +455,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 50,
"attached_condition": "tbl1.a < 5"
@ -460,7 +475,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 20,
"attached_condition": "tbl2.a in (2,3)"
@ -508,7 +524,8 @@ ANALYZE
"r_loops": 1,
"rows": 256,
"r_rows": 256,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
}
@ -538,7 +555,8 @@ ANALYZE
"r_loops": 1,
"rows": 256,
"r_rows": 256,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
}
@ -579,7 +597,8 @@ ANALYZE
"r_loops": 1,
"rows": 256,
"r_rows": 256,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
}
@ -608,7 +627,8 @@ ANALYZE
"r_loops": 1,
"rows": 2,
"r_rows": 2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
},
@ -619,7 +639,8 @@ ANALYZE
"r_loops": 1,
"rows": 2,
"r_rows": 2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 0,
"attached_condition": "<in_optimizer>(t2.b,t2.b in (subquery#2))"
@ -642,7 +663,8 @@ ANALYZE
"r_loops": 1,
"rows": 2,
"r_rows": 2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
}
@ -694,7 +716,8 @@ ANALYZE
"r_loops": 1,
"rows": 2,
"r_rows": 2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100
},
@ -705,7 +728,8 @@ ANALYZE
"r_loops": 1,
"rows": 2,
"r_rows": 2,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 0,
"attached_condition": "t3.f3 in (1,2)"
@ -779,7 +803,8 @@ ANALYZE
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"r_table_time_ms": "REPLACED",
"r_other_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 0,
"attached_condition": "t1.a < 0"