[MDEV-30972] ANALYZE FORMAT=JSON: some time is unaccounted-for in BNL-H joins Created: 2023-03-30  Updated: 2023-04-04  Resolved: 2023-04-04

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.6
Fix Version/s: 11.1.0, 10.11.3, 11.0.2, 10.6.13, 10.7.8, 10.8.8, 10.9.6, 10.10.4

Type: Bug Priority: Major
Reporter: Sergei Petrunia Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-30830 ANALYZE FORMAT=JSON: r_unpack_time_ms... Closed

 Description   

Consider this testcase:

--source include/have_sequence.inc
 
create table t1 (
  a int,
  col1 varchar(100),
  col2 varchar(100),
  col3 varchar(100)
);
 
insert into t1 select
  seq/100,
  concat('col1-', seq),
  concat('col1-', seq),
  concat('col1-', seq)
from seq_1_to_10000;
 
create table t2 (
  a int,
  col1 varchar(100),
  col2 varchar(100),
  col3 varchar(100)
);
 
 
insert into t2 select
  seq/100,
  concat('col1-', seq),
  concat('col1-', seq),
  concat('col1-', seq)
from seq_1_to_20000;
 
analyze table t1,t2;

set join_cache_level=6;
analyze format=json
select * from t1, t2 
where 
  t1.a=t2.a
  and concat(t1.col1, t1.col2, t1.col3)= concat(t2.col1, t2.col2, t2.col3);
 
drop table t1,t2;

Produces

ANALYZE
{
  "query_optimization": {
    "r_total_time_ms": 0.274550914
  },
  "query_block": {
    "select_id": 1,
    "cost": 1865.900178,
    "r_loops": 1,
    "r_total_time_ms": 1258.322335,
    "nested_loop": [
      {
        "table": {
          "table_name": "t1",
          "access_type": "ALL",
          "loops": 1,
          "r_loops": 1,
          "rows": 10000,
          "r_rows": 10000,
          "cost": 1.597164,
          "r_table_time_ms": 8.369960408,
          "r_other_time_ms": 10.40811593,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "t1.a is not null"
        }
      },
      {
        "block-nl-join": {
          "table": {
            "table_name": "t2",
            "access_type": "hash_ALL",
            "key": "#hash#$hj",
            "key_length": "5",
            "used_key_parts": ["a"],
            "ref": ["test.t1.a"],
            "loops": 10000,
            "r_loops": 2,
            "rows": 20000,
            "r_rows": 20000,
            "cost": 1864.303014,
            "r_table_time_ms": 57.63327534,
            "r_other_time_ms": 16.21655048,
            "filtered": 100,
            "r_filtered": 100
          },
          "buffer_type": "flat",
          "buffer_size": "256Kb",
          "join_type": "BNLH",
          "attached_condition": "t2.a = t1.a and concat(t1.col1,t1.col2,t1.col3) = concat(t2.col1,t2.col2,t2.col3)",
          "r_filtered": 1.002505261,
          "r_unpack_time_ms": 135.8873441
        }
      }
    ]
  }
}

In more detail:

  "query_block": {
    "r_total_time_ms": 1258.322335,
    "nested_loop": [
      {
        "table": {
          "table_name": "t1",
          "r_table_time_ms": 8.369960408,
          "r_other_time_ms": 10.40811593,
        }
      },
      {
        "block-nl-join": {
          "table": {
            "table_name": "t2",
            "r_table_time_ms": 57.63327534,
            "r_other_time_ms": 16.21655048,
          },
          "r_unpack_time_ms": 135.8873441
        }
      }
    ]
  }

note that times do not add up to query_block.r_total_time_ms.



 Comments   
Comment by Sergei Petrunia [ 2023-03-31 ]

Indeed, this is because the counter counting "r_unpack_time_ms" doesn't have a "Gap counter" attached to it.

If we add a Gap Counter to it, we can print its value into block-nl-join.r_other_time_ms.

Comment by Sergei Petrunia [ 2023-03-31 ]

With the patch, I get:

ANALYZE
{
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 774.3889331,
    "table": {
      "table_name": "t1",
      "r_table_time_ms": 3.743882206,
      "r_other_time_ms": 4.219490544,
    },
    "block-nl-join": {
      "table": {
        "table_name": "t2",
        "r_table_time_ms": 36.23787405,
        "r_other_time_ms": 6.067091101,
      },
      "attached_condition": "t2.a = t1.a and concat(t1.col1,t1.col2,t1.col3) = concat(t2.col1,t2.col2,t2.col3)",
      "r_unpack_time_ms": 64.98443836,
      "r_other_time_ms": 659.1228799,
    }
  }
}

Note the block-nl-join.r_other_time_ms: 659.1228799. With that member, the numbers add up again.

Comment by Sergei Petrunia [ 2023-03-31 ]

https://github.com/MariaDB/server/commit/b2cc6a3432db69ca6d7ab0360ad48bb5e6dd20fd

Comment by Sergei Petrunia [ 2023-04-04 ]

Got Ok to push from Monty.

Generated at Thu Feb 08 10:20:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.