Slow QUERY Log

Keluhan paling umum yang diterima administrator adalah “aplikasinya lambat” — dan jawabnya jarang berada di satu tempat. General query log dari chapter sebelumnya merekam semuanya, justru karena itu sulit dipakai mencari tersangka. Slow query log bekerja sebaliknya: MySQL hanya mencatat query yang berjalan lebih lama dari sebuah ambang waktu, sehingga isinya selalu berisi kandidat optimasi yang paling layak diselidiki. Chapter ini menyalakan log tersebut di server uji, menurunkan ambangnya sampai nol agar contoh mudah ditangkap, membaca isinya dari tabel dan format file, lalu mengembalikan seluruh pengaturan supaya server kembali bersih.

Ambang Default yang Perlu Diketahui #

Tiga variabel mengendalikan perilaku slow query log. Kita baca nilainya yang masih perawan:

SHOW VARIABLES LIKE 'slow_query_log';
SHOW VARIABLES LIKE 'long_query_time';
SHOW VARIABLES LIKE 'min_examined_row_limit';

Output yang Dihasilkan:

+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | OFF   |
+----------------+-------+
1 row in set (0.00 sec)

+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| min_examined_row_limit | 0     |
+------------------------+-------+
1 row in set (0.00 sec)

Makna ketiganya sederhana. slow_query_log adalah saklar utama yang mati secara default. long_query_time menentukan ambang detik — query yang berjalan 10 detik atau lebih akan dicatat, dan nilai 10 itu memang standar pabrik. min_examined_row_limit adalah saringan tambahan: query yang memeriksa lebih sedikit baris dari nilai ini tidak dianggap layak dicatat, sebab lookup kecil yang kebetulan lambat hampir selalu bukan sumber masalah — nilai 0 berarti saringan ini tidak aktif.

Menyalakan Log dan Menurunkan Ambang #

Kita siapkan tabel kecil untuk dijadikan bahan uji, lalu menyalakan log dengan tujuan tabel seperti chapter sebelumnya:

DROP DATABASE IF EXISTS belajar_admin;
CREATE DATABASE belajar_admin;
USE belajar_admin;
CREATE TABLE pesanan (id INT PRIMARY KEY, produk_id INT, jumlah INT, total DECIMAL(10,2));
INSERT INTO pesanan VALUES (1, 1, 2, 170000.00), (2, 1, 1, 85000.00), (3, 2, 5, 400000.00);

Output yang Dihasilkan:

Query OK, 0 rows affected, 1 warning (0.00 sec)

Query OK, 1 row affected (0.00 sec)

Database changed
Query OK, 0 rows affected (0.00 sec)

Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

Sekarang pengaktifannya. Satu detail penting: slow_query_log dan log_output hanya ber-scope global, tetapi long_query_time ber-scope global dan session — dan perbedaan itu terlihat langsung di blok berikut:

SET GLOBAL slow_query_log = OFF;
TRUNCATE TABLE mysql.slow_log;
SET GLOBAL log_output = 'TABLE';
SET GLOBAL slow_query_log = ON;
SHOW VARIABLES LIKE 'slow_query_log';
SET GLOBAL long_query_time = 0;
SHOW VARIABLES LIKE 'long_query_time';

Output yang Dihasilkan:

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

Baris ON setelah SHOW VARIABLES LIKE 'slow_query_log' membuktikan saklar globalnya bekerja seketika. Sebaliknya, long_query_time masih terbaca 10.000000 meskipun SET GLOBAL long_query_time = 0 baru saja dijalankan — nilai session kita adalah salinan lama yang tidak tersentuh oleh perubahan global. Nilai baru akan diwarisi oleh koneksi-koneksi yang dibuka setelahnya; bila kita ingin menurunkan ambang khusus untuk sesi yang sedang berjalan, perintahnya SET SESSION long_query_time = 0. Blok-blok contoh tutorial ini selalu berjalan dalam sesi baru, jadi sesi pembaca berikutnya otomatis mewarisi angka nol — dan itulah yang kita manfaatkan sekarang.

Membaca Log dari Tabel #

Ambang nol membuat semua statement sesi berikutnya dianggap lambat dan dicatat — mode yang berguna untuk belajar, sebab kita tidak perlu menunggu query sungguhan berjalan 10 detik:

-- @check
SELECT COUNT(*) AS jumlah_pesanan FROM pesanan;
SELECT AVG(total) AS rata_rata_pesanan FROM pesanan;
SELECT CONVERT(sql_text USING utf8mb4) AS teks_query, query_time, lock_time,
       rows_sent, rows_examined
FROM mysql.slow_log
ORDER BY start_time;

Output yang Dihasilkan:

+----------------+
| jumlah_pesanan |
+----------------+
|              3 |
+----------------+
1 row in set (0.00 sec)

+-------------------+
| rata_rata_pesanan |
+-------------------+
|     218333.333333 |
+-------------------+
1 row in set (0.00 sec)

