MySQL 8.0: Statements Latency Histograms

At the end we all agree that what really matters is the Query Response Time, isn’t it ?

MySQL 8.0 engineers have added more visibility in the summary tables as explained in this previous post. But to add more details, now the Performance_Schema also collects the statements latency and provide their distribution thanks to the collected histogram data.

Two tables have been added to Performance_Schema:

• events_statements_histogram_by_digest: details about latency related to schema and query digest
• events_statements_histogram_global: global latency summary across all schemas and queries

Let’s have a look at what we can see:

mysql> SELECT t1.SCHEMA_NAME, CONCAT(ROUND(BUCKET_QUANTILE*100,2),"% under ",
               BUCKET_TIMER_HIGH/1000000000," milliseconds") fact, 
               LEFT(QUERY_SAMPLE_TEXT,64) as QUERY_SAMPLE, t1.DIGEST, 
               COUNT(t1.DIGEST) 
               OVER(PARTITION BY t1.DIGEST) as TOT 
              FROM events_statements_histogram_by_digest t1 
              JOIN events_statements_summary_by_digest t2 
                ON t2.DIGEST = t1.DIGEST AND t2.SCHEMA_NAME = t1.SCHEMA_NAME 
             WHERE COUNT_BUCKET >1 
             ORDER BY t1.DIGEST, BUCKET_TIMER_HIGH DESC 
             LIMIT 10\G
*************************** 1. row ***************************
 SCHEMA_NAME: sbtest
        fact: 86.84% under 100.0000 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 2. row ***************************
 SCHEMA_NAME: sbtest
        fact: 81.58% under 95.4993 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 3. row ***************************
 SCHEMA_NAME: sbtest
        fact: 73.68% under 87.0964 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 4. row ***************************
 SCHEMA_NAME: sbtest
        fact: 68.42% under 83.1764 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 5. row ***************************
 SCHEMA_NAME: sbtest
        fact: 63.16% under 75.8578 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 6. row ***************************
 SCHEMA_NAME: sbtest
        fact: 57.89% under 63.0957 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 7. row ***************************
 SCHEMA_NAME: sbtest
        fact: 47.37% under 50.1187 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 8. row ***************************
 SCHEMA_NAME: sbtest
        fact: 39.47% under 45.7088 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 9. row ***************************
 SCHEMA_NAME: sbtest
        fact: 26.32% under 39.8107 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
*************************** 10. row ***************************
 SCHEMA_NAME: sbtest
        fact: 18.42% under 36.3078 milliseconds
QUERY_SAMPLE: INSERT INTO sbtest1(k, c, pad) VALUES(49929, '83868641912-287739
      DIGEST: 0b515c3fcc7c2095d2b2dccf0040f79254a6fabcf96c7bb9bd597398abba69fb
         TOT: 10
10 rows in set (0.02 sec)

The LIMIT should match the amount of TOT.

We can see (row 7), that only 47.37% of this query is executed in 50ms or less and only 18.42% are executed in less than 36ms.

It’s also possible to illustrate those results like this:

mysql> SELECT CONCAT('<',ROUND(BUCKET_TIMER_HIGH/1000000000,2),'ms') as 'QRT',  
              CONCAT(RPAD('',ROUND(BUCKET_QUANTILE*100),'*'),ROUND(BUCKET_QUANTILE*100,2),"%") bar, 
              COUNT(t1.DIGEST) OVER(PARTITION BY t1.DIGEST) as TOT 
         FROM events_statements_histogram_by_digest t1 
         JOIN events_statements_summary_by_digest t2 
           ON t2.DIGEST = t1.DIGEST AND t2.SCHEMA_NAME = t1.SCHEMA_NAME 
        WHERE COUNT_BUCKET >1 
        ORDER BY t1.DIGEST, BUCKET_TIMER_HIGH DESC 
             LIMIT 10;
+-----------+-----------------------------------------------------------------------------------------------+-----+
| QRT       | bar                                                                                           | TOT |
+-----------+-----------------------------------------------------------------------------------------------+-----+
| <100.00ms | ***************************************************************************************86.84% |  10 |
| <95.50ms  | **********************************************************************************81.58%      |  10 |
| <87.10ms  | **************************************************************************73.68%              |  10 |
| <83.18ms  | ********************************************************************68.42%                    |  10 |
| <75.86ms  | ***************************************************************63.16%                         |  10 |
| <63.10ms  | **********************************************************57.89%                              |  10 |
| <50.12ms  | ***********************************************47.37%                                         |  10 |
| <45.71ms  | ***************************************39.47%                                                 |  10 |
| <39.81ms  | **************************26.32%                                                              |  10 |
| <36.31ms  | ******************18.42%                                                                      |  10 |
+-----------+-----------------------------------------------------------------------------------------------+-----+
10 rows in set (0.02 sec)

Additionally to these tables, in SYS schema, we have added a procedure illustrating the latency histograms too, it’s called: ps_statement_avg_latency_histogram()

mysql> CALL sys.ps_statement_avg_latency_histogram()\G
*************************** 1. row ***************************
Performance Schema Statement Digest Average Latency Histogram: 

  . = 1 unit
  * = 2 units
  # = 3 units

(0 - 348ms)      64 | ********************************
(348 - 696ms)    7  | .......
(696 - 1044ms)   2  | ..
(1044 - 1393ms)  2  | ..
(1393 - 1741ms)  1  | .
(1741 - 2089ms)  0  | 
(2089 - 2437ms)  0  | 
(2437 - 2785ms)  0  | 
(2785 - 3133ms)  0  | 
(3133 - 3481ms)  1  | .
(3481 - 3829ms)  0  | 
(3829 - 4178ms)  0  | 
(4178 - 4526ms)  0  | 
(4526 - 4874ms)  0  | 
(4874 - 5222ms)  0  | 
(5222 - 5570ms)  0  | 

  Total Statements: 78; Buckets: 16; Bucket Size: 348 ms;

1 row in set (0.02 sec)

Query OK, 0 rows affected (0.02 sec)

As you can see, MySQL 8.0 added more visibility in many domains to analyze and understand better your workload.