MDEV-30830: ANALYZE FORMAT=JSON: r_unpack_time_ms is empty for the hashed joins

Do the time counting in the right place.

mysql-test/main/analyze_format_json_timings.result

+#
+# 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_optimization": {
+    "r_total_time_ms": "REPLACED"
+  },
+  "query_block": {
+    "select_id": 1,
+    "cost": "REPLACED",
+    "r_loops": 1,
+    "r_total_time_ms": "REPLACED",
+    "nested_loop": [
+      {
+        "table": {
+          "table_name": "t1",
+          "access_type": "ALL",
+          "loops": 1,
+          "r_loops": 1,
+          "rows": 500,
+          "r_rows": 500,
+          "cost": "REPLACED",
+          "r_table_time_ms": "REPLACED",
+          "r_other_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"],
+            "loops": 500,
+            "r_loops": 1,
+            "rows": 500,
+            "r_rows": 500,
+            "cost": "REPLACED",
+            "r_table_time_ms": "REPLACED",
+            "r_other_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;

mysql-test/main/analyze_format_json_timings.test

+#
+#  Tests to check that r_something_time_ms is non-zero in
+#    ANALYZE FORMAT=JSON <statement>
+#
+--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;
+

sql/sql_join_cache.cc

@@ -1605,7 +1605,6 @@ bool JOIN_CACHE::put_record()
 bool JOIN_CACHE::get_record()
 { 
   bool res;
-  ANALYZE_START_TRACKING(thd(), join_tab->jbuf_unpack_tracker);
   uchar *prev_rec_ptr= 0;
   if (with_length)
     pos+= size_of_rec_len;
@@ -1621,7 +1620,6 @@ bool JOIN_CACHE::get_record()
     if (prev_cache)
       prev_cache->get_record_by_pos(prev_rec_ptr);
   } 
-  ANALYZE_STOP_TRACKING(thd(), join_tab->jbuf_unpack_tracker);
   return res; 
 }
 
@@ -2397,7 +2395,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->thd, join_tab->jbuf_unpack_tracker);
+        read_next_candidate_for_match(rec_ptr);
+        ANALYZE_STOP_TRACKING(join->thd, join_tab->jbuf_unpack_tracker);
         rc= generate_full_extensions(rec_ptr);
         if (rc != NESTED_LOOP_OK && rc != NESTED_LOOP_NO_MORE_ROWS)
 	  goto finish;