KAL
Menu

Log Query Lambat

Mengaktifkan slow query log dan menemukan query bermasalah dari catatannya.

Daftar isi

EXPLAIN menilai query sebelum dijalankan, sedangkan slow query log mencatat query yang ternyata berlangsung lambat ketika benar-benar dieksekusi, sehingga keduanya saling melengkapi. Topik ini membahas cara mengaktifkan slow query log, yaitu catatan server berisi query yang durasinya melewati ambang tertentu, melalui variabel slow_query_log, long_query_time, dan log_queries_not_using_indexes. Isi berkas yang ditunjuk oleh slow_query_log_file kemudian dibaca. Latihan menggunakan query lambat buatan yang durasinya dapat dijamin, sehingga setiap catatan dapat dihasilkan ulang kapan pun. Setelah topik ini, query bermasalah dapat ditemukan dari catatan server, bukan dari dugaan semata.

Data latihan#

Berkas berikut membuat ulang basis data perpustakaan_lambat dari nol. Tabel anggota berisi 2500 baris dan tabel peminjaman berisi 100000 baris dengan pembagian yang rapi, yaitu setiap anggota memiliki tepat 40 peminjaman. Satu-satunya indeks adalah PRIMARY KEY, sehingga query yang menyaring kolom lain pasti memindai seluruh tabel. Tabel peminjaman sengaja tidak diberi indeks secondary lain karena fokus topik ini adalah pencatatan durasi pada server, bukan perbandingan rencana eksekusi. Perintah ANALYZE TABLE dijalankan di akhir berkas agar statistik kedua tabel terbarui.

sql skema-lambat.sql 
-- tidak-dijalankan
-- Skema basis data latihan "perpustakaan_lambat" untuk topik log query lambat.
-- Menjalankan ulang berkas ini selalu menghasilkan isi yang sama.

DROP DATABASE IF EXISTS perpustakaan_lambat;
CREATE DATABASE perpustakaan_lambat;
USE perpustakaan_lambat;

SET SESSION cte_max_recursion_depth = 1000000;

CREATE TABLE anggota (
  anggota_id INT UNSIGNED PRIMARY KEY AUTO_INCREMENT,
  nama VARCHAR(30) NOT NULL
);

CREATE TABLE peminjaman (
  peminjaman_id INT UNSIGNED PRIMARY KEY AUTO_INCREMENT,
  anggota_id INT UNSIGNED NOT NULL,
  tanggal_pinjam DATE NOT NULL,
  status VARCHAR(10) NOT NULL
);

INSERT INTO anggota (nama)
WITH RECURSIVE urut AS (
  SELECT 1 AS n
  UNION ALL
  SELECT n + 1 FROM urut WHERE n < 2500
)
SELECT CONCAT('Anggota ', n) FROM urut;

INSERT INTO peminjaman (anggota_id, tanggal_pinjam, status)
WITH RECURSIVE urut AS (
  SELECT 1 AS n
  UNION ALL
  SELECT n + 1 FROM urut WHERE n < 100000
)
SELECT
  (n MOD 2500) + 1,
  DATE_ADD('2024-01-01', INTERVAL (n MOD 730) DAY),
  ELT((n MOD 3) + 1, 'dipinjam', 'kembali', 'terlambat')
FROM urut;

ANALYZE TABLE anggota;
ANALYZE TABLE peminjaman;
bash 
# membuat ulang basis data latihan beserta statistiknya
mysql -t -u root < skema-lambat.sql
text Keluaran 
+-----------------------------+---------+----------+----------+
| Table                       | Op      | Msg_type | Msg_text |
+-----------------------------+---------+----------+----------+
| perpustakaan_lambat.anggota | analyze | status   | OK       |
+-----------------------------+---------+----------+----------+
+--------------------------------+---------+----------+----------+
| Table                          | Op      | Msg_type | Msg_text |
+--------------------------------+---------+----------+----------+
| perpustakaan_lambat.peminjaman | analyze | status   | OK       |
+--------------------------------+---------+----------+----------+

Dua baris status OK menandakan basis data siap dipakai. Karena tabel dibangun ulang dari nol pada setiap eksekusi, isi kedua tabel selalu sama, sehingga jumlah baris yang diperiksa pada catatan log di bagian akhir topik dapat diulang dengan hasil yang sama.

Mengaktifkan slow query log#

Slow query log dikendalikan oleh variabel server yang semuanya dapat diubah tanpa menghidupkan ulang server. Variabel slow_query_log menyalakan atau mematikan pencatatan, variabel long_query_time menetapkan ambang durasi dalam detik, dan variabel slow_query_log_file menunjuk berkas tempat catatan ditulis. Nilai default long_query_time adalah 10 detik, angka yang terlalu tinggi untuk latihan, sehingga ambangnya diturunkan menjadi 0,2 detik agar query buatan yang berdurasi di bawah satu detik tetap tercatat.

Perintah berikut mengaktifkan pencatatan dan menurunkan ambangnya pada tingkat global.

