Memecahkan masalah dan mengidentifikasi kueri yang berjalan lambat di Azure Database for PostgreSQL

Artikel ini menjelaskan cara mengidentifikasi dan mendiagnosis akar penyebab kueri yang berjalan lambat.

Dalam artikel ini, Anda dapat mempelajari cara:

• Cara mengidentifikasi kueri yang berjalan lambat.
• Cara mengidentifikasi prosedur yang berjalan lambat bersama dengannya. Identifikasi kueri lambat di antara daftar kueri yang termasuk dalam prosedur tersimpan yang berjalan lambat yang sama.

Prasyarat

1. Aktifkan panduan pemecahan masalah dengan mengikuti langkah-langkah yang dijelaskan dalam menggunakan panduan pemecahan masalah.

2. Konfigurasikan auto_explain ekstensi dengan mengizinkan dan memuat ekstensi.

3. Setelah ekstensi dikonfigurasiauto_explain, ubah parameter server berikut, yang mengontrol perilaku ekstensi:

   • auto_explain.log_analyze ke ON.
   • auto_explain.log_buffers ke ON.
   • auto_explain.log_min_duration sesuai dengan apa yang wajar dalam skenario Anda.
   • auto_explain.log_timing ke ON.
   • auto_explain.log_verbose ke ON.

   

Catatan

Jika Anda mengatur auto_explain.log_min_duration ke 0, ekstensi mulai mencatat semua kueri yang dijalankan di server. Ini mungkin memengaruhi performa database. Uji tuntas yang tepat harus dilakukan untuk menetapkan nilai, yang dinilai lambat pada server. Misalnya, jika semua kueri selesai dalam waktu kurang dari 30 detik, dan itu dapat diterima untuk aplikasi Anda, maka disarankan untuk memperbarui parameter menjadi 30.000 milidetik. Ini kemudian akan mencatat kueri apa pun, yang membutuhkan waktu lebih dari 30 detik untuk diselesaikan.

Mengidentifikasi kueri lambat

Dengan panduan pemecahan masalah dan auto_explain ekstensi di tempat, kami menjelaskan skenario dengan bantuan contoh.

Kami memiliki skenario di mana pemanfaatan CPU melonjakan hingga 90% dan ingin menentukan penyebab lonjakan. Untuk men-debug skenario, ikuti langkah-langkah berikut:

1. Segera setelah Anda mendapatkan pemberitahuan tentang skenario CPU, pada menu sumber daya untuk instans Azure Database for PostgreSQL server fleksibel yang terpengaruh, di bawah bagian Pemantauan, pilih Panduan pemecahan masalah.

   

2. Pilih tab CPU . Panduan pemecahan masalah Pengoptimalan pemanfaatan CPU tinggi terbuka.

   

3. Dari menu dropdown Periode analisis (waktu lokal) , pilih rentang waktu tempat Anda ingin memfokuskan analisis.

   

4. Pilih tab Kueri . Ini menunjukkan detail semua kueri yang berjalan dalam interval di mana pemanfaatan CPU 90% terlihat. Dari rekam jepret, kueri terlihat seperti kueri dengan waktu eksekusi rata-rata terlambat selama interval waktu adalah ~2,6 menit, dan kueri berjalan 22 kali selama interval. Kueri tersebut kemungkinan besar menjadi penyebab lonjakan CPU.

   

5. Untuk mengambil teks kueri aktual, sambungkan ke azure_sys database dan jalankan kueri berikut.

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;

1. Dalam contoh yang dipertimbangkan, kueri yang ditemukan lambat adalah:

SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id, c_id
ORDER BY c_w_id;

1. Untuk memahami rencana penjelasan pasti yang dihasilkan, gunakan log Azure Database for PostgreSQL. Setiap kali kueri menyelesaikan eksekusi selama jendela waktu tersebut auto_explain , ekstensi harus menulis entri dalam log. Di menu sumber daya, di bawah bagian Pemantauan , pilih Log.

   

2. Pilih rentang waktu di mana Pemanfaatan CPU 90% ditemukan.

   

