MySQL Slow Query Log — Finding and Optimizing Slow Queries in Production

· 12 min read
#mysql #database #performance #slow-query #monitoring #optimization

In production, you can't sit and run EXPLAIN for every query. Slow Query Log is the "surveillance camera" that automatically records all slow queries for you to analyze and optimize later.

This article will guide you from basic configuration to building a complete monitoring workflow.

Configuring Slow Query Log

Check Current Configuration

SHOW VARIABLES LIKE 'slow_query%';
SHOW VARIABLES LIKE 'long_query_time';
SHOW VARIABLES LIKE 'log_queries_not_using_indexes';

Sample output:

+---------------------+-------------------------------+
| Variable_name       | Value                         |
+---------------------+-------------------------------+
| slow_query_log      | OFF                           |
| slow_query_log_file | /var/lib/mysql/hostname-slow.log |
| long_query_time     | 10.000000                     |
+---------------------+-------------------------------+

Enable Slow Query Log

Method 1: Dynamic Configuration (no restart needed)

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;  -- Log queries > 1 second
SET GLOBAL log_queries_not_using_indexes = 'ON';  -- Log queries not using indexes
SET GLOBAL log_slow_admin_statements = 'ON';  -- Log ALTER, OPTIMIZE, etc.
SET GLOBAL min_examined_row_limit = 1000;  -- Only log if scanning > 1000 rows

Method 2: Permanent Configuration (my.cnf)

# /etc/mysql/mysql.conf.d/mysqld.cnf or /etc/my.cnf

[mysqld]
# Enable slow query log
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log

# Time threshold (seconds, supports microseconds)
long_query_time = 0.5

# Log queries not using indexes
log_queries_not_using_indexes = 1

# Throttle queries not using indexes (avoid spam)
log_throttle_queries_not_using_indexes = 10

# Log admin statements (ALTER, OPTIMIZE, ANALYZE)
log_slow_admin_statements = 1

# Only log queries scanning many rows
min_examined_row_limit = 100

Then restart MySQL:

sudo systemctl restart mysql

Development:

long_query_time = 0.1  # 100ms - catch all slow queries
log_queries_not_using_indexes = 1
min_examined_row_limit = 0

Staging:

long_query_time = 0.5  # 500ms
log_queries_not_using_indexes = 1
min_examined_row_limit = 100

Production:

long_query_time = 1  # 1 second
log_queries_not_using_indexes = 0  # Disable to avoid logging too much
min_examined_row_limit = 1000
log_throttle_queries_not_using_indexes = 5  # Max 5 logs/minute for this type

Understanding Slow Query Log

Log Entry Format

# Time: 2024-03-15T10:30:45.123456Z
# User@Host: app_user[app_user] @ web-server-01 [192.168.1.100]  Id: 12345
# Query_time: 2.345678  Lock_time: 0.000123  Rows_sent: 100  Rows_examined: 500000
SET timestamp=1710498645;
SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC;

Explanation:

  • Time: Timestamp when query completed
  • User@Host: MySQL user and client hostname/IP
  • Query_time: Total execution time (seconds)
  • Lock_time: Time waiting for locks
  • Rows_sent: Rows returned to client
  • Rows_examined: Rows MySQL had to scan

Red flags:

  • Rows_examined >> Rows_sent: Query scans too much but returns little → Missing index
  • High Lock_time: Contention issues, possibly from long-running transactions
  • Same query appearing multiple times: Priority candidate for optimization

View Log Directly

# View real-time
sudo tail -f /var/log/mysql/slow.log

# View last 50 entries
sudo tail -100 /var/log/mysql/slow.log

# Find queries from a specific user
sudo grep -A5 "app_user" /var/log/mysql/slow.log

Analysis with pt-query-digest

pt-query-digest (from Percona Toolkit) is the #1 tool for analyzing slow query logs.

Installation

# Ubuntu/Debian
sudo apt-get install percona-toolkit

# CentOS/RHEL
sudo yum install percona-toolkit

# macOS
brew install percona-toolkit

Basic Usage

# Analyze slow log
pt-query-digest /var/log/mysql/slow.log

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

# Analyze log within time range
pt-query-digest /var/log/mysql/slow.log --since '2024-03-15 00:00:00' --until '2024-03-15 23:59:59'

# Only analyze top 10 slowest queries
pt-query-digest /var/log/mysql/slow.log --limit 10

Understanding Output

