Saat bekerja dengan database OLTP (OnLine Transaction Processing), kinerja kueri sangat penting karena berdampak langsung pada pengalaman pengguna. Kueri yang lambat berarti aplikasi terasa tidak responsif dan lambat dan ini menghasilkan tingkat konversi yang buruk, pengguna yang tidak senang, dan semua rangkaian masalah.
OLTP adalah salah satu kasus penggunaan umum untuk PostgreSQL karena itu Anda ingin kueri Anda berjalan semulus mungkin. Di blog ini kami ingin berbicara tentang bagaimana Anda dapat mengidentifikasi masalah dengan kueri lambat di PostgreSQL.
Memahami Log Lambat
Secara umum, cara paling umum untuk mengidentifikasi masalah kinerja dengan PostgreSQL adalah dengan mengumpulkan kueri lambat. Ada beberapa cara yang bisa Anda lakukan. Pertama, Anda dapat mengaktifkannya di satu database:
pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;
ALTER DATABASESetelah ini semua koneksi baru ke database 'pgbench' akan masuk ke log PostgreSQL.
Dimungkinkan juga untuk mengaktifkan ini secara global dengan menambahkan:
log_min_duration_statement = 0ke konfigurasi PostgreSQL lalu muat ulang konfigurasi:
pgbench=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)Ini memungkinkan pencatatan semua kueri di semua database di PostgreSQL Anda. Jika Anda tidak melihat log apa pun, Anda mungkin ingin mengaktifkan logging_collector =on juga. Log akan menyertakan semua lalu lintas yang masuk ke tabel sistem PostgreSQL, membuatnya lebih berisik. Untuk tujuan kita, mari tetap berpegang pada pencatatan tingkat basis data.
Apa yang akan Anda lihat di log adalah entri seperti di bawah ini:
2020-02-21 09:45:39.022 UTC [13542] LOG: duration: 0.145 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 29817899;
2020-02-21 09:45:39.022 UTC [13544] LOG: duration: 0.107 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 11782597;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.065 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 16318529;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.082 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + 3063 WHERE tid = 3244;
2020-02-21 09:45:39.022 UTC [13526] LOG: duration: 16.450 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 1359 WHERE bid = 195;
2020-02-21 09:45:39.023 UTC [13523] LOG: duration: 15.824 ms statement: UPDATE pgbench_accounts SET abalance = abalance + -3726 WHERE aid = 5290358;
2020-02-21 09:45:39.023 UTC [13542] LOG: duration: 0.107 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -2716 WHERE tid = 1794;
2020-02-21 09:45:39.024 UTC [13544] LOG: duration: 0.112 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3814 WHERE tid = 278;
2020-02-21 09:45:39.024 UTC [13526] LOG: duration: 0.060 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (4876, 195, 39955137, 1359, CURRENT_TIMESTAMP);
2020-02-21 09:45:39.024 UTC [13529] LOG: duration: 0.081 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 3063 WHERE bid = 369;
2020-02-21 09:45:39.024 UTC [13523] LOG: duration: 0.063 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
2020-02-21 09:45:39.024 UTC [13542] LOG: duration: 0.100 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + -2716 WHERE bid = 210;
2020-02-21 09:45:39.026 UTC [13523] LOG: duration: 0.092 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3726 WHERE tid = 67;
2020-02-21 09:45:39.026 UTC [13529] LOG: duration: 0.090 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (3244, 369, 16318529, 3063, CURRENT_TIMESTAMP);Anda dapat melihat informasi tentang kueri dan durasinya. Tidak banyak lagi, tetapi ini jelas merupakan tempat yang baik untuk memulai. Hal utama yang perlu diingat adalah tidak semua kueri lambat merupakan masalah. Terkadang kueri harus mengakses sejumlah besar data dan diharapkan membutuhkan waktu lebih lama untuk mengakses dan menganalisis semua informasi yang diminta pengguna. Pertanyaan lain adalah apa artinya "lambat"? Ini sebagian besar tergantung pada aplikasi. Jika kita berbicara tentang aplikasi interaktif, kemungkinan besar sesuatu yang lebih lambat dari satu detik terlihat. Idealnya semuanya dieksekusi dalam batas 100 - 200 milidetik.
Mengembangkan Rencana Eksekusi Kueri
Setelah kami menentukan bahwa kueri yang diberikan memang sesuatu yang ingin kami tingkatkan, kami harus melihat rencana eksekusi kueri. Pertama-tama, mungkin saja tidak ada yang bisa kami lakukan untuk itu dan kami harus menerima bahwa kueri yang diberikan lambat. Kedua, rencana eksekusi kueri dapat berubah. Pengoptimal selalu mencoba untuk memilih rencana eksekusi yang paling optimal tetapi mereka membuat keputusan hanya berdasarkan sampel data, oleh karena itu rencana eksekusi kueri dapat berubah seiring waktu. Di PostgreSQL Anda dapat memeriksa rencana eksekusi dengan dua cara. Pertama, perkiraan rencana eksekusi, menggunakan EXPLAIN:
pgbench=# EXPLAIN SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4)
Index Cond: (aid = 5290358)Seperti yang Anda lihat, kami diharapkan mengakses data menggunakan pencarian kunci utama. Jika kita ingin memeriksa ulang bagaimana tepatnya query akan dieksekusi, kita dapat menggunakan EXPLAIN ANALYZE:
pgbench=# EXPLAIN ANALYZE SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4) (actual time=0.046..0.065 rows=1 loops=1)
Index Cond: (aid = 5290358)
Planning time: 0.053 ms
Execution time: 0.084 ms
(4 rows)Sekarang, PostgreSQL telah mengeksekusi kueri ini dan dapat memberi tahu kami bukan hanya perkiraan tetapi juga angka pasti terkait rencana eksekusi, jumlah baris yang diakses, dan seterusnya. Harap diingat bahwa mencatat semua kueri dapat menjadi overhead yang serius pada sistem Anda. Anda juga harus mengawasi log dan memastikannya diputar dengan benar.
Pg_stat_statements
Pg_stat_statements adalah ekstensi yang mengumpulkan statistik eksekusi untuk berbagai jenis kueri.
pgbench=# select query, calls, total_time, min_time, max_time, mean_time, stddev_time, rows from public.pg_stat_statements order by calls desc LIMIT 10;
query | calls | total_time | min_time | max_time | mean_time | stddev_time | rows
------------------------------------------------------------------------------------------------------+-------+------------------+----------+------------+---------------------+---------------------+-------
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2 | 30437 | 6636.83641200002 | 0.006533 | 83.832148 | 0.218051595492329 | 1.84977058799388 | 30437
BEGIN | 30437 | 231.095600000001 | 0.000205 | 20.260355 | 0.00759258796859083 | 0.26671126085716 | 0
END | 30437 | 229.483213999999 | 0.000211 | 16.980678 | 0.0075396134310215 | 0.223837608828596 | 0
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2 | 30437 | 290021.784321001 | 0.019568 | 805.171845 | 9.52859297305914 | 13.6632712046825 | 30437
UPDATE pgbench_tellers SET tbalance = tbalance + $1 WHERE tid = $2 | 30437 | 6667.27243200002 | 0.00732 | 212.479269 | 0.219051563294674 | 2.13585110968012 | 30437
SELECT abalance FROM pgbench_accounts WHERE aid = $1 | 30437 | 3702.19730600006 | 0.00627 | 38.860846 | 0.121634763807208 | 1.07735927551245 | 30437
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, $4, CURRENT_TIMESTAMP) | 30437 | 2349.22475800002 | 0.003218 | 61.372127 | 0.0771831901304325 | 0.971590327400244 | 30437
SELECT $1 | 6847 | 60.785467 | 0.002321 | 7.882384 | 0.00887767883744706 | 0.105198744982906 | 6847
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 5000 | 18.592042 | 0.001572 | 0.741427 | 0.0037184084 | 0.0137660355678027 | 5000
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 3000 | 7.323788 | 0.001598 | 0.40152 | 0.00244126266666667 | 0.00834442591085048 | 3000
(10 rows)Seperti yang Anda lihat pada data di atas, kami memiliki daftar kueri dan informasi berbeda tentang waktu eksekusinya - ini hanya sebagian dari data yang dapat Anda lihat di pg_stat_statements tetapi cukup untuk kami untuk memahami bahwa pencarian kunci utama kami terkadang membutuhkan waktu hampir 39 detik untuk diselesaikan - ini tidak terlihat bagus dan ini pasti sesuatu yang ingin kami selidiki.
Jika Anda tidak mengaktifkan pg_stat_statements, Anda dapat melakukannya dengan cara standar. Baik melalui file konfigurasi dan
shared_preload_libraries = 'pg_stat_statements'Atau Anda dapat mengaktifkannya melalui baris perintah PostgreSQL:
pgbench=# CREATE EXTENSION pg_stat_statements;
CREATE EXTENSIONMenggunakan ClusterControl untuk Menghilangkan Kueri Lambat
Jika Anda menggunakan ClusterControl untuk mengelola database PostgreSQL, Anda dapat menggunakannya untuk mengumpulkan data tentang kueri lambat.
Seperti yang Anda lihat, ia mengumpulkan data tentang eksekusi kueri - baris yang dikirim dan diperiksa, statistik waktu eksekusi dan sebagainya. Dengannya Anda dapat dengan mudah menentukan kueri yang paling mahal, dan melihat seperti apa waktu eksekusi rata-rata dan maksimum. Secara default ClusterControl mengumpulkan kueri yang membutuhkan waktu lebih dari 0,5 detik untuk diselesaikan, Anda dapat mengubahnya di pengaturan:
Kesimpulan
Blog singkat ini sama sekali tidak mencakup semua aspek dan alat yang membantu dalam mengidentifikasi dan memecahkan masalah kinerja kueri di PostgreSQL. Kami berharap ini adalah awal yang baik dan akan membantu Anda memahami apa yang dapat Anda lakukan untuk menemukan akar penyebab kueri yang lambat.
