Query lambat hampir tidak pernah datang mengadu. Pengguna melaporkan “aplikasi kadang lelet” tanpa tahu query mana yang bersalah, dan pengembang menebak-nebak index yang mungkin perlu ditambah. Bab sebelumnya mengajarkan cara MEMPERBAIKI pola query; bab ini mengajarkan cara MENEMUKANNya lebih dulu dengan dua alat pelacak: pg_stat_statements, yang mengingat setiap statement pernah dieksekusi beserta jumlah panggilannya, dan log_min_duration_statement, yang mencatat teks query yang melewati ambang durasi ke log server. Kombinasi keduanya mengubah optimasi dari tebakan menjadi daftar tersortir berisi tersangka beserta buktinya.

pg_stat_statements: Memori Kolektif Semua Query #

pg_stat_statements adalah ekstensi resmi yang mengumpulkan statistik per-statement untuk seluruh server. Karena bekerja di level proses, ekstensi ini harus dimuat oleh administrator lewat shared_preload_libraries di postgresql.conf — di server latihan kita sudah aktif — lalu diaktifkan per database dengan CREATE EXTENSION. File berikut mengaktifkannya, mereset semua statistik agar daftar hanya berisi beban latihan ini, lalu menjalankan beban tetap: satu query “mahal” (scan penuh 50.000 baris) tiga kali dan satu query “murah” (primary key) dua kali:

sql buat-beban.sql 
-- pg_stat_statements harus dimuat lewat shared_preload_libraries
-- oleh administrator server, lalu diaktifkan per database.
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

-- Empat pengaturan perilaku ekstensi, terbaca dari pg_settings.
SELECT name, setting
FROM pg_settings
WHERE name IN ('pg_stat_statements.max',
               'pg_stat_statements.save',
               'pg_stat_statements.track',
               'pg_stat_statements.track_utility')
ORDER BY name;

-- Mulai dari nol agar daftar hanya berisi beban latihan ini.
SELECT pg_stat_statements_reset() IS NOT NULL AS statistik_direset;

CREATE TABLE penjualan_slow (
    id integer GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
    produk text NOT NULL,
    jumlah integer NOT NULL
);

INSERT INTO penjualan_slow (produk, jumlah)
SELECT (ARRAY['Kopi','Teh','Gula'])[1 + g % 3], 1 + g % 10
FROM generate_series(1, 50000) AS g;

ANALYZE penjualan_slow;

-- Beban tetap: query "mahal" (scan penuh, tanpa index) tiga kali,
-- query "murah" (primary key) dua kali.
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE id = 42;
SELECT count(*) FROM penjualan_slow WHERE id = 4242;

-- Daftar statement tercatat: literal dinormalkan menjadi $1, $2,
-- dan dbid dibatasi ke database ini agar beban sesi lain tidak ikut.
SELECT query, calls, rows
FROM pg_stat_statements
WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
ORDER BY calls DESC, query;

Output yang Dihasilkan:

text 
CREATE EXTENSION
               name               | setting 
----------------------------------+---------
 pg_stat_statements.max           | 5000
 pg_stat_statements.save          | on
 pg_stat_statements.track         | top
 pg_stat_statements.track_utility | on
(4 rows)

 statistik_direset 
-------------------
 t
(1 row)

CREATE TABLE
INSERT 0 50000
ANALYZE
 count 
-------
  8334
(1 row)

 count 
-------
  8334
(1 row)

 count 
-------
  8334
(1 row)

 count 
-------
     1
(1 row)

 count 
-------
     1
(1 row)

                                 query                                 | calls | rows  
-----------------------------------------------------------------------+-------+-------
 SELECT count(*) FROM penjualan_slow WHERE produk = $1 AND jumlah > $2 |     3 |     3
 SELECT count(*) FROM penjualan_slow WHERE id = $1                     |     2 |     2
 ANALYZE penjualan_slow                                                |     1 |     0
 CREATE TABLE penjualan_slow (                                        +|     1 |     0
     id integer GENERATED ALWAYS AS IDENTITY PRIMARY KEY,             +|       | 
     produk text NOT NULL,                                            +|       | 
     jumlah integer NOT NULL                                          +|       | 
 )                                                                     |       | 
 INSERT INTO penjualan_slow (produk, jumlah)                          +|     1 | 50000
 SELECT (ARRAY[$1,$2,$3])[$4 + g % $5], $6 + g % $7                   +|       | 
 FROM generate_series($8, $9) AS g                                     |       | 
 SELECT pg_stat_statements_reset() IS NOT NULL AS statistik_direset    |     1 |     1
