MySQL Slow Query Log Analysis: Identifying and Fixing Hidden Performance Killers

Introduction

MySQL's slow query log is one of the most underutilized diagnostic tools available. It records every query that takes longer than a configurable threshold, giving you a complete picture of which queries are actually slow in production. I enabled the slow query log on my trading platform's MySQL instance and was surprised by what I found — the queries I thought were slow were not the real problem. The actual performance killers were simple queries running thousands of times per minute.

Here is my process for enabling, analyzing, and acting on MySQL slow query log data.

Environment

• MySQL: 8.0.35
• Database: Trading platform (orders, positions, market_data tables)
• Peak traffic: ~1,000 queries/second
• Tools: pt-query-digest (Percona Toolkit), mysqldumpslow

Problem

I enabled the slow query log with a 1-second threshold:

SET GLOBAL slow_query_log = 1;
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_queries_not_using_indexes = 1;

After 24 hours, the log file was 2.3GB. I initially tried to read it manually:

wc -l /var/log/mysql/slow.log
# 847293 lines

Manually analyzing 847,000 lines was not practical. I needed automated tools to extract the most important patterns.

The initial mysqldumpslow analysis showed:

mysqldumpslow -s t -t 10 /var/log/mysql/slow.log

Count: 124567  Time: 2.34s  (2914s)  Lock: 0.00s  (0s)  Rows: 1.0  (124567)
SELECT * FROM orders WHERE status = 'N' AND created_at > NOW() - INTERVAL ? MINUTE ORDER BY created_at LIMIT ?

Count: 89234   Time: 1.23s  (1097s)  Lock: 0.00s  (0s)  Rows: 1523.4 (13587654)
SELECT * FROM market_data WHERE symbol = 'S' AND date = ? AND time >= ? AND time <= ?

Count: 45678   Time: 0.89s  (406s)   Lock: 0.01s  (456s)  Rows: 1.0  (45678)
SELECT id FROM positions WHERE user_id = ? AND status = 'open'

The first query was the biggest offender by total time — 124,567 executions averaging 2.34 seconds each. It was a simple query, but it was running constantly and scanning too many rows.

Analysis

I used pt-query-digest for a more detailed analysis:

pt-query-digest /var/log/mysql/slow.log > slow-query-report.txt

The report showed:

# Profile
# Rank Query ID           Response time  Calls  R/Call  V/M
# ==== ================== ============== ====== ======= ====
#    1 0xABC123DEF456      2914.0000 34.2% 124567  0.0234  0.00  SELECT orders
#    2 0xDEF789ABC012      1097.0000 12.8%  89234  0.0123  0.00  SELECT market_data
#    3 0xGHI345JKL678       406.0000  4.8%  45678  0.0089  0.00  SELECT positions

The top query (orders SELECT) accounted for 34% of total slow query time. I examined it more closely:

SELECT * FROM orders
WHERE status = 'N'
AND created_at > NOW() - INTERVAL 5 MINUTE
ORDER BY created_at
LIMIT 100;

I checked the execution plan:

EXPLAIN SELECT * FROM orders
WHERE status = 'N'
AND created_at > NOW() - INTERVAL 5 MINUTE
ORDER BY created_at
LIMIT 100;

+----+-------------+--------+------------+-------+------------------+------------------+---------+------+--------+----------+-------+
| id | select_type | table  | partitions | type  | possible_keys    | key              | key_len | ref  | rows   | filtered | Extra |
+----+-------------+--------+------------+-------+------------------+------------------+---------+------+--------+----------+-------+
|  1 | SIMPLE      | orders | NULL       | range | idx_status,idx_ca | idx_created_at   | 5       | NULL | 456789 |    25.00 | Using where; Using filesort |
+----+-------------+--------+------------+-------+------------------+------------------+---------+------+--------+----------+-------+

The query was scanning 456,789 rows and using a filesort. The idx_created_at index was being used for the range scan, but the status = 'N' filter was applied after the scan, not as part of the index. The Using filesort in Extra meant MySQL had to sort the results after filtering.