bash 
# mengaktifkan slow query log dan menurunkan ambang durasinya
mysql -u root -e "SET GLOBAL slow_query_log = ON; SET GLOBAL long_query_time = 0.2;"

Keadaan baru dapat diperiksa dari sesi yang dibuka setelah perubahan tersebut. Perubahan SET GLOBAL hanya berlaku bagi sesi yang dibuka setelahnya, sehingga pemeriksaan berikut dijalankan dari pemanggilan klien mysql yang terpisah. Perbedaan perilaku ini berakar pada cakupan variabelnya, yaitu slow_query_log hanya memiliki nilai global, sedangkan long_query_time memiliki nilai global dan nilai sesi sekaligus.

bash 
# memeriksa status dari sesi baru
mysql -u root -t -e "SELECT @@slow_query_log AS aktif, @@long_query_time AS ambang_detik;"
text Keluaran 
+-------+--------------+
| aktif | ambang_detik |
+-------+--------------+
|     1 |     0.200000 |
+-------+--------------+

Lokasi berkas log dibaca dari variabel slow_query_log_file, dan nilainya berbeda antar pemasangan karena diambil dari nama host server.

bash 
# membaca lokasi berkas slow query log
mysql -u root -t -e "SELECT @@slow_query_log_file AS berkas;"
text Keluaran 
+-------------------------------------------------------------------------+
| berkas                                                                  |
+-------------------------------------------------------------------------+
| /home/kal/my-project/mysql-data/c-6ae7d787-14127d0f-437d218fac8b-slow.log |
+-------------------------------------------------------------------------+

Semua query yang berlangsung setelah titik ini dan melewati ambang 0,2 detik masuk ke berkas tersebut, tanpa perlu menghidupkan ulang server. Pencatatan mulai bekerja seketika pada seluruh koneksi baru, sedangkan keadaan server dikembalikan seperti semula pada bagian akhir topik.

Query lambat buatan#

Untuk menguji pencatatan tanpa menunggu query sungguhan menjadi lambat, MySQL menyediakan fungsi SLEEP(), yaitu fungsi yang menahan eksekusi selama jumlah detik yang diberikan lalu mengembalikan nilai 0. Durasi fungsi ini dapat dijamin, sehingga query buatan melewati ambang 0,2 detik dengan pasti. Query buatan seperti ini menggantikan beban kerja nyata yang durasinya sulit diulang, karena durasi query asli bergantung pada isi tabel, cache, dan beban server pada saat diukur.

bash 
# query buatan yang berhenti selama 0,5 detik
mysql -u root perpustakaan_lambat -t -e "SELECT SLEEP(0.5) AS jeda_buatan;"
text Keluaran 
+-------------+
| jeda_buatan |
+-------------+
|           0 |
+-------------+

Durasi 0,5 detik melampaui ambang 0,2 detik, sehingga query ini masuk ke dalam log meskipun tidak menyentuh satu baris tabel pun. Dalam pemakaian nyata, posisi ini diisi oleh query sungguhan, misalnya pemindaian tabel besar atau pengurutan yang tidak terbantu indeks. Fungsi SLEEP() murni alat pengujian, dan query seperti ini seharusnya tidak pernah ada pada server yang melayani aplikasi.

Pencatatan query tanpa indeks#

Ambang durasi bukan satu-satunya pintu masuk ke log. Variabel log_queries_not_using_indexes memerintahkan server mencatat pula setiap query yang tidak menggunakan indeks, tanpa memandang durasinya. Variabel ini berguna untuk menemukan query yang cepat hari ini tetapi berpotensi membengkak ketika datanya bertambah. Perintah berikut menyalakannya, kemudian query penghitungan pada kolom yang tidak terindeks dijalankan.

bash 
# mencatat pula query yang tidak menggunakan indeks
mysql -u root -e "SET GLOBAL log_queries_not_using_indexes = ON;"
bash 
# query tanpa indeks yang tetap tercatat meski durasinya singkat
mysql -u root perpustakaan_lambat -t -e "SELECT COUNT(*) AS jumlah_terlambat FROM peminjaman WHERE status = 'terlambat';"
text Keluaran 
+------------------+
| jumlah_terlambat |
+------------------+
|            33333 |
+------------------+

Query ini selesai hanya sekitar 0,01 detik pada server latihan, jauh di bawah ambang 0,2 detik, tetapi tetap tercatat karena memindai seluruh 100000 baris peminjaman tanpa indeks. Pada EXPLAIN, bentuk query ini dilaporkan sebagai pemindaian seluruh tabel, dan log kini menunjukkan bahwa query seperti itu benar-benar dijalankan pada server.

Anatomi baris log#

Isi log berupa urutan entri, satu entri untuk setiap query yang tercatat. Karena setiap entri memuat waktu dan durasi yang berubah pada setiap eksekusi, isi log tidak ditempelkan sebagai keluaran di sini. Bentuk entri ditampilkan pada blok berikut sesuai format yang didokumentasikan manual resmi, dengan nilai-nilai contoh dari eksekusi nyata.

