Migrating to MySQL 8.0 for WordPress – episode 2: workload analysis

Now that MySQL is upgraded to 8.0 RC1, let’s have a look on how we could check the workload and see if we can optimize something by adding indexes for example. The same technique can be used to find inefficient queries requiring rewriting.

The first thing we will check is some information regarding the usage of the user used for lefred.be’s website:

mysql> select * from sys.user_summary where user= 'wp_lefred'\G
*************************** 1. row ***************************
user: wp_lefred
statements: 65060
statement_latency: 2.71 m
statement_avg_latency: 2.50 ms
table_scans: 234
file_ios: 17151
file_io_latency: 54.83 s
current_connections: 0
total_connections: 2541
unique_hosts: 1
current_memory: 52.27 MiB
total_memory_allocated: 12.50 GiB

This was after the upgrade, so not much info yet but if I compare with the other sites hosted on the same server, this is the user consuming more resources and it’s indeed expected to be so.

Let’s have a look on which files we spend some time:

mysql> select * from user_summary_by_file_io_type where user = 'wp_lefred';
+-----------+--------------------------------------+-------+---------+-------------+
| user      | event_name                           | total | latency | max_latency |
+-----------+--------------------------------------+-------+---------+-------------+
| wp_lefred | wait/io/file/sql/binlog              | 10546 | 42.00 s | 904.96 ms   |
| wp_lefred | wait/io/file/innodb/innodb_data_file |   703 | 8.20 s  | 428.02 ms   |
| wp_lefred | wait/io/file/innodb/innodb_log_file  |  4258 | 3.16 s  | 1.31 s      |
| wp_lefred | wait/io/file/sql/io_cache            |  1669 | 1.52 s  | 99.89 ms    |
+-----------+--------------------------------------+-------+---------+-------------+

OK this is not much and mostly it’s related to writing the transactions to the binary logs.

We can also check which tables in our schema is the most used and how:

mysql> select * from schema_table_statistics where table_schema='wp_lefred' limit 5\G
*************************** 1. row ***************************
     table_schema: wp_lefred
       table_name: wp_posts
    total_latency: 31.45 s
     rows_fetched: 459094
    fetch_latency: 31.40 s
    rows_inserted: 9
   insert_latency: 21.55 ms
     rows_updated: 36
   update_latency: 30.27 ms
     rows_deleted: 0
   delete_latency: 0 ps
 io_read_requests: 337
          io_read: 5.27 MiB
  io_read_latency: 4.72 s
io_write_requests: 103
         io_write: 1.61 MiB
 io_write_latency: 440.53 ms
 io_misc_requests: 37
  io_misc_latency: 205.77 ms
*************************** 2. row ***************************
     table_schema: wp_lefred
       table_name: wp_options
    total_latency: 11.93 s
     rows_fetched: 303808
    fetch_latency: 6.54 s
    rows_inserted: 1394
   insert_latency: 1.91 s
     rows_updated: 1764
   update_latency: 2.57 s
     rows_deleted: 965
   delete_latency: 907.15 ms
 io_read_requests: 110
          io_read: 1.72 MiB
  io_read_latency: 1.12 s
io_write_requests: 4868
         io_write: 76.06 MiB
 io_write_latency: 2.08 s
 io_misc_requests: 833
  io_misc_latency: 6.46 s
*************************** 3. row ***************************
     table_schema: wp_lefred
       table_name: wp_comments
    total_latency: 2.20 s
     rows_fetched: 183408
    fetch_latency: 2.19 s
    rows_inserted: 8
   insert_latency: 10.58 ms
     rows_updated: 0
   update_latency: 0 ps
     rows_deleted: 40
   delete_latency: 6.22 ms
 io_read_requests: 76
          io_read: 1.19 MiB
  io_read_latency: 338.79 ms
io_write_requests: 68
         io_write: 1.06 MiB
 io_write_latency: 52.50 ms
 io_misc_requests: 14
  io_misc_latency: 71.83 ms
*************************** 4. row ***************************
     table_schema: wp_lefred
       table_name: wp_commentmeta
    total_latency: 1.71 s
     rows_fetched: 7578
    fetch_latency: 1.65 s
    rows_inserted: 26
   insert_latency: 30.89 ms
     rows_updated: 0
   update_latency: 0 ps
     rows_deleted: 152
   delete_latency: 25.42 ms
 io_read_requests: 84
          io_read: 1.31 MiB
  io_read_latency: 1.30 s
io_write_requests: 57
         io_write: 912.00 KiB
 io_write_latency: 58.08 ms
 io_misc_requests: 15
  io_misc_latency: 84.45 ms
