Uploaded image for project: 'Percona Server for MySQL'
  1. Percona Server for MySQL
  2. PS-4999

PS 8.0 tmp_disk_tables broken in slow query log

Details

    • Bug
    • Status: Done
    • Medium
    • Resolution: Fixed
    • 8.0.12-2rc1, Not 5.7.x
    • 8.0.13-3
    • None

    Description

      I have executed some query in 8.0.12 which creates an in memory temp table, this is what I got in the slow query log:

      # Time: 2018-11-07T13:48:48.299425Z
      # User@Host: root[root] @ localhost []  Id:    14
      # Schema: sbtest  Last_errno: 0  Killed: 0
      # Query_time: 6.121805  Lock_time: 0.000347  Rows_sent: 2437104  Rows_examined: 8437104  Rows_affected: 0
      # Bytes_sent: 484748639  Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: 0
      # Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
      # Filesort: No  Filesort_on_disk: No  Merge_passes: 0
      SET timestamp=1541598528;
      select * from sbtest1 where k>70000 union select * from sbtest2 where k>70000;
      

      Comment:
      1. Tmp_disk_tables is 1 here (notice Tmp_table_on_disk in the line below that one is "No" which is inconsistent) - it should be 0 here.
      2. Tmp_table_sizes is 0 and I think it should be calculated regardless if temp table is created on disk or in memory.

      Here's info from performance schema for this query:

      select * from performance_schema.events_statements_current\G;
      *************************** 2. row ***************************
                    THREAD_ID: 86
                     EVENT_ID: 203
                 END_EVENT_ID: NULL
                   EVENT_NAME: statement/sql/select
                       SOURCE: init_net_server_extension.cc:95
                  TIMER_START: 10970180946953000
                    TIMER_END: 10972287135089000
                   TIMER_WAIT: 2106188136000
                    LOCK_TIME: 261000000
                     SQL_TEXT: select * from sbtest1 where k>70000 union select * from sbtest2 where k>70000
                       DIGEST: ae298ff66e9c8fca13309c4b62e81417afe55c46c1f417de2f123d10f45ab6cb
                  DIGEST_TEXT: SELECT * FROM `sbtest1` WHERE `k` > ? UNION SELECT * FROM `sbtest2` WHERE `k` > ?
               CURRENT_SCHEMA: sbtest
                  OBJECT_TYPE: NULL
                OBJECT_SCHEMA: NULL
                  OBJECT_NAME: NULL
        OBJECT_INSTANCE_BEGIN: NULL
                  MYSQL_ERRNO: 0
            RETURNED_SQLSTATE: NULL
                 MESSAGE_TEXT: NULL
                       ERRORS: 0
                     WARNINGS: 0
                ROWS_AFFECTED: 0
                    ROWS_SENT: 0
                ROWS_EXAMINED: 0
      CREATED_TMP_DISK_TABLES: 0
           CREATED_TMP_TABLES: 1
             SELECT_FULL_JOIN: 0
       SELECT_FULL_RANGE_JOIN: 0
                 SELECT_RANGE: 0
           SELECT_RANGE_CHECK: 0
                  SELECT_SCAN: 3
            SORT_MERGE_PASSES: 0
                   SORT_RANGE: 0
                    SORT_ROWS: 0
                    SORT_SCAN: 0
                NO_INDEX_USED: 1
           NO_GOOD_INDEX_USED: 0
             NESTING_EVENT_ID: NULL
           NESTING_EVENT_TYPE: NULL
          NESTING_EVENT_LEVEL: 0
      

      CREATED_TMP_TABLES is 1, but CREATED_TMP_DISK_TABLES is 0

      PS 5.7.23 with in memory temp table:

      # Time: 2018-11-07T15:52:20.869794Z
      # User@Host: root[root] @ localhost []  Id:     5
      # Schema: sbtest  Last_errno: 0  Killed: 0
      # Query_time: 0.096984  Lock_time: 0.000140  Rows_sent: 99999  Rows_examined: 299997  Rows_affected: 0
      # Bytes_sent: 988930  Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: 1663184
      # QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
      # Filesort: No  Filesort_on_disk: No  Merge_passes: 0
      SET timestamp=1541605940;
      select id from sbtest1 where id<100000 union select id from sbtest2 where id<100000;
      

      Tmp_disk_tables is 0 here, but Tmp_table_sizes is calculated which I think it should be (so 5.7 seems fine here).

      PS 8.0.12 with on disk temp table:

      # Time: 2018-11-07T15:42:27.934851Z
      # User@Host: root[root] @ localhost []  Id:    11
      # Schema: sbtest  Last_errno: 0  Killed: 0
      # Query_time: 18.682736  Lock_time: 0.000502  Rows_sent: 2437104  Rows_examined: 8437104  Rows_affected: 0
      # Bytes_sent: 487185771  Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: 16384
      # Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
      # Filesort: No  Filesort_on_disk: No  Merge_passes: 0
      use sbtest;
      SET timestamp=1541605347;
      select * from sbtest1 where k>70000 union select * from sbtest2 where k>70000;
      

      You can see that Tmp_disk_tables is 1 here and Tmp_table_sizes is also calculated - so I would conclude that this affects only queries which create in memory temp tables.

      Just for reference PS 5.7.23 with on disk temp table:

      # Time: 2018-11-07T14:23:12.540917Z
      # User@Host: root[root] @ localhost []  Id:     4
      # Schema: sbtest  Last_errno: 0  Killed: 0
      # Query_time: 8.320551  Lock_time: 0.000114  Rows_sent: 2437104  Rows_examined: 8437104  Rows_affected: 0
      # Bytes_sent: 484748639  Tmp_tables: 1  Tmp_disk_tables: 1  Tmp_table_sizes: 16384
      # QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
      # Filesort: No  Filesort_on_disk: No  Merge_passes: 0
      SET timestamp=1541600592;
      select * from sbtest1 where k>70000 union select * from sbtest2 where k>70000;
      

      Also notice that upstream in 8.0.14 adds a new variable to control format of slow query log:
      https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_log_slow_extra
      https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html#slow-query-log-contents
      and it will include some of the stuff that we already have and some more so this will be fun all around.

      STEPS TO REPRODUCE:

      ### PREPARE ###
      set global log_slow_verbosity='standard';
      set global long_query_time=0;
      set global slow_query_log=ON;
      
      ### REPRODUCE ON DISK TEMP TABLE WITHIN QUERY: ###
      create table t1 (a int, b blob, key k_b(b(64)));
      create table t2 (a int, b blob, key k_b(b(64)));
      insert into t1 values (1,"aaa"),(2,"bbb"),(3,"ccc");
      insert into t2 values (1,"aaa"),(2,"bbb"),(3,"ccc");
      select * from t1 union select * from t2;
      
      ### REPRODUCE IN MEMORY TEMP TABLE WITHIN QUERY: ###
      create table t3 (a int);
      create table t4 (a int);
      insert into t3 values (1),(2),(3);
      insert into t4 values (1),(2),(3);
      select * from t3 union select * from t4;
      

      Attachments

        Activity

          People

            laurynas.biveinis Laurynas Biveinis (Inactive)
            tomislav.plavcic@percona.com Tomislav Plavcic
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - Not Specified
                Not Specified
                Logged:
                Time Spent - 6 hours, 31 minutes
                6h 31m

                Smart Checklist