(6 rows)

Empat fakta penting terbaca dari daftar tersebut. Pertama, literal dinormalkan: WHERE produk = 'Kopi' AND jumlah > 5 tersimpan sebagai produk = $1 AND jumlah > $2, sehingga ribuan query yang sama strukturnya dari aplikasi tergabung menjadi satu entri — kolom calls itulah yang menghitung 3 dan 2. Kedua, DDL dan utilitas ikut tercatat (CREATE TABLE, INSERT, ANALYZE, bahkan statement resetnya sendiri) karena pg_stat_statements.track_utility aktif. Ketiga, kolom rows menghitung total baris hasil: 50000 untuk INSERT, 1 per panggilan count. Keempat, filter dbid membatasi ke database saat ini — tanpa filter itu, daftar akan memuat query dari seluruh database di server yang sama.

Membaca Waktu Eksekusi dari Statistik #

Daftar berdasarkan calls menjawab “apa yang paling sering dieksekusi”; pertanyaan pemburu slow query adalah “apa yang paling mahal per eksekusi”, dan itu dijawab kolom waktu:

sql urut-waktu.sql 
-- Urutkan berdasarkan rata-rata waktu eksekusi per panggilan:
-- inilah cara menemukan query yang paling mahal per eksekusi.
-- Kolom waktu bervariasi antar mesin dan antar eksekusi;
-- kolom calls dan rows stabil untuk beban yang sama.
SELECT query, calls, rows,
       round(mean_exec_time::numeric, 3) AS rata_rata_ms,
       round(total_exec_time::numeric, 1) AS total_ms
FROM pg_stat_statements
WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
ORDER BY mean_exec_time DESC;

Output yang Dihasilkan:

text 
                                     query                                     | calls | rows  | rata_rata_ms | total_ms 
-------------------------------------------------------------------------------+-------+-------+--------------+----------
 INSERT INTO penjualan_slow (produk, jumlah)                                  +|     1 | 50000 |       76.617 |     76.6
 SELECT (ARRAY[$1,$2,$3])[$4 + g % $5], $6 + g % $7                           +|       |       |              | 
 FROM generate_series($8, $9) AS g                                             |       |       |              | 
 ANALYZE penjualan_slow                                                        |     1 |     0 |       22.565 |     22.6
 SELECT count(*) FROM penjualan_slow WHERE produk = $1 AND jumlah > $2         |     3 |     3 |        3.230 |      9.7
 CREATE TABLE penjualan_slow (                                                +|     1 |     0 |        2.136 |      2.1
     id integer GENERATED ALWAYS AS IDENTITY PRIMARY KEY,                     +|       |       |              | 
     produk text NOT NULL,                                                    +|       |       |              | 
     jumlah integer NOT NULL                                                  +|       |       |              | 
 )                                                                             |       |       |              | 
 SELECT pg_stat_statements_reset() IS NOT NULL AS statistik_direset            |     1 |     1 |        0.612 |      0.6
 SELECT query, calls, rows                                                    +|     1 |     6 |        0.093 |      0.1
 FROM pg_stat_statements                                                      +|       |       |              | 
 WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())+|       |       |              | 
 ORDER BY calls DESC, query                                                    |       |       |              | 
 SELECT count(*) FROM penjualan_slow WHERE id = $1                             |     2 |     2 |        0.014 |      0.0
(7 rows)

Output di atas dicatat dari eksekusi nyata dan nilai kolom waktunya pasti berbeda di mesin Anda — bahkan antar eksekusi di mesin yang sama. Itu bukan cacat melainkan sifat dasar pengukuran, dan karena itu urutan baris hasil ORDER BY mean_exec_time DESC bisa sedikit bergeser ketika dua query berdekatan waktunya. Pola yang stabil dan layak dibaca: query scan penuh (produk = $1) berbiaya sekitar 3,2 ms per panggilan — lebih dari 200× query primary key yang hanya 0,014 ms. Perhatikan pula perbedaan membaca rata_rata_ms lawan total_ms: INSERT sekali-jalan tampak paling lambat di kolom rata-rata, padahal beban agregatnya sederhana; sebaliknya, query 3 ms yang dipanggil sejuta kali sehari menumpuk 50 menit di kolom total. Pilih kolom sesuai target perbaikan: rata-rata untuk query yang menghambat satu permintaan, total untuk beban server keseluruhan.

