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

BERLAKU UNTUK: Azure Database for PostgreSQL - Server Fleksibel

Artikel ini memperlihatkan kepada Anda cara memecahkan masalah dan mengidentifikasi kueri yang berjalan lambat menggunakan server fleksibel Azure Database for PostgreSQL.

Dalam skenario pemanfaatan CPU yang tinggi, dalam artikel ini, Anda mempelajari cara:

• Identifikasi kueri yang berjalan lambat.

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

Skenario CPU tinggi - Mengidentifikasi kueri lambat

Prasyarat

Seseorang harus mengaktifkan panduan pemecahan masalah dan ekstensi auto_explain pada instans server fleksibel Azure Database for PostgreSQL. Untuk mengaktifkan panduan pemecahan masalah, ikuti langkah-langkah yang disebutkan di sini.

Untuk mengaktifkan ekstensi auto_explain, ikuti langkah-langkah di bawah ini:

1. Tambahkan ekstensi auto_explain ke pustaka pramuat bersama seperti yang ditunjukkan di bawah ini dari halaman parameter server di portal server fleksibel Azure Database for PostgreSQL.

   

Catatan

Melakukan perubahan ini akan memerlukan hidupkan ulang server.

2. Setelah ekstensi auto_explain ditambahkan ke pustaka pramuat bersama dan server telah dimulai ulang, ubah parameter server auto_explain yang disorot di bawah ini ke ON dari halaman parameter server di portal server fleksibel Azure Database for PostgreSQL dan biarkan yang tersisa dengan nilai default seperti yang ditunjukkan di bawah ini.

   

Catatan

Memperbarui auto_explain.log_min_duration parameter ke 0 akan mulai mencatat semua kueri yang dijalankan di server. Ini dapat berdampak pada performa database. Uji kelayakan yang tepat harus dibuat untuk mendapatkan nilai yang dianggap lambat di server. Contoh jika 30 detik dianggap ambang batas dan semua kueri yang dijalankan di bawah 30 detik dapat diterima untuk aplikasi, maka disarankan untuk memperbarui parameter ke 30000 milidetik. Ini kemudian akan mencatat kueri apa pun yang dijalankan lebih dari 30 detik di server.

Skenario - Mengidentifikasi kueri yang berjalan lambat

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

Kami memiliki skenario di mana pemanfaatan CPU telah meningkat hingga 90% dan ingin mengetahui akar penyebab lonjakan. Untuk men-debug skenario, ikuti langkah-langkah yang disebutkan di bawah ini.

1. Segera setelah Anda diberi tahu oleh skenario CPU, buka panduan pemecahan masalah yang tersedia di bawah tab Bantuan di halaman gambaran umum portal server fleksibel Azure Database for PostgreSQL.

   

2. Pilih tab Penggunaan CPU Tinggi dari halaman yang dibuka. Panduan pemecahan masalah Pemanfaatan CPU tinggi terbuka.

   

3. Pilih rentang waktu lonjakan CPU yang dilaporkan menggunakan daftar dropdown rentang waktu.

   

4. Pilih tab Kueri Penggunaan CPU Teratas.

   Tab berbagi 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. Ini kemungkinan besar penyebab lonjakan CPU.

   

5. Sambungkan ke database azure_sys dan jalankan kueri untuk mengambil teks kueri aktual menggunakan skrip berikut.

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. Dalam contoh yang dipertimbangkan, kueri yang ditemukan lambat adalah sebagai berikut:

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

7. Untuk memahami rencana penjelasan pasti yang dihasilkan, gunakan log server fleksibel Azure Database for PostgreSQL. Ekstensi penjelasan otomatis akan mencatat entri dalam log setiap kali eksekusi kueri selesai selama interval. Pilih bagian Log dari Monitoring tab dari halaman gambaran umum portal server fleksibel Azure Database for PostgreSQL.

   

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

   

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

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

Kolom pesan akan menyimpan rencana eksekusi seperti yang ditunjukkan di bawah ini:

2023-10-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, dan dikonfirmasi oleh duration nilai 150692,864 ms dari output rencana eksekusi yang diambil. Gunakan penjelasan menganalisis output untuk memecahkan masalah lebih lanjut dan menyetel kueri.

Catatan

Perhatikan bahwa kueri berjalan 22 kali selama interval, dan log yang ditunjukkan di atas adalah salah satu entri seperti yang diambil selama interval.

Skenario CPU tinggi - Mengidentifikasi prosedur yang berjalan lambat dan kueri lambat yang terkait dengan prosedur

Dalam skenario kedua, waktu eksekusi prosedur tersimpan ditemukan lambat, dan tujuannya adalah untuk mengidentifikasi dan menyetel kueri yang berjalan lambat yang merupakan bagian dari prosedur tersimpan.

