Risolvere i problemi e identificare le query a esecuzione lenta in Database di Azure per PostgreSQL - Server flessibile

SI APPLICA A: Database di Azure per PostgreSQL - Server flessibile

Questo articolo illustra come risolvere i problemi e identificare le query a esecuzione lenta usando Database di Azure per PostgreSQL server flessibile.

In uno scenario di utilizzo elevato della CPU, in questo articolo si apprenderà come:

• Identificare le query a esecuzione lenta.

• Identificare una procedura a esecuzione lenta insieme a essa. Identificare una query lenta tra un elenco di query che appartengono alla stessa stored procedure a esecuzione lenta.

Scenario elevato della CPU - Identificare una query lenta

Prerequisiti

È necessario abilitare le guide alla risoluzione dei problemi e auto_explain'estensione nell'istanza del server flessibile Database di Azure per PostgreSQL. Per abilitare le guide alla risoluzione dei problemi, seguire i passaggi indicati qui.

Per abilitare auto_explain'estensione, seguire questa procedura:

1. Aggiungere auto_explain'estensione alle librerie di precaricamento condiviso, come illustrato di seguito dalla pagina dei parametri del server nel portale del server flessibile Database di Azure per PostgreSQL.

   

Nota

L'esecuzione di questa modifica richiederà un riavvio del server.

2. Dopo aver aggiunto l'estensione auto_explain alle librerie di precaricamento condiviso e il server è stato riavviato, modificare i parametri del server evidenziati di seguito auto_explain dalla pagina dei parametri del server nel portale del server flessibile Database di Azure per PostgreSQL e lasciare quelli rimanenti ON con valori predefiniti, come illustrato di seguito.

   

Nota

L'aggiornamento auto_explain.log_min_duration del parametro a 0 avvierà la registrazione di tutte le query eseguite nel server. Ciò può influire sulle prestazioni del database. Una due diligence adeguata deve essere effettuata per arrivare a un valore considerato lento sul server. Se ad esempio vengono considerati soglia 30 secondi e tutte le query eseguite al di sotto di 30 secondi sono accettabili per l'applicazione, è consigliabile aggiornare il parametro a 30000 millisecondi. Verrà quindi registrato qualsiasi query eseguita più di 30 secondi nel server.

Scenario - Identificare una query a esecuzione lenta

Con le guide alla risoluzione dei problemi e l'estensione auto_explain sul posto, viene illustrato lo scenario con l'aiuto di un esempio.

È disponibile uno scenario in cui l'utilizzo della CPU è stato aumentato al 90% e si vuole conoscere la causa radice del picco. Per eseguire il debug dello scenario, seguire i passaggi indicati di seguito.

1. Non appena viene visualizzato un avviso per uno scenario di CPU, passare alle guide alla risoluzione dei problemi disponibili nella scheda Guida della pagina di panoramica del portale del server flessibile Database di Azure per PostgreSQL.

   

2. Selezionare la scheda Utilizzo cpu elevato nella pagina aperta. Verrà visualizzata la guida alla risoluzione dei problemi di utilizzo elevato della CPU.

   

3. Selezionare l'intervallo di tempo del picco di CPU segnalato usando l'elenco a discesa intervallo di tempo.

   

4. Selezionare la scheda Top CPU Consume Queries (Query per utilizzo cpu superiore).

   La scheda condivide i dettagli di tutte le query eseguite nell'intervallo in cui è stato rilevato l'utilizzo della CPU al 90%. Dallo snapshot, sembra che la query con il tempo di esecuzione medio più lento durante l'intervallo di tempo sia di circa 2,6 minuti e che la query sia stata eseguita 22 volte durante l'intervallo. Questa è probabilmente la causa di picchi di CPU.

   

5. Connessione per azure_sys database ed eseguire la query per recuperare il testo effettivo della query usando lo script seguente.

    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. Nell'esempio considerato la query trovata lenta è la seguente:

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

7. Per comprendere quale piano di spiegazione esatto è stato generato, usare Database di Azure per PostgreSQL log dei server flessibili. L'estensione di spiegazione automatica avrebbe registrato una voce nei log ogni volta che l'esecuzione della query è stata completata durante l'intervallo. Selezionare la sezione Logs (Log) nella Monitoring scheda della pagina di panoramica del portale del server flessibile Database di Azure per PostgreSQL.

   

8. Selezionare l'intervallo di tempo in cui è stato trovato l'utilizzo della CPU al 90%.

   

9. Eseguire la query seguente per recuperare l'output di analisi della query identificata.

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

La colonna messaggio archivierà il piano di esecuzione come illustrato di seguito:

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

La query è stata eseguita per circa 2,5 minuti, come illustrato nelle guide alla risoluzione dei problemi e viene confermata dal duration valore di 150692,864 ms dall'output del piano di esecuzione recuperato. Usare l'output di analisi spiegazione per risolvere ulteriori problemi e ottimizzare la query.

Nota

Si noti che la query è stata eseguita 22 volte durante l'intervallo e i log illustrati in precedenza sono una voce di questo tipo acquisita durante l'intervallo.

Scenario elevato della CPU: identificare la procedura a esecuzione lenta e le query lente associate alla procedura