# Profile
# Rank Query ID                           Response time  Calls  R/Call V/M
# ==== ================================== ============== ====== ====== =====
#    1 0x1234567890ABCDEF...              1000.0000 45.2%   500 2.0000  0.50 SELECT orders
#    2 0xABCDEF1234567890...               600.0000 27.1%  2000 0.3000  0.80 SELECT products
#    3 0x5678901234ABCDEF...               400.0000 18.1%   100 4.0000  0.10 SELECT users orders

# Query 1: 0x1234567890ABCDEF...
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         12     500
# Exec time     45 1000.00s    0.5s   10.0s    2.0s    5.0s    1.5s    1.8s
# Lock time      5    50ms    0ms    10ms   0.1ms   0.5ms   0.2ms   0.1ms
# Rows sent     10   50000       1     500     100     200      80     100
# Rows examine  80 250.00M   5000  1000000  500000  900000  200000  450000
# Query size    15   2.5MB       5      50       5       5       0       5
# String:
# Databases    app_production
# Hosts        192.168.1.100, 192.168.1.101
# Users        app_user
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ###
#    1s  ################################################################
#  10s+  ####

SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 100\G

Explanation:

  1. Profile section: Summary of queries by total response time

    • Rank: Ranking of slowest query
    • Response time: Total time + % of all queries
    • Calls: Number of times query was called
    • R/Call: Average response time per call
    • V/M: Variance-to-mean ratio (stability, lower = more stable)

  2. Query detail section: Details for each query

    • Exec time: Min/max/avg/95th percentile of execution time
    • Rows examined: Rows scanned
    • Query_time distribution: Histogram showing time distribution

Priority queries for optimization:

  • High % Response time
  • Rows examined >> Rows sent
  • High Calls (large impact on system)

Useful Options

# Only show queries with execution time > 2s
pt-query-digest /var/log/mysql/slow.log --filter '$event->{Query_time} > 2'

# Group by database
pt-query-digest /var/log/mysql/slow.log --group-by db

# Only analyze SELECT queries
pt-query-digest /var/log/mysql/slow.log --filter '$event->{arg} =~ m/^SELECT/'

# Export to JSON
pt-query-digest /var/log/mysql/slow.log --output json > report.json

# Compare 2 time periods
pt-query-digest /var/log/mysql/slow-yesterday.log --review-history review.db
pt-query-digest /var/log/mysql/slow-today.log --review-history review.db

Analysis with mysqldumpslow

mysqldumpslow is built into MySQL, simpler than pt-query-digest:

# Top 10 slowest queries (by total time)
mysqldumpslow -s t -t 10 /var/log/mysql/slow.log

# Top 10 most frequently called queries
mysqldumpslow -s c -t 10 /var/log/mysql/slow.log

# Top 10 queries with highest avg time
mysqldumpslow -s at -t 10 /var/log/mysql/slow.log

# Top 10 queries scanning most rows
mysqldumpslow -s ar -t 10 /var/log/mysql/slow.log

Sort options (-s):

  • t: Total time
  • at: Average time
  • c: Count (number of calls)
  • l: Lock time
  • r: Rows sent
  • ar: Average rows sent

Performance Schema (Alternative to Slow Query Log)

MySQL 5.6+ has Performance Schema - a more modern way to monitor query performance.

Enable Query Digests

-- Check if Performance Schema is enabled
SHOW VARIABLES LIKE 'performance_schema';

-- Enable digest instruments if needed
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME LIKE '%statement%';

UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME LIKE '%statements%';

Analysis Queries

-- Top 10 slowest queries (by total time)
SELECT 
    DIGEST_TEXT,
    COUNT_STAR as exec_count,
    ROUND(SUM_TIMER_WAIT/1000000000000, 3) as total_time_sec,
    ROUND(AVG_TIMER_WAIT/1000000000, 3) as avg_time_ms,
    SUM_ROWS_EXAMINED as rows_examined,
    SUM_ROWS_SENT as rows_sent,
    FIRST_SEEN,
    LAST_SEEN
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;

-- Queries with high Rows_examined/Rows_sent ratio (missing index)
SELECT 
    DIGEST_TEXT,
    COUNT_STAR as exec_count,
    SUM_ROWS_EXAMINED as rows_examined,
    SUM_ROWS_SENT as rows_sent,
    ROUND(SUM_ROWS_EXAMINED / NULLIF(SUM_ROWS_SENT, 0), 2) as examine_per_sent
FROM performance_schema.events_statements_summary_by_digest
WHERE SUM_ROWS_SENT > 0
ORDER BY examine_per_sent DESC
LIMIT 10;

