Dalam setiap penerapan, selalu ada beberapa kueri yang berjalan terlalu lambat.
Baca terus untuk mengetahui cara menemukan kueri yang membutuhkan waktu terlalu lama untuk dieksekusi, dan cara mengetahui mengapa kueri itu lambat.
Hanya Gunakan pg_stat_statements?
pg_stat_statements adalah ekstensi populer yang disertakan dalam distribusi inti PostgreSQL dan tersedia secara default di hampir semua penyedia DBaaS. Ini sangat berharga, dan kurang lebih satu-satunya cara untuk mendapatkan statistik kueri tanpa memasang ekstensi khusus.
Namun, ia memiliki beberapa keterbatasan dalam hal menemukan kueri yang lambat.
Statistik Kumulatif
Ekstensi pg_stat_statements memberikan kumulatif statistik tentang setiap kueri yang pernah dijalankan oleh server. Untuk setiap kueri, ini menunjukkan, di antara metrik lainnya, jumlah total waktu yang telah dieksekusi, dan total waktu yang dibutuhkan untuk semua eksekusi.
Untuk "menangkap" kueri lambat saat terjadi, Anda perlu mengambil seluruh konten pg_stat_statements secara berkala lihat, simpan dalam database deret waktu, dan bandingkan jumlah eksekusi. Misalnya, jika memiliki konten pg_stat_statements pada pukul 10.00 dan 10.10, Anda dapat memilih kueri yang memiliki jumlah eksekusi lebih tinggi pada pukul 10.10 daripada pukul 10.00. Untuk kueri ini, Anda dapat menghitung waktu eksekusi rata-rata selama interval ini, menggunakan:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Jika waktu eksekusi rata-rata ini melebihi ambang batas atas, Anda dapat memicu peringatan untuk mengambil tindakan.
Ini bekerja dengan cukup baik dalam praktiknya, tetapi Anda memerlukan infrastruktur pemantauan yang baik, atau layanan khusus seperti pgDash.
Parameter Kueri
pg_stat_statements tidak menangkap nilai parameter bind yang diteruskan ke kueri.
Salah satu hal yang diperkirakan oleh perencana kueri Postgres untuk memilih rencana eksekusi adalah jumlah baris yang kemungkinan akan difilter oleh suatu kondisi. Misalnya jika sebagian besar baris tabel memiliki nilai kolom terindeks negara sebagai “AS”, perencana mungkin memutuskan untuk melakukan pemindaian berurutan dari seluruh tabel untuk di mana klausa country = "US" , dan mungkin memutuskan untuk menggunakan pemindaian indeks untuk country = "UK" sejak pertama di mana klausa diharapkan cocok dengan sebagian besar baris dalam tabel.
Mengetahui nilai sebenarnya dari parameter yang eksekusi kuerinya lambat dapat membantu mendiagnosis masalah kueri lambat dengan lebih cepat.
Logging Kueri Lambat
Alternatif yang lebih sederhana adalah mencatat kueri lambat. Tidak seperti DBMS tertentu lainnya yang membuat ini mudah, PostgreSQL memberi kita banyak pengaturan konfigurasi yang tampak serupa:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Ini dijelaskan secara rinci dalam dokumentasi Postgres. Inilah titik awal yang masuk akal:
# next line says only log queries that take longer 5 seconds
log_min_duration_statement = 5s
log_parameter_max_length = 1024
log_parameter_max_length_on_error = 1024
Yang menghasilkan log seperti ini:
2022-04-14 06:17:11.462 UTC [369399] LOG: duration: 5.060 ms statement: select i.*, t."Name" as track, ar."Name" as artist
from "InvoiceLine" as i
join "Track" as t on i."TrackId" = t."TrackId"
join "Album" as al on al."AlbumId" = t."AlbumId"
join "Artist" as ar on ar."ArtistId" = al."ArtistId";
Jika ada terlalu banyak log, Anda dapat meminta Postgres untuk mencatat hanya (misalnya) 50% kueri yang berjalan lebih dari 5 detik:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Anda tentu saja harus membaca dokumen tentang apa arti dan implikasi parameter ini sebelum menambahkannya ke dalam konfigurasi Postgres Anda. Berhati-hatilah karena setelannya unik dan tidak intuitif.
Rencana Eksekusi Kueri Lambat
Biasanya tidak cukup untuk mengetahui bahwa kueri lambat terjadi, Anda juga harus mencari tahu mengapa itu lambat. Untuk ini, Anda biasanya akan terlebih dahulu memeriksa rencana eksekusi kueri.
auto_explain adalah ekstensi PostgreSQL inti lainnya (sekali lagi, tersedia di sebagian besar DBaaS juga) yang dapat mencatat rencana eksekusi kueri yang baru saja selesai dieksekusi. Ini didokumentasikan di sini.
Untuk mengaktifkan auto_explain, Anda biasanya menambahkannya ke shared_preload_libraries dan mulai ulang Postgres. Berikut adalah contoh konfigurasi starter:
# logs execution plans of queries that take 10s or more to run
auto_explain.log_min_duration = 10s
auto_explain.log_verbose = on
auto_explain.log_settings = on
auto_explain.log_format = json
auto_explain.log_nested_statements = on
# enabling these provide more information, but have a performance cost
#auto_explain.log_analyze = on
#auto_explain.log_buffers = on
#auto_explain.log_wal = on
#auto_explain.log_timing = on
#auto_explain.log_triggers = on
Ini akan menyebabkan rencana dicatat sebagai format JSON, yang kemudian dapat divisualisasikan dalam alat seperti ini.
Kueri yang Masih Menjalankan
Semua teknik yang tercantum di atas memiliki satu kesamaan:mereka menghasilkan keluaran yang dapat ditindaklanjuti hanya setelah sebuah query telah selesai dieksekusi. Mereka tidak dapat digunakan untuk menangani kueri yang sangat lambat kali ini, sehingga mereka belum menyelesaikan eksekusi.
Setiap koneksi ke server PostgreSQL ditangani oleh backend , khususnya backend klien . Saat backend seperti itu menjalankan kueri, statusnya aktif . Itu mungkin juga telah memulai transaksi tetapi kemudian menganggur, disebut menganggur dalam transaksi negara.
pg_stat_activity tampilan sistem yang didokumentasikan di sini menyediakan daftar semua backend Postgres yang berjalan. Anda dapat meminta tampilan ini untuk mendapatkan kueri yang masih berjalan:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Omong-omong, tanpa menggunakan ekstensi pihak ketiga, tidak ada cara untuk mengetahui rencana eksekusi kueri yang saat ini dijalankan oleh backend.
Kunci
Jika rencana eksekusi kueri lambat tidak menunjukkan masalah yang jelas, backend yang mengeksekusi kueri mungkin tertunda oleh kunci yang dipertentangkan.
Kunci diperoleh baik secara eksplisit maupun implisit selama eksekusi kueri karena berbagai alasan. Ada seluruh bab dalam dokumentasi Postgres yang dikhususkan untuk ini.
Kunci Logging
Biasanya, batas atas berapa lama menunggu diatur menggunakan opsi lock_timeout , biasanya di sisi klien. Jika kueri telah menunggu selama ini untuk mendapatkan kunci, Postgres akan membatalkan eksekusi kueri ini dan mencatat kesalahan:
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 ERROR: canceling statement due to lock timeout
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 STATEMENT: cluster t;
Katakanlah Anda ingin menyetel batas waktu penguncian 1 menit, tetapi log kueri yang menunggu penguncian lebih dari, katakanlah 30 detik. Anda dapat melakukannya menggunakan:
log_lock_waits = on
deadlock_timeout = 30s
Ini akan membuat log seperti ini:
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 LOG: process 70 still waiting for ShareLock on transaction 493 after 30009.004 ms
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 68. Wait queue: 70.
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 STATEMENT: select * from t for update;
Penggunaan deadlock_timeout bukan salah ketik:ini adalah nilai yang digunakan mekanisme logging tunggu kunci. Idealnya, seharusnya ada sesuatu seperti log_min_duration_lock_wait , tapi sayangnya, bukan itu masalahnya.
Jika terjadi kebuntuan yang sebenarnya, Postgres akan membatalkan transaksi yang menemui jalan buntu setelah deadlock_timeout durasi, dan akan mencatat pernyataan yang menyinggung. Tidak diperlukan konfigurasi eksplisit.
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 LOG: process 68 detected deadlock while waiting for ShareLock on transaction 496 after 30007.633 ms
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 70. Wait queue: .
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 ERROR: deadlock detected
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process 68 waits for ShareLock on transaction 496; blocked by process 70.
Process 70 waits for ShareLock on transaction 495; blocked by process 68.
Process 68: select * from t where a=4 for update;
Process 70: select * from t where a=0 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 HINT: See server log for query details.
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
Menemukan Kunci Saat Ini
Seluruh daftar kunci yang diberikan saat ini tersedia dari tampilan sistem pg_locks. Namun, biasanya lebih mudah menggunakan fungsi pg_blocking_pids , bersama dengan pg_stat_activity , seperti ini:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
yang dapat menampilkan output seperti ini:
state | pid | pg_blocking_pids | query
---------------------+--------+------------------+-------------------------------------------------
active | 378170 | {} | SELECT state, pid, pg_blocking_pids(pid), query+
| | | FROM pg_stat_activity +
| | | WHERE backend_type='client backend';
active | 369399 | {378068} | cluster "Track";
idle in transaction | 378068 | {} | select * from "Track" for update;
(3 rows)
yang menunjukkan bahwa ada satu backend yang diblokir (yang mengeksekusi pernyataan CLUSTER), dan bahwa itu diblokir oleh PID 378068 (yang telah mengeksekusi SELECT..FOR UPDATE tetapi kemudian berhenti dalam transaksi).
