Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-31121

ANALYZE statement produces 0 for all timings in embedded server

Details

    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.

      Attachments

        Activity

          danblack Daniel Black added a comment -

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

          danblack Daniel Black added a comment - the timer (my_timer_init) isn't initialized in embedded. Reminder - https://github.com/MariaDB/server/pull/2448

          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.

          psergei Sergei Petrunia added a comment - 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.

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

          psergei Sergei Petrunia added a comment - danblack ok handled that PR. But it won't solve this bug, would it...

          bb-10.4-mdev31121

          psergei Sergei Petrunia added a comment - bb-10.4-mdev31121
          Johnston Rex Johnston added a comment -

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

          Johnston Rex Johnston added a comment - 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 } } }

          People

            psergei Sergei Petrunia
            psergei Sergei Petrunia
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.