Kolom-kolom view ini pantas dipetakan berdasarkan sifatnya:

KelompokKolomSifat
Identitasquery, dbid, calls, rowsStabil dan deterministik untuk beban tetap
Waktutotal_exec_time, mean_exec_time, stddev_exec_timeBervariasi antar mesin dan antar eksekusi
I/Oshared_blks_hit, shared_blks_read, temp_blks_writtenBervariasi mengikuti kondisi cache
Saat pertama/terakhirmin_exec_time, max_exec_timeBervariasi; berguna mendeteksi lonjakan

Ambang Log Durasi: Bukti di Baris Log #

Statistik menjawab “berapa sering dan berapa mahal”, tetapi kadang kita butuh jejak lengkap: kapan persisnya query itu lambat, dan teks aslinya dengan literal yang utuh. Itu pekerjaan log_min_duration_statement — pengaturan yang memerintahkan server menuliskan setiap query yang berjalan lebih lama dari ambangnya:

sql log-ambang.sql 
-- Ambang log durasi: -1 berarti mati (default PostgreSQL).
SELECT name, setting, unit, context
FROM pg_settings
WHERE name = 'log_min_duration_statement';

-- Setel ambang hanya untuk sesi ini (superuser).
SET log_min_duration_statement = '100ms';
SHOW log_min_duration_statement;

-- Query di bawah 100 ms tidak menulis apa pun ke log;
-- query di atasnya tercatat dengan teks dan durasinya di log server.
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;

RESET log_min_duration_statement;
SHOW log_min_duration_statement;

Output yang Dihasilkan:

text 
            name            | setting | unit |  context  
----------------------------+---------+------+-----------
 log_min_duration_statement | -1      | ms   | superuser
(1 row)

SET
 log_min_duration_statement 
----------------------------
 100ms
(1 row)

 count 
-------
  8334
(1 row)

RESET
 log_min_duration_statement 
----------------------------
 -1
(1 row)

Nilai default -1 berarti fitur mati: tidak ada query yang dicatat durasinya. SET ... = '100ms' menyalakannya untuk sesi ini saja — kolom context = superuser pada output mengonfirmasi bahwa pengaturannya bisa diubah per sesi oleh superuser tanpa menyentuh server — dan RESET mengembalikannya. Query count kita selesai sekitar 3 ms, jauh di bawah ambang, sehingga tidak menulis apa pun ke log; sedangkan query yang melewati 100 ms akan menuliskan baris berisi durasi dan teks lengkapnya ke log server. Pengaturan permanen dilakukan lewat postgresql.conf (atau ALTER SYSTEM SET) dan dibaca ulang dengan reload. Ke mana tulisannya pergi? Itu ditentukan log_destination: default stderr berarti baris log ikut keluaran kesalahan proses server — di lingkungan latihan ini berkas log yang ditunjuk pg_ctl -l, di server systemd berarti jurnal journalctl, di container berarti stdout yang dikapalkan ke pusat log; menyalakan logging_collector memindahkannya ke berkas terkelola di direktori data. Pilih nilai ambang yang menyaring: 0 mencatat SEMUA query (berguna hanya untuk debugging singkat), sedangkan ambang seperti 200–500 ms hanya menangkap query yang benar-benar lambat tanpa membanjiri log.

Alur Kerja Triage Slow Query #

Kedua alat itu paling kuat dipakai bergantian dalam satu ritme tetap:

  1. Tandai titik nol. Catat waktu mulai pantauan, atau jalankan pg_stat_statements_reset() bila server memang dipakai untuk uji beban terisolasi.
  2. Biarkan beban berjalan. Statistik hanya seberguna durasi pengamatannya — idealnya satu siklus bisnis penuh (termasuk laporan mingguan atau bulanan yang jarang muncul).
  3. Susun tersangka. Urutkan pg_stat_statements oleh mean_exec_time untuk kasus per-permintaan, dan oleh total_exec_time untuk beban server; periksa calls sebelum menghakimi query yang tampak cepat.
  4. Bedah juara bertahan. Jalankan EXPLAIN (ANALYZE, BUFFERS) pada query teratas persis dengan bentuk dan parameternya — di sinilah pola dari chapter-chapter sebelumnya (index kolom join, keyset, dan sebagainya) menemukan sasarannya.
  5. Perbaiki, lalu ukur ulang. Bandingkan statistik sesudah dengan sebelumnya pada query yang sama; jika mean_exec_time tidak turun, hipotesisnya salah dan daftar tersangka harus dibaca ulang.

