Skip to main content
Log inGet free account

MySQL Slow Log

Use MySQL Slow Log to troubleshoot and identify serious performance issues.

Discuss in Slack
Edit this page on GitHub Report an issue with this doc

This section provides information on how to analyze your MySQL Slow Log to improve site performance.

Analyzing the MySQL Slow Log is an important part of troubleshooting client issues before and after launch.

Requirements

  • SFTP command line interface (CLI)
  • MySQL command line interface
  • A working knowledge of SQL queries and MySQL

Download the MySQL Slow Log via SFTP

  1. Access the Site Dashboard and navigate to the desired environment (Multidev, Dev, Test, or Live).

  2. Click Connection Info and copy the SFTP Command Line command.

  3. Edit and execute the command by replacing appserver with dbserver:

    From:

    sftp -o Port=2222 dev.de305d54-75b4-431b-adb2-eb6b9e546014@appserver.dev.de305d54-75b4-431b-adb2-eb6b9e546014.drush.in

    To:

    sftp -o Port=2222 dev.de305d54-75b4-431b-adb2-eb6b9e546014@dbserver.dev.de305d54-75b4-431b-adb2-eb6b9e546014.drush.in

  4. Run the following SFTP command in your terminal:

    get -r logs

You now have a local copy of the logs directory, which contains the following:

├── logs
    └──mysqld-slow-query.log
    └──mysqld.log

Below is an example output.

sftp -o Port=2222 live.8883e341-e49d-4c84-958b-8685f263e5fb@dbserver.live.8883e341-e49d-4c84-958b-8685f263e5fb.drush.in
Connected to live.8883e341-e49d-4c84-958b-8685f263e5fb@dbserver.live.8883e341-e49d-4c84-958b-8685f263e5fb.drush.in.
sftp> cd logs
sftp> ls -l
-rw-rw----    1 0f59c6e86b6b4889a413835b20fcddf3 support    586912 Apr 18 19:31 mysqld-slow-query.log
-rw-rw----    1 0f59c6e86b6b4889a413835b20fcddf3 support    628455 Apr 18 19:31 mysqld.log
-rw-rw----    1 0f59c6e86b6b4889a413835b20fcddf3 support   1048713 Jan  2 11:34 mysqld.log-20190102
sftp> get mysqld-slow-query.log
Fetching /srv/bindings/0f59c6e86b6b4889a413835b20fcddf3/logs/mysqld-slow-query.log to mysqld-slow-query.log
/srv/bindings/0f59c6e86b6b4889a413835b20fcddf3/logs/mysqld-slow-query.log                                            100%  573KB 780.7KB/s   00:00
sftp> exit

Analyze the MySQL Slow Log

There are several different tools you can use to analyze a MySQL Slow Log:

  • Percona Toolkit

    Recommended. This toolkit is actively maintained and includes a number of database utilities, including a Slow Query log analyzer, pt-query-digest.

  • MySQL Slow Query Log Filter

    This filter has not been updated since 2007. Although still useful, using this filter will throw warnings with newer versions of PHP.

These tools provide summaries of the most commonly called, poor performing, SQL queries called by your website without manually going through the MySQL Slow Log. Refer to each tool's documentation for more information.

Percona Toolkit's pt-query-digest

The example commands below generate a report using pt-query-digest from a MySQL Slow Log file. In this example, one query meets the threshold for reporting as slow: a SELECT COUNT query on the node table that returns a total of results from a nested SELECT query on the node table.

pt-query-digest mysqld-slow-query.log
# 530ms user time, 50ms system time, 41.72M rss, 147.91M vsz
# Current date: Tue Apr 30 17:17:32 2019
# Hostname: dbserver-9dcedaed.c.pantheon-dmz.internal
# Files: mysqld-slow-query.log
# Overall: 543 total, 5 unique, 0.01 QPS, 2.23x concurrency ______________
# Time range: 2019-04-29 15:05:24 to 2019-04-30 17:16:55
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        209994s      1s   7431s    387s   1649s    986s     84s
# Lock time          153ms    56us     4ms   281us   568us   282us   194us
# Rows sent          2.16k       0      30    4.07   16.81    6.40    0.99
# Rows examine     243.74G       0   3.68G 459.64M   1.95G 675.94M 173.70M
# Query size       1004.36k      64   2.26k   1.85k   2.16k  409.57   1.53k

