Aracılığıyla paylaş

PostgreSQL için Azure Veritabanı'nda yavaş çalışan sorguların sorunlarını giderme ve tanımlama

Bu makalede yavaş çalışan sorguların kök nedenini belirleme ve tanılama işlemi açıklanır.

Bu makalede şunları öğrenebilirsiniz:

  • Yavaş çalışan sorguları tanımlama.
  • Bununla birlikte yavaş çalışan bir yordamı tanımlama. Aynı yavaş çalışan saklı yordama ait sorguların listesi arasında yavaş bir sorgu tanımlayın.

Önkoşullar

  1. Sorun giderme kılavuzlarını kullanma başlığında açıklanan adımları izleyerek sorun giderme kılavuzlarını etkinleştirin.

  2. Uzantıyı auto_explain izin verilenler listesine ekleyerek ve yükleyerek yapılandırın.

  3. auto_explain Uzantı yapılandırıldıktan sonra, uzantının davranışını denetleyen aşağıdaki sunucu parametrelerini değiştirin:

    • auto_explain.log_analyze için ON.
    • auto_explain.log_buffers için ON.
    • auto_explain.log_min_duration senaryonuzda makul olan şeylere göre.
    • auto_explain.log_timing için ON.
    • auto_explain.log_verbose için ON.

    Yapılandırılması gereken auto_explain sunucu parametrelerini gösteren ekran görüntüsü.

Not

0 olarak ayarlarsanız auto_explain.log_min_duration , uzantı sunucuda yürütülen tüm sorguları günlüğe kaydetmeye başlar. Bu, veritabanının performansını etkileyebilir. Sunucuda yavaş olarak kabul edilen bir değeri belirlemek için kapsamlı bir inceleme yapılmalıdır. Örneğin, tüm sorgular 30 saniyeden kısa sürede tamamlanırsa ve bu uygulamanız için kabul edilebilirse, parametreyi 30.000 milisaniyeye güncelleştirmeniz önerilir. Daha sonra bu işlem, tamamlanması 30 saniyeden uzun süren tüm sorguları günlüğe kaydeder.

Yavaş sorguyu tanımlama

Sorun giderme kılavuzları ve auto_explain uzantı ile senaryoyu bir örnek yardımıyla açıklıyoruz.

CPU kullanımının %90'a yükseldiği ve ani artışın nedenini belirlemek istediğimiz bir senaryomuz var. Senaryoda hata ayıklamak için şu adımları izleyin:

  1. Bir CPU senaryosu tarafından uyarı alır almaz, PostgreSQL için Azure Veritabanı esnek sunucusunun etkilenen örneğinin kaynak menüsünde İzleme bölümünde Sorun giderme kılavuzları'nı seçin.

    Sorun giderme kılavuzları menü seçeneğinin ekran görüntüsü.

  2. CPU sekmesini seçin. Yüksek CPU kullanımını iyileştirme sorun giderme kılavuzu açılır.

    Sorun giderme kılavuzları menüsü - sekmelerin ekran görüntüsü.

  3. Çözümleme dönemi (yerel saat) açılan listesinden, çözümlemeye odaklanmak istediğiniz zaman aralığını seçin.

    Sorun giderme kılavuzları menüsü - CPU sekmesinin ekran görüntüsü.

  4. Sorgular sekmesini seçin. %90 CPU kullanımının görüldüğü aralıkta çalıştırılan tüm sorguların ayrıntılarını gösterir. Anlık görüntüden, zaman aralığı boyunca en yavaş ortalama yürütme süresine sahip sorgu yaklaşık 2,6 dakika ve sorgu aralık boyunca 22 kez çalıştırıldı gibi görünüyor. Bu sorgu büyük olasılıkla CPU ani artışlarının nedenidir.

    Sorun giderme kılavuzları menüsü - En çok CPU kullanan sorgular sekmesinin ekran görüntüsü.

  5. Gerçek sorgu metnini almak için veritabanına bağlanın azure_sys ve aşağıdaki sorguyu yürütür.

    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. Dikkate alınan örnekte yavaş bulunan sorgu şöyleydi:
SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id, c_id
ORDER BY c_w_id;

  1. Tam olarak hangi açıklama planının oluşturulduğunu anlamak için PostgreSQL için Azure Veritabanı günlüklerini kullanın. Bu zaman penceresi sırasında sorgunun yürütülmesi her tamamlandığında uzantının auto_explain günlüklere bir girdi yazması gerekir. Kaynak menüsünde, İzleme bölümünün altında Günlükler'i seçin.

    Sorun giderme kılavuzları menüsü - Günlükler'in ekran görüntüsü.

  2. %90 CPU Kullanımının bulunduğu zaman aralığını seçin.

    Sorun giderme kılavuzlarında zaman penceresini seçmeyi gösteren ekran görüntüsü.

  3. Tanımlanan sorgu için EXPLAIN ANALYZE çıktısını almak için aşağıdaki sorguyu yürütür.

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

