MySQL Slow Query Log — Tìm và tối ưu các query chậm trong Production

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

Trong production, bạn không thể ngồi chạy EXPLAIN cho từng query. Slow Query Log là "camera giám sát" tự động ghi lại tất cả các query chậm để bạn phân tích và tối ưu sau.

Bài viết này sẽ hướng dẫn bạn từ cấu hình cơ bản đến xây dựng quy trình monitoring hoàn chỉnh.

Cấu hình Slow Query Log

Kiểm tra cấu hình hiện tại

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

Output mẫu:

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

Bật Slow Query Log

Cách 1: Cấu hình động (không cần restart)

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;  -- Log query > 1 giây
SET GLOBAL log_queries_not_using_indexes = 'ON';  -- Log query không dùng index
SET GLOBAL log_slow_admin_statements = 'ON';  -- Log cả ALTER, OPTIMIZE, etc.
SET GLOBAL min_examined_row_limit = 1000;  -- Chỉ log nếu scan > 1000 rows

Cách 2: Cấu hình vĩnh viễn (my.cnf)

# /etc/mysql/mysql.conf.d/mysqld.cnf hoặc /etc/my.cnf

[mysqld]
# Bật slow query log
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log

# Ngưỡng thời gian (giây, hỗ trợ microseconds)
long_query_time = 0.5

# Log các query không dùng index
log_queries_not_using_indexes = 1

# Giới hạn log query không dùng index (tránh spam)
log_throttle_queries_not_using_indexes = 10

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

# Chỉ log query scan nhiều rows
min_examined_row_limit = 100

Sau đó restart MySQL:

sudo systemctl restart mysql

Cấu hình khuyến nghị theo môi trường

Development:

long_query_time = 0.1  # 100ms - bắt mọi query chậm
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 giây
log_queries_not_using_indexes = 0  # Tắt để tránh log quá nhiều
min_examined_row_limit = 1000
log_throttle_queries_not_using_indexes = 5  # Max 5 logs/phút cho loại này

Đọc hiểu Slow Query Log

Format của log entry

# 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;

Giải thích:

  • Time: Thời điểm query hoàn thành
  • User@Host: User MySQL và hostname/IP client
  • Query_time: Tổng thời gian thực thi (giây)
  • Lock_time: Thời gian chờ lock
  • Rows_sent: Số rows trả về client
  • Rows_examined: Số rows MySQL phải scan

Red flags:

  • Rows_examined >> Rows_sent: Query scan quá nhiều nhưng trả về ít → Thiếu index
  • Lock_time cao: Contention issues, có thể do long-running transactions
  • Cùng query xuất hiện nhiều lần: Candidate ưu tiên tối ưu

Xem log trực tiếp

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

# Xem 50 entries gần nhất
sudo tail -100 /var/log/mysql/slow.log

# Tìm các query của một user cụ thể
sudo grep -A5 "app_user" /var/log/mysql/slow.log

Phân tích với pt-query-digest

pt-query-digest (từ Percona Toolkit) là công cụ số 1 để phân tích slow query log.

Cài đặt

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

# CentOS/RHEL
sudo yum install percona-toolkit

# macOS
brew install percona-toolkit

Sử dụng cơ bản

# Phân tích slow log
pt-query-digest /var/log/mysql/slow.log

# Lưu report
pt-query-digest /var/log/mysql/slow.log > report.txt

# Phân tích log trong khoảng thời gian
pt-query-digest /var/log/mysql/slow.log --since '2024-03-15 00:00:00' --until '2024-03-15 23:59:59'

# Chỉ phân tích top 10 query chậm nhất
pt-query-digest /var/log/mysql/slow.log --limit 10

Đọc hiểu 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

Giải thích:

  1. Profile section: Tóm tắt các query theo thời gian response tổng

    • Rank: Thứ hạng query chậm nhất
    • Response time: Tổng thời gian + % so với tất cả query
    • Calls: Số lần query được gọi
    • R/Call: Response time trung bình mỗi lần
    • V/M: Variance-to-mean ratio (độ ổn định, thấp hơn = ổn định hơn)

  2. Query detail section: Chi tiết từng query

    • Exec time: Min/max/avg/95th percentile của execution time
    • Rows examined: Số rows phải scan
    • Query_time distribution: Histogram cho thấy phân bố thời gian

Query ưu tiên tối ưu:

  • % Response time cao
  • Rows examined >> Rows sent
  • Calls nhiều (ảnh hưởng lớn đến hệ thống)

Các options hữu ích

# Chỉ hiện query có execution time > 2s
pt-query-digest /var/log/mysql/slow.log --filter '$event->{Query_time} > 2'

# Nhóm theo database
pt-query-digest /var/log/mysql/slow.log --group-by db

# Chỉ phân tích SELECT queries
pt-query-digest /var/log/mysql/slow.log --filter '$event->{arg} =~ m/^SELECT/'

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

# So sánh 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

Phân tích với mysqldumpslow

mysqldumpslow là công cụ có sẵn trong MySQL, đơn giản hơn pt-query-digest:

# Top 10 query chậm nhất (theo total time)
mysqldumpslow -s t -t 10 /var/log/mysql/slow.log

# Top 10 query được gọi nhiều nhất
mysqldumpslow -s c -t 10 /var/log/mysql/slow.log

# Top 10 query có avg time cao nhất
mysqldumpslow -s at -t 10 /var/log/mysql/slow.log