*************************** 5. row ***************************
     table_schema: wp_lefred
       table_name: wp_postmeta
    total_latency: 1.61 s
     rows_fetched: 59397
    fetch_latency: 1.45 s
    rows_inserted: 39
   insert_latency: 39.75 ms
     rows_updated: 130
   update_latency: 124.20 ms
     rows_deleted: 1
   delete_latency: 337.19 us
 io_read_requests: 35
          io_read: 560.00 KiB
  io_read_latency: 563.27 ms
io_write_requests: 141
         io_write: 2.20 MiB
 io_write_latency: 160.52 ms
 io_misc_requests: 131
  io_misc_latency: 497.16 ms
5 rows in set (0.19 sec)

Now let’s start to identify the workload for this user. Using SYS schema, we will first check what kind of statements are executed (by experience, maybe not on WordPress, I know that sometimes people gets surprised by the result):

mysql> select * from user_summary_by_statement_type where user ='wp_lefred';
+-----------+-------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| user      | statement   | total | total_latency | max_latency | lock_latency | rows_sent | rows_examined | rows_affected | full_scans |
+-----------+-------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| wp_lefred | select      | 47050 | 1.36 m        | 5.33 s      | 13.47 s      |    195760 |       1145513 |             0 |        234 |
| wp_lefred | update      |  2214 | 39.73 s       | 906.92 ms   | 1.27 s       |         0 |          2776 |          1934 |          0 |
| wp_lefred | insert      |  1493 | 15.68 s       | 2.62 s      | 3.22 s       |         0 |             0 |          1439 |          0 |
| wp_lefred | delete      |   863 | 11.65 s       | 1.32 s      | 131.04 ms    |         0 |          1164 |          1161 |          0 |
| wp_lefred | show_fields |   981 | 7.04 s        | 696.34 ms   | 3.21 s       |      4655 |         28180 |             0 |          0 |
| wp_lefred | set_option  |  7659 | 5.02 s        | 1.04 s      | 0 ps         |         0 |             0 |             0 |          0 |
| wp_lefred | Init DB     |  2553 | 2.24 s        | 606.10 ms   | 784.00 us    |         0 |             0 |             0 |          0 |
| wp_lefred | Quit        |  2553 | 79.69 ms      | 4.26 ms     | 0 ps         |         0 |             0 |             0 |          0 |
+-----------+-------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
8 rows in set (0.02 sec)

This time, as expected, the workload is read oriented. I can also see that show_fields is still heavily used… I never understood why you always need to ask for the fields you created yourself in an app… but OK, I need to deal with it. If you write your own application, please don’t use that technique as is creates a disk temporary tables each time 🙁

SYS schema also provides you a nice view called statement_analysis that we can use to have information about the queries.

We can use this view to find the query that consumes most resources on the system (records are sorted by total_latencybefore formatting to human readable value):

mysql> select * from statement_analysis where db = 'wp_lefred' limit 1\G
*************************** 1. row ***************************
            query: UPDATE `wp_options` SET `optio ... ` = ? WHERE `option_name` = ? 
               db: wp_lefred
        full_scan: 
       exec_count: 1681
        err_count: 0
       warn_count: 0
    total_latency: 15.30 s
      max_latency: 98.56 ms
      avg_latency: 9.10 ms
     lock_latency: 780.66 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 1681
rows_examined_avg: 1
    rows_affected: 1608
rows_affected_avg: 1
       tmp_tables: 0
  tmp_disk_tables: 0
      rows_sorted: 0
sort_merge_passes: 0
           digest: b8b5219dfc9846cf7621b3121006835b
       first_seen: 2017-10-24 14:59:53.301502
        last_seen: 2017-10-25 00:02:22.206160
1 row in set (0.01 sec)

We can see that this query is currently the one with the highest latency in total, this means that maybe the query is fast by called way too much. In this example the numbers are not bad, nothing to worry about as this is a write. So this view is excellent, but if I would like to check the execution plan of the query for example, I would like to have a full example.
To achieve this, I will join a performance_schema table:

mysql> select t1.*, QUERY_SAMPLE_TEXT from statement_analysis as t1 
            join performance_schema.events_statements_summary_by_digest as t2 
            on t2.digest=t1.digest and t2.SCHEMA_NAME = t1.db where db = 'wp_lefred' 
            limit 1\G
*************************** 1. row ***************************
            query: SELECT `option_name` , `option ... options` WHERE `autoload` = ? 
               db: wp_lefred
        full_scan: *
       exec_count: 103
        err_count: 0
       warn_count: 0
    total_latency: 2.97 s
      max_latency: 600.21 ms
      avg_latency: 28.82 ms
     lock_latency: 39.46 ms
        rows_sent: 28825
    rows_sent_avg: 280
    rows_examined: 208849