Prasyarat

Seseorang harus mengaktifkan panduan pemecahan masalah dan ekstensi auto_explain pada instans server fleksibel Azure Database for PostgreSQL sebagai prasyarat. Untuk mengaktifkan panduan pemecahan masalah, ikuti langkah-langkah yang disebutkan di sini.

Untuk mengaktifkan ekstensi auto_explain, ikuti langkah-langkah di bawah ini:

1. Tambahkan ekstensi auto_explain ke pustaka pramuat bersama seperti yang ditunjukkan di bawah ini dari halaman parameter server di portal server fleksibel Azure Database for PostgreSQL.

   

Catatan

Melakukan perubahan ini akan memerlukan hidupkan ulang server.

2. Setelah ekstensi auto_explain ditambahkan ke pustaka pramuat bersama dan server telah dimulai ulang, ubah parameter server auto_explain yang disorot di bawah ini ke ON dari halaman parameter server di portal server fleksibel Azure Database for PostgreSQL dan biarkan yang tersisa dengan nilai default seperti yang ditunjukkan di bawah ini.

   

Catatan

• Memperbarui auto_explain.log_min_duration parameter ke 0 akan mulai mencatat semua kueri yang dijalankan di server. Ini dapat berdampak pada performa database. Uji kelayakan yang tepat harus dibuat untuk mendapatkan nilai yang dianggap lambat di server. Contoh jika 30 detik dianggap ambang batas dan semua kueri yang dijalankan di bawah 30 detik dapat diterima untuk aplikasi, maka disarankan untuk memperbarui parameter ke 30000 milidetik. Ini kemudian akan mencatat kueri apa pun yang dijalankan lebih dari 30 detik di server.
• Parameter auto_explain.log_nested_statements menyebabkan pernyataan berlapis (pernyataan yang dijalankan di dalam fungsi atau prosedur) dipertimbangkan untuk pengelogan. Saat nonaktif, hanya paket kueri tingkat atas yang dicatat. 

Skenario - 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 telah meningkat hingga 90% dan ingin mengetahui akar penyebab lonjakan. Untuk men-debug skenario, ikuti langkah-langkah yang disebutkan di bawah ini.

1. Segera setelah Anda diberi tahu oleh skenario CPU, buka panduan pemecahan masalah yang tersedia di bawah tab Bantuan di halaman gambaran umum portal server fleksibel Azure Database for PostgreSQL.

   

2. Pilih tab Penggunaan CPU Tinggi dari halaman yang dibuka. Panduan pemecahan masalah Pemanfaatan CPU tinggi terbuka.

   

3. Pilih rentang waktu lonjakan CPU yang dilaporkan menggunakan daftar dropdown rentang waktu.

   

4. Pilih tab Kueri Penggunaan CPU Teratas.

   Tab berbagi 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 ~6,3 menit, dan kueri berjalan 35 kali selama interval. Ini kemungkinan besar penyebab lonjakan CPU.

   

   Penting untuk dicatat dari rekam jepret di bawah ini bahwa jenis kueri seperti yang disorot di bawah ini adalah 'Utilitas''. Umumnya, utilitas dapat menjadi prosedur atau fungsi tersimpan yang berjalan selama interval.

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

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. Dalam contoh yang dipertimbangkan, kueri yang ditemukan lambat adalah prosedur tersimpan seperti yang disebutkan di bawah ini:

    call autoexplain_test ();

7. Untuk memahami penjelasan pasti apa yang dihasilkan untuk kueri yang merupakan bagian dari prosedur tersimpan, gunakan log server fleksibel Azure Database for PostgreSQL. Ekstensi penjelasan otomatis akan mencatat entri dalam log setiap kali eksekusi kueri selesai selama interval. Pilih bagian Log dari Monitoring tab dari halaman gambaran umum portal server fleksibel Azure Database for PostgreSQL.

   

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

   

9. Jalankan kueri di bawah ini untuk mengambil output analisis yang dijelaskan dari kueri yang diidentifikasi.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add a snippet of SQL text identified or add table name involved in the queries related to stored procedure>"
| 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.

2023-10-11 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

2023-10-11 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


2023-10-11 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

Harap dicatat untuk tujuan demonstrasi, jelaskan analisis output hanya beberapa kueri yang digunakan dalam prosedur yang dibagikan. Idenya adalah satu dapat mengumpulkan penjelasan menganalisis output semua kueri dari log, dan kemudian mengidentifikasi yang paling lambat dan mencoba menyetelnya.

Konten terkait

• Pemanfaatan CPU Tinggi
• Penyetelan Autovacuum