diff --git a/mysql-test/include/analyze-format.inc b/mysql-test/include/analyze-format.inc index 08006e26c79..330be82ef96 100644 --- a/mysql-test/include/analyze-format.inc +++ b/mysql-test/include/analyze-format.inc @@ -1,3 +1,3 @@ # The time on ANALYSE FORMAT=JSON is rather variable ---replace_regex /("(r_total_time_ms|r_buffer_size|r_filling_time_ms)": )[^, \n]*/\1"REPLACED"/ +--replace_regex /("(r_[a-z_]*_time_ms|r_buffer_size)": )[^, \n]*/\1"REPLACED"/ diff --git a/mysql-test/main/analyze_format_json.result b/mysql-test/main/analyze_format_json.result index c306c2fc1b3..48a12125f98 100644 --- a/mysql-test/main/analyze_format_json.result +++ b/mysql-test/main/analyze_format_json.result @@ -145,7 +145,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "1Kb", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": "REPLACED" } } } @@ -184,7 +185,8 @@ ANALYZE "buffer_size": "1Kb", "join_type": "BNL", "attached_condition": "tbl1.c > tbl2.c", - "r_filtered": 15.833 + "r_filtered": 15.833, + "r_unpack_time_ms": "REPLACED" } } } @@ -628,7 +630,8 @@ ANALYZE "buffer_size": "65", "join_type": "BNL", "attached_condition": "(t2.b,t2.b in (subquery#2))", - "r_filtered": null + "r_filtered": null, + "r_unpack_time_ms": "REPLACED" }, "subqueries": [ { @@ -713,7 +716,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "1", "join_type": "BNL", - "r_filtered": null + "r_filtered": null, + "r_unpack_time_ms": "REPLACED" }, "subqueries": [ { @@ -745,7 +749,8 @@ ANALYZE "buffer_size": "65", "join_type": "BNL", "attached_condition": "t2.f2 = t3.f3", - "r_filtered": null + "r_filtered": null, + "r_unpack_time_ms": "REPLACED" } } } diff --git a/mysql-test/main/analyze_format_json_timings.result b/mysql-test/main/analyze_format_json_timings.result new file mode 100644 index 00000000000..f00833b40eb --- /dev/null +++ b/mysql-test/main/analyze_format_json_timings.result @@ -0,0 +1,85 @@ +# +# MDEV-30830: ANALYZE FORMAT=JSON: r_unpack_time_ms is empty for the hashed joins +# +# +# First, check a regular BNL-join +# +create table t1 ( +a int, +b int +); +insert into t1 select seq, seq/3 from seq_0_to_99; +create table t2 ( +a int, +b int +); +insert into t2 select seq, seq/5 from seq_0_to_99; +set @js='$out'; +set @out=(select json_extract(@js,'$**.block-nl-join.r_unpack_time_ms')); +select cast(json_extract(@out,'$[0]') as DOUBLE) > 0; +cast(json_extract(@out,'$[0]') as DOUBLE) > 0 +1 +drop table t1,t2; +# +# Now, check the hashed, BNL-H join +# +create table t1 ( +a int, +b int +); +insert into t1 select seq, seq/3 from seq_0_to_499; +create table t2 ( +a int, +b int +); +insert into t2 select seq, seq/5 from seq_0_to_499; +set @tmp=@@join_cache_level, join_cache_level=6; +select '$out' as X; +X +{ + "query_block": { + "select_id": 1, + "r_loops": 1, + "r_total_time_ms": "REPLACED", + "table": { + "table_name": "t1", + "access_type": "ALL", + "r_loops": 1, + "rows": 500, + "r_rows": 500, + "r_total_time_ms": "REPLACED", + "filtered": 100, + "r_filtered": 100, + "attached_condition": "t1.a < 700 and t1.b is not null" + }, + "block-nl-join": { + "table": { + "table_name": "t2", + "access_type": "hash_ALL", + "key": "#hash#$hj", + "key_length": "5", + "used_key_parts": ["b"], + "ref": ["test.t1.b"], + "r_loops": 1, + "rows": 500, + "r_rows": 500, + "r_total_time_ms": "REPLACED", + "filtered": 100, + "r_filtered": 20, + "attached_condition": "t2.a < 100" + }, + "buffer_type": "flat", + "buffer_size": "18Kb", + "join_type": "BNLH", + "attached_condition": "t2.b = t1.b", + "r_filtered": 100, + "r_unpack_time_ms": "REPLACED" + } + } +} +set @out=(select json_extract(@js,'$**.block-nl-join.r_unpack_time_ms')); +select cast(json_extract(@out,'$[0]') as DOUBLE) > 0; +cast(json_extract(@out,'$[0]') as DOUBLE) > 0 +1 +set join_cache_level=@tmp; +drop table t1, t2; diff --git a/mysql-test/main/analyze_format_json_timings.test b/mysql-test/main/analyze_format_json_timings.test new file mode 100644 index 00000000000..fdb4c8d5989 --- /dev/null +++ b/mysql-test/main/analyze_format_json_timings.test @@ -0,0 +1,77 @@ +# +# Tests to check that r_something_time_ms is non-zero in +# ANALYZE FORMAT=JSON +# +--source include/default_optimizer_switch.inc +--source include/have_sequence.inc + +# The tests here are large so that we get non-zero timings +--source include/big_test.inc + +--echo # +--echo # MDEV-30830: ANALYZE FORMAT=JSON: r_unpack_time_ms is empty for the hashed joins +--echo # + +--echo # +--echo # First, check a regular BNL-join +--echo # +create table t1 ( + a int, + b int +); +insert into t1 select seq, seq/3 from seq_0_to_99; + +create table t2 ( + a int, + b int +); +insert into t2 select seq, seq/5 from seq_0_to_99; + +let $out=` +analyze format=json +select * from t1, t2 +where + t1.a < 700 and + t2.a < 100 + and t1.b=t2.b +`; + +evalp set @js='$out'; +set @out=(select json_extract(@js,'$**.block-nl-join.r_unpack_time_ms')); +select cast(json_extract(@out,'$[0]') as DOUBLE) > 0; +drop table t1,t2; + +--echo # +--echo # Now, check the hashed, BNL-H join +--echo # +create table t1 ( + a int, + b int +); +insert into t1 select seq, seq/3 from seq_0_to_499; + +create table t2 ( + a int, + b int +); +insert into t2 select seq, seq/5 from seq_0_to_499; +set @tmp=@@join_cache_level, join_cache_level=6; + +let $out=` +analyze format=json +select * from t1, t2 +where + t1.a < 700 and + t2.a < 100 + and t1.b=t2.b +`; + +--source include/analyze-format.inc +evalp select '$out' as X; + +set @out=(select json_extract(@js,'$**.block-nl-join.r_unpack_time_ms')); +select cast(json_extract(@out,'$[0]') as DOUBLE) > 0; + +set join_cache_level=@tmp; +drop table t1, t2; + diff --git a/mysql-test/main/analyze_stmt_orderby.result b/mysql-test/main/analyze_stmt_orderby.result index 23f4c39dd5b..fbd57078b8e 100644 --- a/mysql-test/main/analyze_stmt_orderby.result +++ b/mysql-test/main/analyze_stmt_orderby.result @@ -429,7 +429,8 @@ ANALYZE "buffer_size": "65", "join_type": "BNL", "attached_condition": "t3.a = t0.a", - "r_filtered": 10 + "r_filtered": 10, + "r_unpack_time_ms": "REPLACED" } } } @@ -500,7 +501,8 @@ ANALYZE "buffer_size": "119", "join_type": "BNL", "attached_condition": "t5.a = t6.a", - "r_filtered": 21.429 + "r_filtered": 21.429, + "r_unpack_time_ms": "REPLACED" } } } diff --git a/mysql-test/main/derived_split_innodb.result b/mysql-test/main/derived_split_innodb.result index bea2271eaf3..22974251c56 100644 --- a/mysql-test/main/derived_split_innodb.result +++ b/mysql-test/main/derived_split_innodb.result @@ -461,7 +461,8 @@ ANALYZE "buffer_size": "1Kb", "join_type": "BNL", "attached_condition": "trigcond(t11.col1 = t10.col1)", - "r_filtered": 10 + "r_filtered": 10, + "r_unpack_time_ms": "REPLACED" } } } diff --git a/mysql-test/main/except.result b/mysql-test/main/except.result index c96ba62a215..6b629cb6a0f 100644 --- a/mysql-test/main/except.result +++ b/mysql-test/main/except.result @@ -327,7 +327,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "119", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 0.0012 } } }, @@ -361,7 +362,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "119", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 5.4e-4 } } } @@ -423,7 +425,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "119", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 0.0011 } } }, @@ -457,7 +460,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "119", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 6.1e-4 } } } diff --git a/mysql-test/main/except.test b/mysql-test/main/except.test index 4eaae1a3888..80df958c354 100644 --- a/mysql-test/main/except.test +++ b/mysql-test/main/except.test @@ -14,8 +14,10 @@ EXPLAIN extended select * from ((select a,b from t1) except (select c,d from t2) EXPLAIN format=json (select a,b from t1) except (select c,d from t2); --replace_regex /"r_total_time_ms": [0-9e\.\-+]*,/"r_total_time_ms": "REPLACED",/ +--source include/analyze-format.inc ANALYZE format=json (select a,b from t1) except (select c,d from t2); --replace_regex /"r_total_time_ms": [0-9e\.\-+]*,/"r_total_time_ms": "REPLACED",/ +--source include/analyze-format.inc ANALYZE format=json select * from ((select a,b from t1) except (select c,d from t2)) a; select * from ((select a,b from t1) except (select c,d from t2)) a; diff --git a/mysql-test/main/explain_json.result b/mysql-test/main/explain_json.result index 17f83fe5362..b0ea1d273fb 100644 --- a/mysql-test/main/explain_json.result +++ b/mysql-test/main/explain_json.result @@ -1536,7 +1536,8 @@ ANALYZE "buffer_size": "400", "join_type": "BKA", "mrr_type": "Rowid-ordered scan", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": "REPLACED" } } } diff --git a/mysql-test/main/intersect.result b/mysql-test/main/intersect.result index e4a8300ec74..a32a79c0043 100644 --- a/mysql-test/main/intersect.result +++ b/mysql-test/main/intersect.result @@ -385,7 +385,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "256Kb", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 6.1e-4 } } } @@ -464,7 +465,8 @@ ANALYZE "buffer_type": "flat", "buffer_size": "256Kb", "join_type": "BNL", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": 5.8e-4 } } } diff --git a/mysql-test/main/rowid_filter_innodb.result b/mysql-test/main/rowid_filter_innodb.result index 6bc00da6f4c..6248932d666 100644 --- a/mysql-test/main/rowid_filter_innodb.result +++ b/mysql-test/main/rowid_filter_innodb.result @@ -3634,7 +3634,8 @@ ANALYZE "join_type": "BKA", "mrr_type": "Rowid-ordered scan", "attached_condition": "a.atp = 1", - "r_filtered": 100 + "r_filtered": 100, + "r_unpack_time_ms": "REPLACED" }, "block-nl-join": { "table": { @@ -3657,7 +3658,8 @@ ANALYZE "join_type": "BKA", "mrr_type": "Rowid-ordered scan", "attached_condition": "fi.fh in (6311439873746261694,-397087483897438286,8518228073041491534,-5420422472375069774)", - "r_filtered": 40 + "r_filtered": 40, + "r_unpack_time_ms": "REPLACED" } } } diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc index 6b76db8139e..78f2d5e9254 100644 --- a/sql/sql_explain.cc +++ b/sql/sql_explain.cc @@ -1904,6 +1904,9 @@ void Explain_table_access::print_explain_json(Explain_query *query, writer->add_double(jbuf_tracker.get_filtered_after_where()*100.0); else writer->add_null(); + + writer->add_member("r_unpack_time_ms"); + writer->add_double(jbuf_unpack_tracker.get_time_ms()); } } diff --git a/sql/sql_explain.h b/sql/sql_explain.h index 3add40419cf..2be6390e2cf 100644 --- a/sql/sql_explain.h +++ b/sql/sql_explain.h @@ -721,7 +721,7 @@ public: class Explain_table_access : public Sql_alloc { public: - Explain_table_access(MEM_ROOT *root) : + Explain_table_access(MEM_ROOT *root, bool timed) : derived_select_number(0), non_merged_sjm_number(0), extra_tags(root), @@ -734,6 +734,7 @@ public: pushed_index_cond(NULL), sjm_nest(NULL), pre_join_sort(NULL), + jbuf_unpack_tracker(timed), rowid_filter(NULL) {} ~Explain_table_access() { delete sjm_nest; } @@ -840,7 +841,12 @@ public: Table_access_tracker tracker; Exec_time_tracker op_tracker; Table_access_tracker jbuf_tracker; - + + /* + Track the time to unpack rows from the join buffer. + */ + Time_and_counter_tracker jbuf_unpack_tracker; + Explain_rowid_filter *rowid_filter; int print_explain(select_result_sink *output, uint8 explain_flags, diff --git a/sql/sql_join_cache.cc b/sql/sql_join_cache.cc index 26716a4a5c4..41d7dd89f55 100644 --- a/sql/sql_join_cache.cc +++ b/sql/sql_join_cache.cc @@ -1638,7 +1638,7 @@ bool JOIN_CACHE::get_record() pos+= referenced_fields*size_of_fld_ofs; if (prev_cache) prev_cache->get_record_by_pos(prev_rec_ptr); - } + } return res; } @@ -2414,7 +2414,9 @@ enum_nested_loop_state JOIN_CACHE::join_matching_records(bool skip_last) (join_tab->first_inner && !not_exists_opt_is_applicable))) || !skip_next_candidate_for_match(rec_ptr)) { - read_next_candidate_for_match(rec_ptr); + ANALYZE_START_TRACKING(join_tab->jbuf_unpack_tracker); + read_next_candidate_for_match(rec_ptr); + ANALYZE_STOP_TRACKING(join_tab->jbuf_unpack_tracker); rc= generate_full_extensions(rec_ptr); if (rc != NESTED_LOOP_OK && rc != NESTED_LOOP_NO_MORE_ROWS) goto finish; diff --git a/sql/sql_select.cc b/sql/sql_select.cc index e3a3a33a7c1..ec66d0baf31 100644 --- a/sql/sql_select.cc +++ b/sql/sql_select.cc @@ -26906,6 +26906,7 @@ bool JOIN_TAB::save_explain_data(Explain_table_access *eta, // psergey-todo: data for filtering! tracker= &eta->tracker; jbuf_tracker= &eta->jbuf_tracker; + jbuf_unpack_tracker= &eta->jbuf_unpack_tracker; /* Enable the table access time tracker only for "ANALYZE stmt" */ if (thd->lex->analyze_stmt) @@ -27536,7 +27537,8 @@ int JOIN::save_explain_data_intern(Explain_query *output, Explain_table_access *eta= (new (output->mem_root) - Explain_table_access(output->mem_root)); + Explain_table_access(output->mem_root, + thd->lex->analyze_stmt)); if (!eta) DBUG_RETURN(1); diff --git a/sql/sql_select.h b/sql/sql_select.h index b0fa0b66b62..7282a83ef09 100644 --- a/sql/sql_select.h +++ b/sql/sql_select.h @@ -309,6 +309,7 @@ typedef struct st_join_table { Table_access_tracker *tracker; Table_access_tracker *jbuf_tracker; + Time_and_counter_tracker *jbuf_unpack_tracker; /* Bitmap of TAB_INFO_* bits that encodes special line for EXPLAIN 'Extra' column, or 0 if there is no info.