Log durasi melengkapi ritme ini untuk kasus yang lolos dari statistik: query yang hanya lambat pada momen tertentu (lock contention, beban puncak, cache dingin) meninggalkan jejak waktunya di baris log meskipun rata-ratanya tampak sehat.

Menemukan tersangka hanyalah setengah pekerjaan — setengah lainnya adalah mengukur perbaikan dengan cara yang tidak menipu. Dua query yang dibandingkan di cache yang berbeda, dijalankan sekali saja, atau diukur dari sisi yang salah akan menghasilkan kesimpulan yang keliru; chapter penutup section ini membangun disiplin pengukuran itu.

Referensi #

Berkas Sumber

Berkas pendukung halaman ini dapat diunduh dan dijalankan langsung sesuai penjelasan di atas.

buat-beban.sql

Unduh berkas
sql 
-- pg_stat_statements harus dimuat lewat shared_preload_libraries
-- oleh administrator server, lalu diaktifkan per database.
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

-- Empat pengaturan perilaku ekstensi, terbaca dari pg_settings.
SELECT name, setting
FROM pg_settings
WHERE name IN ('pg_stat_statements.max',
               'pg_stat_statements.save',
               'pg_stat_statements.track',
               'pg_stat_statements.track_utility')
ORDER BY name;

-- Mulai dari nol agar daftar hanya berisi beban latihan ini.
SELECT pg_stat_statements_reset() IS NOT NULL AS statistik_direset;

CREATE TABLE penjualan_slow (
    id integer GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
    produk text NOT NULL,
    jumlah integer NOT NULL
);

INSERT INTO penjualan_slow (produk, jumlah)
SELECT (ARRAY['Kopi','Teh','Gula'])[1 + g % 3], 1 + g % 10
FROM generate_series(1, 50000) AS g;

ANALYZE penjualan_slow;

-- Beban tetap: query "mahal" (scan penuh, tanpa index) tiga kali,
-- query "murah" (primary key) dua kali.
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;
SELECT count(*) FROM penjualan_slow WHERE id = 42;
SELECT count(*) FROM penjualan_slow WHERE id = 4242;

-- Daftar statement tercatat: literal dinormalkan menjadi $1, $2,
-- dan dbid dibatasi ke database ini agar beban sesi lain tidak ikut.
SELECT query, calls, rows
FROM pg_stat_statements
WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
ORDER BY calls DESC, query;

log-ambang.sql

Unduh berkas
sql 
-- Ambang log durasi: -1 berarti mati (default PostgreSQL).
SELECT name, setting, unit, context
FROM pg_settings
WHERE name = 'log_min_duration_statement';

-- Setel ambang hanya untuk sesi ini (superuser).
SET log_min_duration_statement = '100ms';
SHOW log_min_duration_statement;

-- Query di bawah 100 ms tidak menulis apa pun ke log;
-- query di atasnya tercatat dengan teks dan durasinya di log server.
SELECT count(*) FROM penjualan_slow WHERE produk = 'Kopi' AND jumlah > 5;

RESET log_min_duration_statement;
SHOW log_min_duration_statement;

urut-waktu.sql

Unduh berkas
sql 
-- Urutkan berdasarkan rata-rata waktu eksekusi per panggilan:
-- inilah cara menemukan query yang paling mahal per eksekusi.
-- Kolom waktu bervariasi antar mesin dan antar eksekusi;
-- kolom calls dan rows stabil untuk beban yang sama.
SELECT query, calls, rows,
       round(mean_exec_time::numeric, 3) AS rata_rata_ms,
       round(total_exec_time::numeric, 1) AS total_ms
FROM pg_stat_statements
WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
ORDER BY mean_exec_time DESC;