[MDEV-31121] ANALYZE statement produces 0 for all timings in embedded server Created: 2023-04-24  Updated: 2023-04-25  Resolved: 2023-04-25

Status: Closed
Project: MariaDB Server
Component/s: Embedded Server, Optimizer
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 11.1.1, 10.11.3, 10.4.29, 10.5.20, 10.6.13, 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


 Description   

This was discovered by BB:
https://buildbot.mariadb.net/buildbot/builders/fulltest-debug-big-only/builds/9346/steps/mtr-emb/logs/stdio

--- /home/buildbot/maria-slave/fulltest-debug-big-only/build/mysql-test/main/analyze_format_json_timings.result	2023-04-21 15:46:37.427168390 +0000
 
+++ /home/buildbot/maria-slave/fulltest-debug-big-only/build/mysql-test/main/analyze_format_json_timings.reject	2023-04-21 16:24:56.512945088 +0000
 
@@ -18,7 +18,7 @@
 
 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
 
+0
 
 drop table t1,t2;
 
 #
 
 # Now, check the hashed, BNL-H join
 
@@ -85,7 +85,7 @@
 
 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
 
+0
 
 set join_cache_level=@tmp;
 
 drop table t1, t2;
 
 #

analyze_format_json_timings.test has been added recently. Before that, all tests just masked the values of r.*time_ms in ANALYZE outputs .

If I make the test to print the verbatim ANALYZE output, I can see this:

    "table": {
 
      "table_name": "t1",
 
      "access_type": "ALL",
 
      "r_loops": 1,
 
      "rows": 1000,
 
      "r_rows": 1000,
 
      "r_table_time_ms": 0,
 
      "r_other_time_ms": 0,
 
      "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"],
 
        "r_loops": 1,
 
        "rows": 2000,
 
        "r_rows": 2000,
 
        "r_table_time_ms": 0,
 
        "r_other_time_ms": 0,
 
        "filtered": 100,
 
        "r_filtered": 100
 
      },

Note that counter values seem to be ok (r_loops, r_rows). But timings are not.

 Comments   
Comment by Daniel Black [ 2023-04-24 ]

the timer (my_timer_init) isn't initialized in embedded. Reminder - https://github.com/MariaDB/server/pull/2448

Comment by Sergei Petrunia [ 2023-04-24 ]

This is because timing layer is not initialized correctly:

(gdb) p sys_timer_info.cycles.frequency
 
$17 = 0

The call to

  my_timer_init(&sys_timer_info);

is present only in mysqld_main() only, which I guess is not run in embedded server.

Comment by Sergei Petrunia [ 2023-04-24 ]

danblack ok handled that PR. But it won't solve this bug, would it...

Comment by Sergei Petrunia [ 2023-04-24 ]

bb-10.4-mdev31121

Comment by Rex Johnston [ 2023-04-24 ]

confirmed. without my_timer_init() in the library initialization, ms timers return zero, with the patch, they return proper timings. e.g.

analyze format=json select sleep(1+a) from t1;
 
ANALYZE
 
{
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "r_total_time_ms": 2006.2,
 
    "table": {
 
      "table_name": "t1",
 
      "access_type": "ALL",
 
      "r_loops": 1,
 
      "rows": 2,
 
      "r_rows": 2,
 
      "r_total_time_ms": 0.0589,
 
      "filtered": 100,
 
      "r_filtered": 100
 
    }
 
  }
 
}

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