# Profile
# Rank Query ID           Response time     Calls R/Call   V/M   Item
# ==== ================== ================= ===== ======== ===== =========
#    1 0xFA7FBE1532364377 180389.0902 85.9%   280 644.2468 26... SELECT node field_data_field_director node taxonomy_term_data taxonomy_vocabulary taxonomy_index field_data_field_term field_data_field_parent_course field_data_field_section_number
#    2 0xF65556406AC174D4  29585.0274 14.1%   250 118.3401 59... SELECT node field_data_field_director node taxonomy_term_data taxonomy_vocabulary taxonomy_index field_data_field_term field_data_field_parent_course field_data_field_section_number
# MISC 0xMISC                 20.3315  0.0%    13   1.5640   0.0 <3 ITEMS>

# Query 1: 0.00 QPS, 1.91x concurrency, ID 0xFA7FBE1532364377 at byte 201003
# This item is included in the report because it matches --limit.
# Scores: V/M = 2622.28
# Time range: 2019-04-29 15:05:24 to 2019-04-30 17:16:48
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         51     280
# Exec time     85 180389s      6s   7431s    644s   3110s   1300s    213s
# Lock time     65   100ms   154us     4ms   355us   799us   370us   236us
# Rows sent     12     273       0       1    0.97    0.99    0.15    0.99
# Rows examine  76 186.16G  18.10M   3.68G 680.80M   2.87G 790.80M 460.88M
# Query size    43 438.41k   1.57k   1.57k   1.57k   1.53k       0   1.53k
# String:
# Databases    pantheon
# Hosts        10.128.0.130 (150/53%), 10.128.0.120 (130/46%)
# Users        pantheon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  #
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'node'\G
#    SHOW CREATE TABLE `pantheon`.`node`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'field_data_field_director'\G
#    SHOW CREATE TABLE `pantheon`.`field_data_field_director`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'taxonomy_term_data'\G
#    SHOW CREATE TABLE `pantheon`.`taxonomy_term_data`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'taxonomy_vocabulary'\G
#    SHOW CREATE TABLE `pantheon`.`taxonomy_vocabulary`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'taxonomy_index'\G
#    SHOW CREATE TABLE `pantheon`.`taxonomy_index`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'field_data_field_term'\G
#    SHOW CREATE TABLE `pantheon`.`field_data_field_term`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'field_data_field_parent_course'\G
#    SHOW CREATE TABLE `pantheon`.`field_data_field_parent_course`\G
#    SHOW TABLE STATUS FROM `pantheon` LIKE 'field_data_field_section_number'\G
#    SHOW CREATE TABLE `pantheon`.`field_data_field_section_number`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) AS expression
FROM
(SELECT 1 AS expression
FROM
node node
LEFT JOIN field_data_field_director field_data_field_director ON node.nid = field_data_field_director.entity_id AND (field_data_field_director.entity_type = 'node' AND field_data_field_director.deleted = '0')
LEFT JOIN node node_field_data_field_director ON field_data_field_director.field_director_target_id = node_field_data_field_director.nid
LEFT JOIN (SELECT td.*, tn.nid AS nid
FROM
taxonomy_term_data td
LEFT JOIN taxonomy_vocabulary tv ON td.vid = tv.vid
LEFT JOIN taxonomy_index tn ON tn.tid = td.tid
WHERE  (tv.machine_name IN  ('term')) ) taxonomy_term_data_node ON node.nid = taxonomy_term_data_node.nid
INNER JOIN field_data_field_term field_data_field_term ON node.nid = field_data_field_term.entity_id AND (field_data_field_term.entity_type = 'node' AND field_data_field_term.deleted = '0')
LEFT JOIN field_data_field_parent_course field_data_field_parent_course ON node.nid = field_data_field_parent_course.entity_id AND (field_data_field_parent_course.entity_type = 'node' AND field_data_field_parent_course.deleted = '0')
LEFT JOIN field_data_field_section_number field_data_field_section_number ON node.nid = field_data_field_section_number.entity_id AND (field_data_field_section_number.entity_type = 'node' AND field_data_field_section_number.deleted = '0')
WHERE (( (field_data_field_parent_course.field_parent_course_target_id = '7996' ) )AND(( (node.status = '1') AND (node.type IN  ('section')) AND (field_data_field_term.field_term_tid IN  ('141', '131', '126', '96')) )))) subquery\G