3. Jalankan kueri berikut untuk mengambil output EXPLAIN ANALYZE untuk kueri yang diidentifikasi.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<snippet of SQL text identified or name of any of the tables referenced in the query>"
| project TimeGenerated, Message

Kolom pesan menyimpan rencana eksekusi seperti yang ditunjukkan dalam output ini:

2024-11-10 19:56:46 UTC-6525a8e7.2e3d-LOG: duration: 150692.864 ms plan:

Query Text: SELECT c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;
GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=70930.833..129231.950 rows=10000000 loops=1)
Output: c_id, sum(c_balance), c_w_id
Group Key: customer.c_w_id, customer.c_id
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=70930.821..81898.430 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance
Sort Key: customer.c_w_id, customer.c_id
Sort Method: external merge Disk: 225104kB
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.021..22997.697 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance

Kueri berjalan selama ~2,5 menit, seperti yang ditunjukkan dalam panduan pemecahan masalah. Nilai duration 150692,864 ms dari output rencana eksekusi yang diambil mengonfirmasinya. Gunakan output EXPLAIN ANALYZE untuk memecahkan masalah lebih lanjut dan menyetel kueri.

Catatan

Amati bahwa kueri berjalan 22 kali selama interval, dan log yang diperlihatkan berisi entri seperti itu yang diambil selama interval.

Mengidentifikasi kueri yang berjalan lambat dalam prosedur tersimpan

Dengan panduan pemecahan masalah dan ekstensi auto_explain di tempat, kami menjelaskan skenario dengan bantuan contoh.

Kami memiliki skenario di mana pemanfaatan CPU melonjakan hingga 90% dan ingin menentukan penyebab lonjakan. Untuk men-debug skenario, ikuti langkah-langkah berikut:

1. Segera setelah Anda mendapatkan pemberitahuan tentang skenario CPU, pada menu sumber daya untuk instans Azure Database for PostgreSQL server fleksibel yang terpengaruh, di bawah bagian Pemantauan, pilih Panduan pemecahan masalah.

   

2. Pilih tab CPU . Panduan pemecahan masalah Pengoptimalan pemanfaatan CPU tinggi terbuka.

   

3. Dari menu dropdown Periode analisis (waktu lokal) , pilih rentang waktu tempat Anda ingin memfokuskan analisis.

   

4. Pilih tab Kueri . Ini menunjukkan detail semua kueri yang berjalan dalam interval di mana pemanfaatan CPU 90% terlihat. Dari rekam jepret, kueri terlihat seperti kueri dengan waktu eksekusi rata-rata terlambat selama interval waktu adalah ~2,6 menit, dan kueri berjalan 22 kali selama interval. Kueri tersebut kemungkinan besar menjadi penyebab lonjakan CPU.

   

5. Sambungkan ke database azure_sys dan jalankan kueri untuk mengambil teks kueri aktual menggunakan skrip di bawah ini.

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;

1. Dalam contoh yang dipertimbangkan, kueri yang ditemukan lambat adalah prosedur tersimpan:

    call autoexplain_test ();

1. Untuk memahami rencana penjelasan pasti yang dihasilkan, gunakan log Azure Database for PostgreSQL. Setiap kali kueri menyelesaikan eksekusi selama jendela waktu tersebut auto_explain , ekstensi harus menulis entri dalam log. Di menu sumber daya, di bawah bagian Pemantauan , pilih Log. Kemudian, dalam Rentang waktu:, pilih jendela waktu tempat Anda ingin memfokuskan analisis.

1. Jalankan kueri berikut untuk mengambil penjelasan menganalisis output kueri yang diidentifikasi.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<snippet of SQL text identified or name of any of the tables referenced in the query>"
| project TimeGenerated, Message

Prosedur ini memiliki beberapa kueri, yang disorot di bawah ini. Penjelasan menganalisis output dari setiap kueri yang digunakan dalam prosedur tersimpan masuk untuk menganalisis lebih lanjut dan memecahkan masalah. Waktu eksekusi kueri yang dicatat dapat digunakan untuk mengidentifikasi kueri terlambat yang merupakan bagian dari prosedur tersimpan.

2024-11-10 17:52:45 UTC-6526d7f0.7f67-LOG: duration: 38459.176 ms plan:

