Problemen met trage query's in Azure Database for PostgreSQL - Flexible Server oplossen en identificeren

VAN TOEPASSING OP: Azure Database for PostgreSQL - Flexibele server

In dit artikel leest u hoe u problemen met trage query's oplost en identificeert met behulp van flexibele Azure Database for PostgreSQL-server.

In een scenario met hoog CPU-gebruik leert u in dit artikel het volgende:

• Identificeer trage query's.

• Identificeer een traaglopende procedure samen met deze procedure. Identificeer een trage query in een lijst met query's die deel uitmaken van dezelfde traag uitgevoerde opgeslagen procedure.

Scenario met hoog CPU-gebruik: trage query identificeren

Vereisten

U moet handleidingen voor probleemoplossing en auto_explain-extensie inschakelen op het flexibele serverexemplaren van Azure Database for PostgreSQL. Volg de stappen die hier worden vermeld om probleemoplossingsgidsen in te schakelen.

Volg de onderstaande stappen om auto_explain-extensie in te schakelen:

1. Voeg auto_explain-extensie toe aan de gedeelde preloadbibliotheken, zoals hieronder wordt weergegeven op de pagina serverparameters in de flexibele Azure Database for PostgreSQL-serverportal.

   

Notitie

Als u deze wijziging aanbrengt, moet de server opnieuw worden opgestart.

2. Nadat de auto_explain-extensie is toegevoegd aan gedeelde preloadbibliotheken en de server opnieuw is opgestart, wijzigt u de onderstaande gemarkeerde auto_explain serverparameters ON van de pagina serverparameters op de azure Database for PostgreSQL flexibele serverportal en laat u de overige met standaardwaarden staan, zoals hieronder wordt weergegeven.

   

Notitie

Als u de parameter bijwerkt auto_explain.log_min_duration naar 0, worden alle query's die op de server worden uitgevoerd, bijgehouden. Dit kan van invloed zijn op de prestaties van de database. Er moet een juiste due diligence worden uitgevoerd om te komen tot een waarde die als traag op de server wordt beschouwd. Voorbeeld als drempelwaarde van 30 seconden wordt beschouwd en alle query's die minder dan 30 seconden worden uitgevoerd, acceptabel zijn voor de toepassing, wordt geadviseerd om de parameter bij te werken naar 30000 milliseconden. Hiermee wordt een query vastgelegd die meer dan 30 seconden op de server wordt uitgevoerd.

Scenario: trage query identificeren

Met handleidingen voor probleemoplossing en auto_explain-extensie leggen we het scenario uit met behulp van een voorbeeld.

We hebben een scenario waarin het CPU-gebruik tot 90% is gestegen en de hoofdoorzaak van de piek wil weten. Volg de onderstaande stappen om fouten in het scenario op te sporen.

1. Zodra u wordt gewaarschuwd door een CPU-scenario, gaat u naar de handleidingen voor probleemoplossing die beschikbaar zijn op het tabblad Help op de overzichtspagina van azure Database for PostgreSQL Flexible Server Portal.

   

2. Selecteer het tabblad Hoog CPU-gebruik op de geopende pagina. De probleemoplossingsgids voor hoog CPU-gebruik wordt geopend.

   

3. Selecteer het tijdsbereik van de gerapporteerde CPU-piek met behulp van de vervolgkeuzelijst tijdsbereik.

   

4. Selecteer het tabblad Top CPU-verbruikende query's.

   Het tabblad deelt details van alle query's die zijn uitgevoerd in het interval waarin 90% CPU-gebruik is gezien. Vanuit de momentopname lijkt het erop dat de query met de traagste gemiddelde uitvoeringstijd tijdens het tijdsinterval ongeveer 2,6 minuten was en de query 22 keer werd uitgevoerd tijdens het interval. Dit is waarschijnlijk de oorzaak van CPU-pieken.

   

5. Verbinding maken om de database te azure_sys en de query uit te voeren om de werkelijke querytekst op te halen met behulp van het volgende script.

    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. In het voorbeeld dat werd overwogen, was de query die traag is gevonden het volgende:

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

7. Gebruik Azure Database for PostgreSQL Flexibele serverlogboeken om te begrijpen wat het exacte uitlegplan is gegenereerd. Automatisch uitleggen extensie zou een vermelding in de logboeken hebben geregistreerd telkens wanneer de query-uitvoering is voltooid tijdens het interval. Selecteer de sectie Logboeken op het Monitoring tabblad op de overzichtspagina van azure Database for PostgreSQL Flexible Server Portal.

   

8. Selecteer het tijdsbereik waarin 90% CPU-gebruik is gevonden.

   

9. Voer de volgende query uit om de analyse-uitvoer van de geïdentificeerde query op te halen.

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

In de berichtkolom wordt het uitvoeringsplan opgeslagen, zoals hieronder wordt weergegeven:

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

De query is uitgevoerd gedurende ongeveer 2,5 minuten, zoals weergegeven in handleidingen voor probleemoplossing en wordt bevestigd door de duration waarde van 150692,864 ms uit de uitvoer van het uitvoeringsplan dat is opgehaald. Gebruik de uitleg van analyse-uitvoer om problemen verder op te lossen en de query af te stemmen.

Notitie

Houd er rekening mee dat de query 22 keer tijdens het interval is uitgevoerd en dat de logboeken die hierboven worden weergegeven, een dergelijke vermelding zijn die tijdens het interval is vastgelegd.

Hoog CPU-scenario: trage procedure en trage query's identificeren die zijn gekoppeld aan de procedure

In het tweede scenario is de uitvoeringstijd van een opgeslagen procedure traag en is het doel om de traag uitgevoerde query te identificeren en af te stemmen die deel uitmaakt van de opgeslagen procedure.

