[MDEV-20854] ANALYZE for statements: not clear where the time is spent Created: 2019-10-17  Updated: 2020-01-23  Resolved: 2019-11-12

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Fix Version/s: 10.5.0

Type: Task Priority: Major
Reporter: Sergei Petrunia Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: analyze-stmt


 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.

 Comments   
Comment by Sergei Petrunia [ 2019-11-09 ]

"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"
 
   },

Comment by Sergei Petrunia [ 2019-11-09 ]

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).

Comment by Sergei Petrunia [ 2019-11-09 ]

Pushed into bb-10.5-mdev20854

Generated at Thu Feb 08 09:02:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.