The fix was a composite index that covers both the filter and the sort:

CREATE INDEX idx_status_created ON orders (status, created_at);

But there was a complication — this query is a polling query that runs every few seconds from the application. Even with an index, the constant polling was creating unnecessary load.

Solution

I addressed the problems at three levels:

1. Create the composite index:

CREATE INDEX idx_status_created ON orders (status, created_at);

After the index was created:

EXPLAIN SELECT * FROM orders
WHERE status = 'N'
AND created_at > NOW() - INTERVAL 5 MINUTE
ORDER BY created_at
LIMIT 100;

+----+-------------+--------+------------+-------+------------------+------------------+---------+------+------+----------+-------+
| id | select_type | table  | partitions | type  | possible_keys    | key              | key_len | ref  | rows | filtered | Extra |
+----+-------------+--------+------------+-------+------------------+------------------+---------+------+------+----------+-------+
|  1 | SIMPLE      | orders | NULL       | range | idx_status_created | idx_status_created | 5     | NULL |  100 |   100.00 | Using where |
+----+-------------+--------+------------+-------+------------------+------------------+---------+------+------+----------+-------+

Rows scanned dropped from 456,789 to 100. The Using filesort was gone because the index already returns rows in created_at order within each status value.

2. Replace polling with a push mechanism:

Instead of polling every 5 seconds, I switched to using MySQL's WAIT_FOR_EXECUTED_GTID_SET or application-level event notification:

import redis
import time

def watch_for_new_orders():
    """Subscribe to Redis pub/sub for new orders instead of polling MySQL."""
    r = redis.Redis()
    pubsub = r.pubsub()
    pubsub.subscribe("new_orders")

    for message in pubsub.listen():
        if message["type"] == "message":
            order_id = message["data"]
            process_order(order_id)

This reduced the query frequency from every 5 seconds to only when new orders actually arrive.

3. Optimize the second-slowest query (market_data):

The market_data query had a different problem — it was selecting all columns when only a few were needed:

-- Before: Selects all columns
SELECT * FROM market_data
WHERE symbol = 'AAPL' AND date = '2024-06-01'
AND time >= '09:30:00' AND time <= '16:00:00';

-- After: Select only needed columns
SELECT symbol, time, close_price, volume
FROM market_data
WHERE symbol = 'AAPL' AND date = '2024-06-01'
AND time >= '09:30:00' AND time <= '16:00:00';

I also added a composite index for this query pattern:

CREATE INDEX idx_symbol_date_time ON market_data (symbol, date, time);

4. Set up ongoing slow query monitoring:

#!/bin/bash
# analyze-slow-queries.sh — Run daily via cron

DAYS=1
THRESHOLD=1

# Rotate the slow log
mysql -e "FLUSH SLOW LOGS"

# Analyze yesterday's slow log
pt-query-digest \
    --since "${DAYS}d" \
    --threshold "${THRESHOLD}" \
    --limit 20 \
    /var/log/mysql/slow.log \
    | mail -s "MySQL Slow Query Report" admin@example.com

After implementing all fixes, the slow query log showed a 95% reduction in entries:

# Before optimization: 847,293 lines in 24 hours
# After optimization: 42,156 lines in 24 hours

Lessons Learned

1. Enable the slow query log — It is the single most useful tool for finding real performance problems. Set the threshold to 1 second and analyze daily.
2. Use pt-query-digest — This tool groups similar queries, ranks them by impact, and provides actionable recommendations. It is far more useful than reading the raw log.
3. Look at total time, not just average time — A query that takes 10ms but runs 100,000 times per hour is more impactful than a query that takes 5 seconds but runs once per hour.
4. Replace polling with event-driven patterns — Constant polling queries create unnecessary load. Use pub/sub, webhooks, or push notifications instead.
5. Monitor query frequency — A query that suddenly runs 10x more often is often a sign of an application bug, not a database problem.

This blog does not accept any external sponsorships, affiliate marketing, or ad revenue.