-- Most frequently run queries
SELECT 
    DIGEST_TEXT,
    COUNT_STAR as exec_count,
    ROUND(AVG_TIMER_WAIT/1000000000, 3) as avg_time_ms
FROM performance_schema.events_statements_summary_by_digest
ORDER BY COUNT_STAR DESC
LIMIT 10;

-- Reset statistics
TRUNCATE performance_schema.events_statements_summary_by_digest;

Advantages vs Slow Query Log

Feature Slow Query Log Performance Schema
Real-time ❌ Need to read file ✅ Query directly
Aggregation ❌ Need tools ✅ Auto-aggregated
Overhead 🟡 Disk I/O 🟢 In-memory
History ✅ Keeps logs permanently ❌ Resets on restart
Flexibility 🟡 Limited filtering ✅ SQL queries

Recommendation: Use both — Performance Schema for real-time monitoring, Slow Query Log for historical analysis.

Query Optimization Workflow

Step 1: Identify Queries to Optimize

Prioritize by:

  1. High total time — Largest overall impact
  2. High frequency + moderate time — Accumulates into big problem
  3. User-facing queries — Direct UX impact

Step 2: Reproduce and Measure Baseline

-- Enable profiling
SET profiling = 1;

-- Run original query
SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 100;

-- View profile
SHOW PROFILES;
SHOW PROFILE FOR QUERY 1;

Profile output:

+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000050 |
| checking permissions | 0.000010 |
| Opening tables       | 0.000025 |
| init                 | 0.000030 |
| System lock          | 0.000015 |
| optimizing           | 0.000010 |
| statistics           | 0.000080 |
| preparing            | 0.000020 |
| Sorting result       | 0.000010 |
| executing            | 0.000005 |
| Sending data         | 2.345000 |  ← Bottleneck!
| end                  | 0.000010 |
| query end            | 0.000005 |
| closing tables       | 0.000010 |
| freeing items        | 0.000020 |
| cleaning up          | 0.000005 |
+----------------------+----------+

Step 3: Analyze with EXPLAIN

EXPLAIN SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 100;

+----+-------------+--------+------+---------------+------+---------+------+--------+-----------------------------+
| id | select_type | table  | type | possible_keys | key  | key_len | ref  | rows   | Extra                       |
+----+-------------+--------+------+---------------+------+---------+------+--------+-----------------------------+
|  1 | SIMPLE      | orders | ALL  | NULL          | NULL | NULL    | NULL | 500000 | Using where; Using filesort |
+----+-------------+--------+------+---------------+------+---------+------+--------+-----------------------------+

Problems:

  • type: ALL — Full table scan
  • rows: 500000 — Scanning entire table
  • Using filesort — Sort without index

Step 4: Apply Optimization

-- Create composite index
CREATE INDEX idx_status_created ON orders(status, created_at DESC);

Step 5: Verify Improvement

EXPLAIN SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 100;

+----+-------------+--------+------+-------------------+-------------------+---------+-------+------+-------------+
| id | select_type | table  | type | possible_keys     | key               | key_len | ref   | rows | Extra       |
+----+-------------+--------+------+-------------------+-------------------+---------+-------+------+-------------+
|  1 | SIMPLE      | orders | ref  | idx_status_created | idx_status_created | 32     | const | 5000 | Using index |
+----+-------------+--------+------+-------------------+-------------------+---------+-------+------+-------------+

Improvements:

  • type: ref — Using index
  • rows: 5000 — Scanning 100x less
  • Using index — No filesort needed

Step 6: Monitor After Deploy

# After a few days, check if query still appears in slow log
pt-query-digest /var/log/mysql/slow.log --since '2024-03-18' | grep "SELECT.*orders.*status"

Monitoring and Alerting

Slow Query Check Script

#!/bin/bash
# check_slow_queries.sh

LOG_FILE="/var/log/mysql/slow.log"
THRESHOLD=50  # Alert if > 50 slow queries in 5 minutes
SLACK_WEBHOOK="https://hooks.slack.com/services/xxx"

# Count slow queries in last 5 minutes
COUNT=$(pt-query-digest "$LOG_FILE" --since "$(date -d '5 minutes ago' '+%Y-%m-%d %H:%M:%S')" --output json 2>/dev/null | jq '.global.total.count // 0')

if [ "$COUNT" -gt "$THRESHOLD" ]; then
    MESSAGE="⚠️ MySQL Alert: $COUNT slow queries in last 5 minutes"
    curl -X POST -H 'Content-type: application/json' \
        --data "{\"text\":\"$MESSAGE\"}" \
        "$SLACK_WEBHOOK"