Nel secondo scenario viene rilevato un tempo di esecuzione della stored procedure lento e l'obiettivo è identificare e ottimizzare la query a esecuzione lenta che fa parte della stored procedure.

Prerequisiti

È necessario abilitare le guide alla risoluzione dei problemi e l'estensione auto_explain nell'istanza del server flessibile Database di Azure per PostgreSQL come prerequisito. Per abilitare le guide alla risoluzione dei problemi, seguire i passaggi indicati qui.

Per abilitare auto_explain'estensione, seguire questa procedura:

1. Aggiungere auto_explain'estensione alle librerie di precaricamento condiviso, come illustrato di seguito dalla pagina dei parametri del server nel portale del server flessibile Database di Azure per PostgreSQL.

   

Nota

L'esecuzione di questa modifica richiederà un riavvio del server.

2. Dopo aver aggiunto l'estensione auto_explain alle librerie di precaricamento condiviso e il server è stato riavviato, modificare i parametri del server evidenziati di seguito auto_explain dalla pagina dei parametri del server nel portale del server flessibile Database di Azure per PostgreSQL e lasciare quelli rimanenti ON con valori predefiniti, come illustrato di seguito.

   

Nota

• L'aggiornamento auto_explain.log_min_duration del parametro a 0 avvierà la registrazione di tutte le query eseguite nel server. Ciò può influire sulle prestazioni del database. Una due diligence adeguata deve essere effettuata per arrivare a un valore considerato lento sul server. Se ad esempio vengono considerati soglia 30 secondi e tutte le query eseguite al di sotto di 30 secondi sono accettabili per l'applicazione, è consigliabile aggiornare il parametro a 30000 millisecondi. Verrà quindi registrato qualsiasi query eseguita più di 30 secondi nel server.
• Il parametro auto_explain.log_nested_statements fa in modo che le istruzioni nidificate (istruzioni eseguite all'interno di una funzione o di una routine) vengano considerate per la registrazione. Quando è disattivata, vengono registrati solo i piani di query di primo livello. 

Scenario - Identificare una query a esecuzione lenta in una stored procedure

Con le guide alla risoluzione dei problemi e l'estensione auto_explain sul posto, viene illustrato lo scenario con l'aiuto di un esempio.

È disponibile uno scenario in cui l'utilizzo della CPU è stato aumentato al 90% e si vuole conoscere la causa radice del picco. Per eseguire il debug dello scenario, seguire i passaggi indicati di seguito.

1. Non appena viene visualizzato un avviso per uno scenario di CPU, passare alle guide alla risoluzione dei problemi disponibili nella scheda Guida della pagina di panoramica del portale del server flessibile Database di Azure per PostgreSQL.

   

2. Selezionare la scheda Utilizzo cpu elevato nella pagina aperta. Verrà visualizzata la guida alla risoluzione dei problemi di utilizzo elevato della CPU.

   

3. Selezionare l'intervallo di tempo del picco di CPU segnalato usando l'elenco a discesa intervallo di tempo.

   

4. Selezionare la scheda Top CPU Consume Queries (Query per utilizzo cpu superiore).

   La scheda condivide i dettagli di tutte le query eseguite nell'intervallo in cui è stato rilevato l'utilizzo della CPU al 90%. Dallo snapshot, sembra che la query con il tempo di esecuzione medio più lento durante l'intervallo di tempo sia di circa 6,3 minuti e che la query sia stata eseguita 35 volte durante l'intervallo. Questa è probabilmente la causa di picchi di CPU.

   

   È importante notare dallo snapshot seguente che il tipo di query come evidenziato di seguito è "Utilità". In genere, un'utilità può essere una stored procedure o una funzione in esecuzione durante l'intervallo.

5. Connessione per azure_sys database ed eseguire la query per recuperare il testo effettivo della query usando lo script seguente.

    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. Nell'esempio considerato, la query trovata lenta era una stored procedure come indicato di seguito:

    call autoexplain_test ();

7. Per comprendere quali spiegazioni esatte vengono generate per le query che fanno parte della stored procedure, usare Database di Azure per PostgreSQL log flessibili del server. L'estensione di spiegazione automatica avrebbe registrato una voce nei log ogni volta che l'esecuzione della query è stata completata durante l'intervallo. Selezionare la sezione Log dalla Monitoring scheda nella pagina di panoramica del portale del server flessibile Database di Azure per PostgreSQL.

   

8. Selezionare l'intervallo di tempo in cui è stato trovato l'utilizzo della CPU al 90%.

   

9. Eseguire la query seguente per recuperare l'output di analisi spiegato della query identificata.

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

La procedura include più query, evidenziate di seguito. La spiegazione analizza l'output di ogni query usata nella stored procedure viene registrata per analizzare ulteriormente e risolvere i problemi. Il tempo di esecuzione delle query registrate può essere usato per identificare le query più lente che fanno parte della stored 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

Nota

Si noti che a scopo dimostrativo viene illustrato come analizzare l'output di poche query usate nella procedura. L'idea è che si può raccogliere spiegare l'analisi dell'output di tutte le query dai log e quindi identificare il più lento di quelli e provare a ottimizzarli.

Contenuto correlato

• Utilizzo elevato della CPU
• Ottimizzazione automatica