# Top 10 query scan nhiều rows nhất
mysqldumpslow -s ar -t 10 /var/log/mysql/slow.log

Sort options (-s):

  • t: Total time
  • at: Average time
  • c: Count (số lần gọi)
  • l: Lock time
  • r: Rows sent
  • ar: Average rows sent

Performance Schema (Thay thế Slow Query Log)

MySQL 5.6+ có Performance Schema - cách hiện đại hơn để monitor query performance.

Bật Query Digests

-- Kiểm tra Performance Schema đã bật chưa
SHOW VARIABLES LIKE 'performance_schema';

-- Bật digest instruments nếu cần
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%';

Query phân tích

-- Top 10 query chậm nhất (theo 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;

-- Query có tỷ lệ Rows_examined/Rows_sent cao (thiếu 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;

-- Query chạy thường xuyên nhất
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;

Ưu điểm so với Slow Query Log

Feature Slow Query Log Performance Schema
Real-time ❌ Cần đọc file ✅ Query trực tiếp
Aggregation ❌ Cần tools ✅ Tự động aggregate
Overhead 🟡 I/O disk 🟢 In-memory
History ✅ Giữ log vĩnh viễn ❌ Reset khi restart
Flexibility 🟡 Limited filtering ✅ SQL queries

Recommendation: Dùng cả hai — Performance Schema cho real-time monitoring, Slow Query Log cho historical analysis.

Quy trình tối ưu query chậm

Bước 1: Xác định query cần tối ưu

Ưu tiên theo:

  1. Total time cao — Ảnh hưởng tổng thể lớn nhất
  2. Frequency cao + moderate time — Tích lũy thành vấn đề lớn
  3. User-facing queries — Ảnh hưởng trực tiếp UX

Bước 2: Reproduce và đo baseline

-- Bật profiling
SET profiling = 1;

-- Chạy query gốc
SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 100;

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

Output profile:

+----------------------+----------+
| 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 |
+----------------------+----------+

Bước 3: Phân tích với 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 |
+----+-------------+--------+------+---------------+------+---------+------+--------+-----------------------------+

Vấn đề:

  • type: ALL — Full table scan
  • rows: 500000 — Scan toàn bộ bảng
  • Using filesort — Sort không dùng index

Bước 4: Áp dụng tối ưu

-- Tạo composite index
CREATE INDEX idx_status_created ON orders(status, created_at DESC);

Bước 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 |
+----+-------------+--------+------+-------------------+-------------------+---------+-------+------+-------------+

Cải thiện:

  • type: ref — Sử dụng index
  • rows: 5000 — Scan ít hơn 100x
  • Using index — Không cần filesort

Bước 6: Theo dõi sau deploy

# Sau vài ngày, kiểm tra query còn xuất hiện trong slow log không
pt-query-digest /var/log/mysql/slow.log --since '2024-03-18' | grep "SELECT.*orders.*status"

Monitoring và Alerting

Script kiểm tra slow queries

#!/bin/bash
# check_slow_queries.sh

LOG_FILE="/var/log/mysql/slow.log"
THRESHOLD=50  # Alert nếu > 50 slow queries trong 5 phút
SLACK_WEBHOOK="https://hooks.slack.com/services/xxx"

# Đếm slow queries trong 5 phút gần nhất
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

Cron job định kỳ

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

# Chạy mỗi 5 phút
*/5 * * * * root /opt/scripts/check_slow_queries.sh

# Gửi daily report lúc 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 hàng tuần
0 0 * * 0 root mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$(date +\%Y\%m\%d) && mysqladmin flush-logs

Grafana Dashboard

Nếu bạn dùng Prometheus + Grafana, cấu hình mysqld_exporter:

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

Các metrics quan trọng:

  • mysql_global_status_slow_queries — Tổng số slow queries
  • mysql_global_status_questions — Tổng số queries
  • rate(mysql_global_status_slow_queries[5m]) — Slow queries per second

Tích hợp với Laravel

Log slow queries từ 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,
            ])
        );
    }
}

Sử dụng:

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

Best Practices

1. Thiết lập ngưỡng hợp lý

  • Development: 100ms
  • Production: 1-2 seconds
  • Batch jobs: 10-30 seconds (với prefix log riêng)

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 cho batch jobs

// Trong batch job
DB::statement("SET SESSION long_query_time = 30");
// ... chạy batch operations ...
DB::statement("SET SESSION long_query_time = 1");

4. Regular review schedule

  • Daily: Kiểm tra alert/anomalies
  • Weekly: Review top 10 slow queries
  • Monthly: Full analysis và cleanup indexes

Kết luận

Slow Query Log là công cụ thiết yếu cho bất kỳ production MySQL nào. Kết hợp với Performance Schema và các tools như pt-query-digest, bạn có thể:

  • Phát hiện query chậm trước khi users phàn nàn
  • Xác định chính xác query cần tối ưu
  • Đo lường hiệu quả sau khi tối ưu

Key takeaways:

  1. Bật slow query log ngay từ đầu
  2. Sử dụng pt-query-digest để phân tích
  3. Performance Schema cho real-time monitoring
  4. Ưu tiên query theo total time × frequency
  5. Verify improvement sau mỗi optimization
  6. Thiết lập alerting và regular review

Với 3 bài viết về EXPLAIN, Indexing Strategies, và Slow Query Log, bạn đã có đủ kiến thức để debug và tối ưu hầu hết các vấn đề performance MySQL trong thực tế.

Bình luận