+-----------------------------------------------------+-----------------+-----------------+-----------+---------------+
| teks_query                                          | query_time      | lock_time       | rows_sent | rows_examined |
+-----------------------------------------------------+-----------------+-----------------+-----------+---------------+
| select @@version_comment limit 1                    | 00:00:00.000108 | 00:00:00.000000 |         1 |             1 |
| SELECT COUNT(*) AS jumlah_pesanan FROM pesanan      | 00:00:00.000588 | 00:00:00.000003 |         1 |             0 |
| SELECT AVG(total) AS rata_rata_pesanan FROM pesanan | 00:00:00.000125 | 00:00:00.000000 |         1 |             3 |
+-----------------------------------------------------+-----------------+-----------------+-----------+---------------+
3 rows in set (0.00 sec)

Tiga baris log yang tampil menceritakan urutan kejadian yang rapi. Baris pertama adalah statement banner klien (select @@version_comment limit 1) — bukti bahwa sesi ini mewarisi ambang global 0 sejak statement pertamanya. Dua baris berikutnya adalah kedua query agregasi kita, lengkap dengan angka-angka diagnosis di kolom-kolomnya:

Kolom terakhir itulah detektor utama masalah index: query yang mengirim 1 baris tetapi memeriksa 1 juta baris hampir pasti kehilangan index di kolom filternya. Perlu dicatat juga dua keunikan blok ini: pertama, sql_text di tabel mysql.slow_log bertipe biner sehingga kita membungkusnya dengan CONVERT(... USING utf8mb4) agar terbaca sebagai teks; kedua, statement pembaca log itu sendiri tidak muncul dalam hasil — baris slow log baru ditulis setelah sebuah statement selesai, jadi pembacaan log tidak pernah melihat dirinya sendiri.

Membaca Log dari File #

Mode tabel yang kita pakai nyaman karena bisa di-WHERE, namun konfigurasi default produksi justru menulis slow log ke file — lokasinya ditentukan variabel slow_query_log_file, umumnya berada di direktori log seperti /var/log/mysql/. Format file berupa teks: setiap kejadian dibuka tiga baris header berawalan #, lalu diikuti teks querynya. Isi header itu sama persis dengan kolom tabel yang baru kita pelajari:

Contoh baris Query_time di atas layak dicermati sebagai ilustrasi kasus nyata: query tersebut mengirim 5 baris hasil, tetapi memeriksa lebih dari satu juta baris — pola klasik tabel besar tanpa index pada kolom GROUP BY. Membaca file mentah dengan less atau grep cocok untuk insiden tunggal, namun file yang berisi puluhan ribu baris butuh diringkas. MySQL membawa alatnya sendiri — mysqldumpslow mengelompokkan query serupa dan mengurutkan hasilnya, membatasi sepuluh teratas sekaligus mengganti nilai literal menjadi N atau S sehingga pola query terlihat alih-alih ratusan duplikat:

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

Opsi -s t memilih urutan berdasarkan total waktu eksekusi dan -t 10 membatasi sepuluh besar. Perlu diingat bahwa mysqldumpslow bekerja pada file, bukan tabel — satu alasan lagi mengapa mode file tetap populer di server produksi.

Mematikan Log dan Pola Produksi #

Blok penutup mengembalikan seluruh pengaturan dan membersihkan jejak uji sekaligus:

SET GLOBAL slow_query_log = OFF;
SET GLOBAL long_query_time = 10;
SET GLOBAL log_output = 'FILE';
TRUNCATE TABLE mysql.slow_log;
DROP DATABASE belajar_admin;

Output yang Dihasilkan:

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)

Lima statement ini menegaskan ulang disiplin yang sama dengan general log: saklar dimatikan, ambang dikembalikan ke default pabrik, tujuan log kembali ke file, tabel log dikosongkan, dan database latihan dihapus. Di server produksi polanya serupa namun ambangnya bukan nol — praktik yang umum adalah long_query_time = 1 (query di atas satu detik dicatat), lalu diturunkan bertahap ke 0.5 atau 0.2 seiring daftar query bermasalah menipis. Opsi pendamping log_queries_not_using_indexes turut mencatat query yang memindai tabel tanpa index meski waktunya cepat — sinyal dini sebelum tabel membesar dan query itu benar-benar menjadi lambat.

Referensi #

• The Slow Query Log — MySQL 8.4 Reference Manual
• Server Logs — MySQL 8.4 Reference Manual
• Selecting General Query Log and Slow Query Log Output Destinations — MySQL 8.4 Reference Manual

Slow query log kini memberi kita daftar tersangka yang terurut berdasarkan waktu. Sebagian besar tersangka akan lolos begitu index yang tepat ditambahkan; sisanya menuntut pekerjaan pemeliharaan seperti penyegaran statistik dan penataan ulang ruang tabel — materi chapter penutup section ini.