Vereisten

U moet handleidingen voor probleemoplossing en auto_explain extensie inschakelen op het flexibele serverexemplaren van Azure Database for PostgreSQL als een vereiste. Volg de stappen die hier worden vermeld om probleemoplossingsgidsen in te schakelen.

Volg de onderstaande stappen om auto_explain-extensie in te schakelen:

1. Voeg auto_explain-extensie toe aan de gedeelde preloadbibliotheken, zoals hieronder wordt weergegeven op de pagina serverparameters in de flexibele Azure Database for PostgreSQL-serverportal.

   

Notitie

Als u deze wijziging aanbrengt, moet de server opnieuw worden opgestart.

2. Nadat de auto_explain-extensie is toegevoegd aan gedeelde preloadbibliotheken en de server opnieuw is opgestart, wijzigt u de onderstaande gemarkeerde auto_explain serverparameters ON van de pagina serverparameters op de azure Database for PostgreSQL flexibele serverportal en laat u de overige met standaardwaarden staan, zoals hieronder wordt weergegeven.

   

Notitie

• Als u de parameter bijwerkt auto_explain.log_min_duration naar 0, worden alle query's die op de server worden uitgevoerd, bijgehouden. Dit kan van invloed zijn op de prestaties van de database. Er moet een juiste due diligence worden uitgevoerd om te komen tot een waarde die als traag op de server wordt beschouwd. Voorbeeld als drempelwaarde van 30 seconden wordt beschouwd en alle query's die minder dan 30 seconden worden uitgevoerd, acceptabel zijn voor de toepassing, wordt geadviseerd om de parameter bij te werken naar 30000 milliseconden. Hiermee wordt een query vastgelegd die meer dan 30 seconden op de server wordt uitgevoerd.
• De parameter auto_explain.log_nested_statements zorgt ervoor dat geneste instructies (instructies die in een functie of procedure worden uitgevoerd) in aanmerking komen voor logboekregistratie. Wanneer deze is uitgeschakeld, worden alleen queryplannen op het hoogste niveau geregistreerd. 

Scenario: trage query identificeren in een opgeslagen procedure

Met handleidingen voor probleemoplossing en auto_explain-extensie leggen we het scenario uit met behulp van een voorbeeld.

We hebben een scenario waarin het CPU-gebruik tot 90% is gestegen en de hoofdoorzaak van de piek wil weten. Volg de onderstaande stappen om fouten in het scenario op te sporen.

1. Zodra u wordt gewaarschuwd door een CPU-scenario, gaat u naar de handleidingen voor probleemoplossing die beschikbaar zijn op het tabblad Help op de overzichtspagina van azure Database for PostgreSQL Flexible Server Portal.

   

2. Selecteer het tabblad Hoog CPU-gebruik op de geopende pagina. De probleemoplossingsgids voor hoog CPU-gebruik wordt geopend.

   

3. Selecteer het tijdsbereik van de gerapporteerde CPU-piek met behulp van de vervolgkeuzelijst tijdsbereik.

   

4. Selecteer het tabblad Top CPU-verbruikende query's.

   Het tabblad deelt details van alle query's die zijn uitgevoerd in het interval waarin 90% CPU-gebruik is gezien. Vanuit de momentopname ziet het eruit alsof de query met de traagste gemiddelde uitvoeringstijd tijdens het tijdsinterval ongeveer 6,3 minuten was en de query 35 keer werd uitgevoerd tijdens het interval. Dit is waarschijnlijk de oorzaak van CPU-pieken.

   

   Het is belangrijk om uit de onderstaande momentopname te zien dat het querytype, zoals hieronder is gemarkeerd, 'Utility' is. Over het algemeen kan een hulpprogramma een opgeslagen procedure of functie zijn die tijdens het interval wordt uitgevoerd.

5. Verbinding maken om de database te azure_sys en de query uit te voeren om de werkelijke querytekst op te halen met behulp van het onderstaande script.

    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. In het voorbeeld dat werd overwogen, was de gevonden query traag een opgeslagen procedure, zoals hieronder wordt vermeld:

    call autoexplain_test ();

7. Als u wilt weten welke exacte uitleg wordt gegenereerd voor de query's die deel uitmaken van de opgeslagen procedure, gebruikt u flexibele serverlogboeken van Azure Database for PostgreSQL. Automatisch uitleggen extensie zou een vermelding in de logboeken hebben geregistreerd telkens wanneer de query-uitvoering is voltooid tijdens het interval. Selecteer de sectie Logboeken op het Monitoring tabblad op de overzichtspagina van azure Database for PostgreSQL Flexible Server Portal.

   

8. Selecteer het tijdsbereik waarin 90% CPU-gebruik is gevonden.

   

9. Voer de onderstaande query uit om de uitgelegde analyse-uitvoer van de geïdentificeerde query op te halen.

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

De procedure heeft meerdere query's, die hieronder zijn gemarkeerd. De uitleg over het analyseren van de uitvoer van elke query die in de opgeslagen procedure wordt gebruikt, wordt aangemeld om verder te analyseren en problemen op te lossen. De uitvoeringstijd van de vastgelegde query's kan worden gebruikt om de traagste query's te identificeren die deel uitmaken van de opgeslagen procedure.

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

Notitie

Let op: voor demonstratiedoeleinden wordt uitgelegd hoe de uitvoer van slechts enkele query's die in de procedure worden gebruikt, worden gedeeld. Het idee is dat u uitleg kunt verzamelen over het analyseren van de uitvoer van alle query's uit de logboeken, en vervolgens de traagste query's kunt identificeren en proberen deze af te stemmen.

Gerelateerde inhoud

• Hoog CPU-gebruik
• Autovacuum afstemmen