Query Text: insert into customer_balance SELECT c_id, SUM(c_balance) AS total_balance FROM customer GROUP BY c_w_id,c_id order by c_w_id
Insert on public.customer_balance (cost=1906820.83..2231820.83 rows=0 width=0) (actual time=38459.173..38459.174 rows=0 loops=1)Buffers: shared hit=10108203 read=454055 dirtied=54058, temp read=77521 written=77701 WAL: records=10000000 fpi=1 bytes=640002197
    -> Subquery Scan on "*SELECT*" (cost=1906820.83..2231820.83 rows=10000000 width=36) (actual time=20415.738..29514.742 rows=10000000 loops=1)
        Output: "*SELECT*".c_id, "*SELECT*".total_balance Buffers: shared hit=1 read=400000, temp read=77521 written=77701
            -> GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=20415.737..28574.266 rows=10000000 loops=1)
                Output: customer.c_id, sum(customer.c_balance), customer.c_w_id Group Key: customer.c_w_id, customer.c_id Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                -> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=20415.723..22023.515 rows=10000000 loops=1)
                    Output: customer.c_id, customer.c_w_id, customer.c_balance Sort Key: customer.c_w_id, customer.c_id Sort Method: external merge Disk: 225104kB Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                     -> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.310..15061.471 rows=10000000 loops=1) Output: customer.c_id, customer.c_w_id, customer.c_balance Buffers: shared hit=1 read=400000

2024-11-10 17:52:07 UTC-6526d7f0.7f67-LOG: duration: 61939.529 ms plan:
Query Text: delete from customer_balance
Delete on public.customer_balance (cost=0.00..799173.51 rows=0 width=0) (actual time=61939.525..61939.526 rows=0 loops=1) Buffers: shared hit=50027707 read=620942 dirtied=295462 written=71785 WAL: records=50026565 fpi=34 bytes=2711252160
    -> Seq Scan on public.customer_balance (cost=0.00..799173.51 rows=15052451 width=6) (actual time=3185.519..35234.061 rows=50000000 loops=1)
        Output: ctid Buffers: shared hit=27707 read=620942 dirtied=26565 written=71785 WAL: records=26565 fpi=34 bytes=11252160

2024-11-10 17:51:05 UTC-6526d7f0.7f67-LOG: duration: 10387.322 ms plan:
Query Text: select max(c_id) from customer
Finalize Aggregate (cost=180185.84..180185.85 rows=1 width=4) (actual time=10387.220..10387.319 rows=1 loops=1) Output: max(c_id) Buffers: shared hit=37148 read=1204 written=69
    -> Gather (cost=180185.63..180185.84 rows=2 width=4) (actual time=10387.214..10387.314 rows=1 loops=1)
        Output: (PARTIAL max(c_id)) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=37148 read=1204 written=69
        -> Partial Aggregate (cost=179185.63..179185.64 rows=1 width=4) (actual time=10387.012..10387.013 rows=1 loops=1) Output: PARTIAL max(c_id) Buffers: shared hit=37148 read=1204 written=69
            -> Parallel Index Only Scan using customer_i1 on public.customer (cost=0.43..168768.96 rows=4166667 width=4) (actual time=0.446..7676.356 rows=10000000 loops=1)
               Output: c_w_id, c_d_id, c_id Heap Fetches: 24 Buffers: shared hit=37148 read=1204 written=69

Catatan

Untuk tujuan demonstrasi, output EXPLAIN ANALYZE hanya dari beberapa kueri yang digunakan dalam prosedur ditampilkan. Idenya adalah seseorang dapat mengumpulkan output EXPLAIN ANALYZE dari semua kueri dari log, dan mengidentifikasi yang paling lambat dan mencoba menyetelnya.

Konten terkait

• Memecahkan masalah pemanfaatan CPU tinggi di Azure Database for PostgreSQL.
• Memecahkan masalah pemanfaatan IOPS tinggi di Azure Database for PostgreSQL.
• Memecahkan masalah pemanfaatan memori tinggi di Azure Database for PostgreSQL.
• Parameter server di Azure Database for PostgreSQL.
• Penyetelan autovacuum di Azure Database for PostgreSQL.