fi

Periodic Cron Jobs

# /etc/cron.d/mysql-slow-query-monitor

# Run every 5 minutes
*/5 * * * * root /opt/scripts/check_slow_queries.sh

# Send daily report at 9AM
0 9 * * * root pt-query-digest /var/log/mysql/slow.log --since '24 hours ago' | mail -s "Daily Slow Query Report" dba@company.com

# Rotate log weekly
0 0 * * 0 root mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$(date +\%Y\%m\%d) && mysqladmin flush-logs

Grafana Dashboard

If using Prometheus + Grafana, configure mysqld_exporter:

# prometheus.yml
scrape_configs:
  - job_name: 'mysql'
    static_configs:
      - targets: ['mysql-server:9104']

Key metrics:

  • mysql_global_status_slow_queries — Total slow queries
  • mysql_global_status_questions — Total queries
  • rate(mysql_global_status_slow_queries[5m]) — Slow queries per second

Laravel Integration

Log Slow Queries from Application

// app/Providers/AppServiceProvider.php
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Log;

public function boot()
{
    if (config('app.debug')) {
        DB::listen(function ($query) {
            if ($query->time > 1000) { // > 1 second
                Log::warning('Slow Query', [
                    'sql' => $query->sql,
                    'bindings' => $query->bindings,
                    'time' => $query->time . 'ms',
                    'connection' => $query->connectionName,
                ]);
            }
        });
    }
}

Custom Artisan Command

// app/Console/Commands/AnalyzeSlowQueries.php
namespace App\Console\Commands;

use Illuminate\Console\Command;
use Illuminate\Support\Facades\DB;

class AnalyzeSlowQueries extends Command
{
    protected $signature = 'db:slow-queries {--limit=10}';
    protected $description = 'Analyze slow queries from Performance Schema';

    public function handle()
    {
        $limit = $this->option('limit');

        $results = DB::select("
            SELECT 
                LEFT(DIGEST_TEXT, 100) as query_preview,
                COUNT_STAR as exec_count,
                ROUND(SUM_TIMER_WAIT/1000000000000, 3) as total_time_sec,
                ROUND(AVG_TIMER_WAIT/1000000000, 3) as avg_time_ms,
                SUM_ROWS_EXAMINED as rows_examined,
                SUM_ROWS_SENT as rows_sent
            FROM performance_schema.events_statements_summary_by_digest
            ORDER BY SUM_TIMER_WAIT DESC
            LIMIT ?
        ", [$limit]);

        $this->table(
            ['Query', 'Count', 'Total Time (s)', 'Avg Time (ms)', 'Rows Examined', 'Rows Sent'],
            collect($results)->map(fn($r) => [
                $r->query_preview,
                $r->exec_count,
                $r->total_time_sec,
                $r->avg_time_ms,
                $r->rows_examined,
                $r->rows_sent,
            ])
        );
    }
}

Usage:

php artisan db:slow-queries --limit=20

Best Practices

1. Set Reasonable Thresholds

  • Development: 100ms
  • Production: 1-2 seconds
  • Batch jobs: 10-30 seconds (with separate log prefix)

2. Log Rotation

# /etc/logrotate.d/mysql-slow
/var/log/mysql/slow.log {
    daily
    rotate 14
    compress
    delaycompress
    missingok
    create 640 mysql mysql
    postrotate
        mysqladmin flush-logs
    endscript
}

3. Separate Slow Log for Batch Jobs

// In batch job
DB::statement("SET SESSION long_query_time = 30");
// ... run batch operations ...
DB::statement("SET SESSION long_query_time = 1");

4. Regular Review Schedule

  • Daily: Check alerts/anomalies
  • Weekly: Review top 10 slow queries
  • Monthly: Full analysis and index cleanup

Conclusion

Slow Query Log is an essential tool for any production MySQL. Combined with Performance Schema and tools like pt-query-digest, you can:

  • Detect slow queries before users complain
  • Identify exactly which queries need optimization
  • Measure effectiveness after optimization

Key takeaways:

  1. Enable slow query log from the start
  2. Use pt-query-digest for analysis
  3. Performance Schema for real-time monitoring
  4. Prioritize queries by total time × frequency
  5. Verify improvement after each optimization
  6. Set up alerting and regular reviews

With these 3 articles on EXPLAIN, Indexing Strategies, and Slow Query Log, you now have enough knowledge to debug and optimize most MySQL performance issues in practice.

Comments