rows_examined_avg: 2028
    rows_affected: 0
rows_affected_avg: 0
       tmp_tables: 0
  tmp_disk_tables: 0
      rows_sorted: 0
sort_merge_passes: 0
           digest: 52292f0ae858595a6dfe100f30207c9f
       first_seen: 2017-10-24 14:59:50.492922
        last_seen: 2017-10-24 23:45:26.192839
QUERY_SAMPLE_TEXT: SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes'
1 row in set (0.21 sec)

Now we can use this sample query to retrieve the QEP.

If you enable the long history, you can use that table to retrieve even older queries.

To enable it you need to perform:

UPDATE setup_consumers SET enabled = 1 WHERE name = 'events_statements_history_long';

Then you can make a list using a statement like this one:

mysql> SELECT left(digest_text, 64), 
        ROUND(SUM(timer_end-timer_start)/1000000000, 1) AS tot_exec_ms, 
        ROUND(SUM(timer_end-timer_start)/1000000000/COUNT(*), 1) AS avg_exec_ms, 
        ROUND(MIN(timer_end-timer_start)/1000000000, 1) AS min_exec_ms, 
        ROUND(MAX(timer_end-timer_start)/1000000000, 1) AS max_exec_ms, 
        ROUND(SUM(timer_wait)/1000000000, 1) AS tot_wait_ms, 
        ROUND(SUM(timer_wait)/1000000000/COUNT(*), 1) AS avg_wait_ms, 
        ROUND(MIN(timer_wait)/1000000000, 1) AS min_wait_ms, 
        ROUND(MAX(timer_wait)/1000000000, 1) AS max_wait_ms, 
        ROUND(SUM(lock_time)/1000000000, 1) AS tot_lock_ms, 
        ROUND(SUM(lock_time)/1000000000/COUNT(*), 1) AS avglock_ms, 
        ROUND(MIN(lock_time)/1000000000, 1) AS min_lock_ms, 
        ROUND(MAX(lock_time)/1000000000, 1) AS max_lock_ms, 
        MIN(LEFT(DATE_SUB(NOW(), 
         INTERVAL (isgs.VARIABLE_VALUE - TIMER_START*10e-13) second), 19)) AS first_seen, 
        MAX(LEFT(DATE_SUB(NOW(), 
         INTERVAL (isgs.VARIABLE_VALUE - TIMER_START*10e-13) second), 19)) AS last_seen, 
        COUNT(*) as cnt, ANY_VALUE(SQL_TEXT)   
     FROM events_statements_history_long   
     JOIN global_status AS isgs  
     WHERE isgs.variable_name = 'UPTIME' and CURRENT_SCHEMA='wp_lefred' 
     GROUP BY LEFT(digest_text,64)  ORDER BY tot_exec_ms DESC limit 1\G
*************************** 1. row ***************************
left(digest_text, 64): UPDATE `wp_options` SET `option_value` = ? , `autoload` = ? WHER
          tot_exec_ms: 722.2
          avg_exec_ms: 11.5
          min_exec_ms: 0.3
          max_exec_ms: 72.0
          tot_wait_ms: 722.2
          avg_wait_ms: 11.5
          min_wait_ms: 0.3
          max_wait_ms: 72.0
          tot_lock_ms: 37.1
           avglock_ms: 0.6
          min_lock_ms: 0.1
          max_lock_ms: 2.2
           first_seen: 2017-10-24 16:40:51
            last_seen: 2017-10-24 16:50:17
                  cnt: 63
  ANY_VALUE(SQL_TEXT): UPDATE `wp_options` SET `option_value` = '1508856059', 
                       `autoload` = 'yes' 
                       WHERE `option_name` = 'jetpack_next_sync_time_full-sync-enqueue'
1 row in set (0.32 sec)

There are many other useful tables in SYS schema like:

mysql> SHOW TABLES WHERE `Tables_in_sys` LIKE 'statements_with%';
+---------------------------------------------+
| Tables_in_sys                               |
+---------------------------------------------+
| statements_with_errors_or_warnings          |
| statements_with_full_table_scans            |
| statements_with_runtimes_in_95th_percentile |
| statements_with_sorting                     |
| statements_with_temp_tables                 |
+---------------------------------------------+
5 rows in set (0.00 sec)

Like for the preview queries, you can always join performance_schema.events_statements_summary_by_digest to get a full example to analyze.

In the next post, we will see how we can verify the Query Execution Plan of a query, its cost and what it really does.