You can use this output to copy the offending query and run it through EXPLAIN on the MySQL server to find out why the query runs slowly. In this case, EXPLAIN shows that the table is missing an index, so adding an index could improve performance.

MySQL Slow Query Log Filter

Below is an example usage of MySQL Slow Query Log Filter, with a minimum execution time of 1 second, sorted by execution count and a no duplicates flag:

php mysql-log-filter-1.9/mysql_filter_slow_log.php -T=1 --sort-execution-count --no-duplicates mysqld-slow-query.log > site_name_slow_1s_noDupes.txt

Here are the contents of site_name_slow-1s_noDupes.txt:

# Execution count: 11 times on 1970-01-01 01:00:00.  
# Column       :     avg |     max |       sum  
# Query time   :       1 |       1 |        11  
# Lock time    :       0 |       0 |         0  
# Rows examined: 132,363 | 132,363 | 1,455,993  
# Rows sent    :       5 |       5 |        55
# User@Host: pantheon[pantheon] @  [10.223.176.175]  
# User@Host: pantheon[pantheon] @  [10.223.177.102]  
# User@Host: pantheon[pantheon] @  [10.223.192.119]  
# User@Host: pantheon[pantheon] @  [10.223.192.139]  
# User@Host: pantheon[pantheon] @  [10.223.192.68]  
# User@Host: pantheon[pantheon] @  [10.223.192.87]  
SET timestamp=1418627746;SELECT node.title AS node_title, node.nid AS nid, node_counter.totalcount AS node_counter_totalcount, ga_stats_count_pageviews_today.count AS ga_stats_count_pageviews_today_countFROM node nodeLEFT JOIN node_counter node_counter ON node.nid = node_counter.nidLEFT OUTER JOIN ga_stats_count ga_stats_count_pageviews_today ON node.nid = ga_stats_count_pageviews_today.nid AND (ga_stats_count_pageviews_today.metric='pageviews' AND ga_stats_count_pageviews_today.timeframe='today') WHERE (( (node.status = '1') AND (node.type IN  ('story')) )) ORDER BY ga_stats_count_pageviews_today_count DESC LIMIT 5 OFFSET 0;

This particular query is examining 132,363 records to return 5, while taking a full second to do so. That would make it a fairly good candidate for refactoring, since most sites prefer queries to execute in milliseconds.

Look at Slow Queries by Hour

Another method is to look at slow queries by the hour to see if there are spikes in slow queries that correspond to site traffic patterns:

grep Time mysqld-slow.log | cut -d: -f1,2 | sort | uniq -c

70 # Time: 140708 10  
71 # Time: 140708 11  
49 # Time: 140708 12  
77 # Time: 140708 13  
77 # Time: 140708 14  
35 # Time: 140708 15  
76 # Time: 140708 16

The output above shows that there were 70 slow queries between 10 and 11AM (UTC). That is a roughly even distribution, which probably means there are a few slow queries that keep repeating.

Refer to MySQL Troubleshooting with New Relic® Performance Monitoring for an in-depth look at finding serious MySQL performance issues using New Relic Pro and MySQL Slow Logs.

More Resources