text Keluaran yang diharapkan 
# Time: 2026-11-02T04:11:08.155288Z
# User@Host: root[root] @ localhost []  Id:  2297
# Query_time: 0.500162  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
use perpustakaan_lambat;
SET timestamp=1793592667;
SELECT SLEEP(0.5) AS jeda_buatan;

Setiap entri diawali tiga baris komentar berawalan tanda pagar. Baris Time adalah waktu pencatatan, User@Host menyebut pengguna beserta asal koneksi, sedangkan Id adalah nomor koneksi di server. Baris ketiga memuat ukuran biaya query, yaitu Query_time untuk durasinya, Lock_time untuk waktu yang habis menunggu kunci, Rows_sent untuk jumlah baris yang dikirim ke klien, dan Rows_examined untuk jumlah baris yang benar-benar diperiksa. Setelah komentar, baris use menunjukkan basis data default yang aktif, SET timestamp= mencatat waktu awal query agar catatan dapat diputar ulang, dan baris terakhir berisi teks query persis seperti yang dikirim klien.

Dua entri yang dihasilkan topik ini membentuk pola yang berlawanan. Entri SLEEP() menunjukkan Query_time sekitar 0,5 dengan Rows_examined hanya 1, sedangkan entri query COUNT menunjukkan durasi sekitar 0,01 detik dengan Rows_examined sebesar 100000. Kolom rows pada EXPLAIN adalah perkiraan sebelum query dijalankan, sedangkan Rows_examined pada log adalah jumlah baris yang benar-benar diperiksa saat eksekusi, sehingga keduanya saling menguji. Selain entri query, berkas juga memuat baris pembuka seperti started with: yang muncul setiap kali server dijalankan ulang.

Menonaktifkan pencatatan kembali#

Server latihan dipakai bersama oleh banyak topik, sehingga keadaan server perlu dikembalikan setiap kali demonstrasi selesai. Pencatatan query tanpa indeks dimatikan terlebih dahulu, ambang durasi dikembalikan ke nilai default 10 detik, dan pencatatan utama dimatikan. Ketiga pernyataan dijalankan dari satu pemanggilan klien yang sama, dan pemeriksaan akhir digabungkan pada perintah tersebut sehingga keadaan server sesudahnya langsung terlihat.

bash 
# menonaktifkan kembali slow query log beserta variabel pendukungnya
mysql -u root -t -e "SET GLOBAL log_queries_not_using_indexes = OFF; SET GLOBAL long_query_time = 10; SET GLOBAL slow_query_log = OFF; SELECT @@slow_query_log AS aktif;"
text Keluaran 
+-------+
| aktif |
+-------+
|     0 |
+-------+

Nilai 0 pada keluaran menegaskan bahwa server sudah kembali ke keadaan semula. Berkas lognya tetap ada di lokasi yang ditunjukkan slow_query_log_file dan aman untuk dibaca kapan pun, sedangkan catatan baru tidak lagi ditambahkan. Pada server produksi, langkah yang sama menjadi kebiasaan penutup setiap sesi penalaan agar log tidak tumbuh tanpa pengawasan.

Kesalahan umum#

Kesalahan pertama adalah mengira SET GLOBAL segera mengubah sesi yang sedang terbuka. Variabel long_query_time memiliki nilai sesi sendiri, sehingga sesi yang dibuka sebelum perubahan tetap menggunakan ambang lamanya, sedangkan sesi baru mengikuti nilai globalnya. Bila satu sesi perlu diubah tanpa menutupnya, gunakan SET SESSION long_query_time pada sesi tersebut. Kesalahan kedua adalah membiarkan log_queries_not_using_indexes aktif selamanya pada server yang sibuk. Log membengkak karena setiap query tanpa indeks tercatat, dan berkas yang terlalu besar justru menyulitkan pencarian, sehingga variabel ini sebaiknya diaktifkan sementara saat mengejar masalah, lalu dinonaktifkan kembali setelah akar masalah ditemukan. Kesalahan ketiga adalah menganggap perubahan SET GLOBAL bertahan selamanya. Semua perubahan pada topik ini hilang ketika server dijalankan ulang, karena nilai global tidak ditulis ke berkas konfigurasi. Agar pencatatan tetap hidup setelah server berjalan kembali, konfigurasi yang diinginkan harus dinyatakan pada bagian [mysqld] berkas konfigurasi server, misalnya slow_query_log=ON dan long_query_time=0.2.

Ringkasan#

  • Variabel slow_query_log menyalakan pencatatan, long_query_time menetapkan ambang durasi dalam detik, dan slow_query_log_file menunjuk berkas catatannya.
  • SET GLOBAL hanya berlaku bagi sesi yang dibuka setelahnya dan hilang ketika server dijalankan ulang, sehingga konfigurasi tetap harus ditulis pada berkas konfigurasi.
  • Variabel log_queries_not_using_indexes mencatat setiap query tanpa indeks tanpa memandang durasi, sehingga query yang cepat hari ini tetap dapat dikenali sebelum datanya membesar.
  • Setiap entri log memuat Query_time dan Rows_examined, yaitu angka hasil eksekusi nyata yang menguji perkiraan pada EXPLAIN.

Referensi#