İleti sütunu yürütme planını şu çıktıda gösterildiği gibi depolar:

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

Sorun giderme kılavuzunda gösterildiği gibi sorgu yaklaşık 2,5 dakika çalıştı. Getirilen duration yürütme planı çıkışından alınan 150692.864 ms değeri bunu onaylar. Daha fazla sorun gidermek ve sorguyu ayarlamak için EXPLAIN ANALYZE çıktısını kullanın.

Not

Sorgunun aralık boyunca 22 kez çalıştırıldığını ve gösterilen günlüklerin aralık boyunca yakalanan bu tür girişleri içerdiğini gözlemleyin.

Saklı yordamda yavaş çalışan sorguyu tanımlama

Sorun giderme kılavuzları ve auto_explain uzantısıyla senaryoyu bir örnek yardımıyla açıklayacağız.

CPU kullanımının %90'a yükseldiği ve ani artışın nedenini belirlemek istediğimiz bir senaryomuz var. Senaryoda hata ayıklamak için şu adımları izleyin:

  1. Bir CPU senaryosu tarafından uyarı alır almaz, PostgreSQL için Azure Veritabanı esnek sunucusunun etkilenen örneğinin kaynak menüsünde İzleme bölümünde Sorun giderme kılavuzları'nı seçin.

    Sorun giderme kılavuzları menüsünün ekran görüntüsü.

  2. CPU sekmesini seçin. Yüksek CPU kullanımını iyileştirme sorun giderme kılavuzu açılır.

    Sorun giderme kılavuzları sekmelerinin ekran görüntüsü.

  3. Çözümleme dönemi (yerel saat) açılan listesinden, çözümlemeye odaklanmak istediğiniz zaman aralığını seçin.

    Sorun giderme kılavuzları - CPU sekmesinin ekran görüntüsü.

  4. Sorgular sekmesini seçin. %90 CPU kullanımının görüldüğü aralıkta çalıştırılan tüm sorguların ayrıntılarını gösterir. Anlık görüntüden, zaman aralığı boyunca en yavaş ortalama yürütme süresine sahip sorgu yaklaşık 2,6 dakika ve sorgu aralık boyunca 22 kez çalıştırıldı gibi görünüyor. Bu sorgu büyük olasılıkla CPU ani artışlarının nedenidir.

    Sorun giderme kılavuzları - CPU sekmesi - sorgular ekran görüntüsü.

  5. Aşağıdaki betiği kullanarak azure_sys veritabanına bağlanın ve gerçek sorgu metnini almak için sorguyu yürütür.

    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. Dikkate alınan örnekte, yavaş bulunan sorgu bir saklı yordamdı:
    call autoexplain_test ();
  1. Tam olarak hangi açıklama planının oluşturulduğunu anlamak için PostgreSQL için Azure Veritabanı günlüklerini kullanın. Bu zaman penceresi sırasında sorgunun yürütülmesi her tamamlandığında uzantının auto_explain günlüklere bir girdi yazması gerekir. Kaynak menüsünde, İzleme bölümünün altında Günlükler'i seçin. Ardından, Zaman aralığı: alanında, çözümlemeye odaklanmak istediğiniz zaman penceresini seçin.

Sorun giderme kılavuzları menüsünün ekran görüntüsü - Günlükler Zaman aralığı.

  1. Tanımlanan sorgunun açıklama çözümleme çıktısını almak için aşağıdaki sorguyu yürütür.
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

Yordamda aşağıda vurgulanan birden çok sorgu vardır. Saklı yordamda kullanılan her sorgunun açıklama analizi çıkışı, daha fazla analiz etmek ve sorun gidermek için oturum açar. Günlüğe kaydedilen sorguların yürütme süresi, saklı yordamın parçası olan en yavaş sorguları tanımlamak için kullanılabilir.

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

Not

Tanıtım amacıyla yordamda kullanılan yalnızca birkaç sorgunun EXPLAIN ANALYZE çıkışı gösterilir. Fikir, günlüklerden tüm sorguların EXPLAIN ANALYZE çıkışını toplayıp bunların en yavaşını belirleyip ayarlamaya çalışmaktır.

İlgili içerik

  • Last updated on