In ogni distribuzione, ci sono sempre alcune query che vengono eseguite troppo lentamente.
Continua a leggere per scoprire come scoprire le query che richiedono troppo tempo per essere eseguite e come capire perché sono lente.
Usa solo pg_stat_statements?
pg_stat_statements è un'estensione popolare inclusa nella distribuzione principale di PostgreSQL e disponibile per impostazione predefinita su quasi tutti i provider DBaaS. È inestimabile ed è più o meno l'unico modo per ottenere statistiche sulle query senza installare estensioni personalizzate.
Ha tuttavia un paio di limitazioni quando si tratta di scoprire query lente.
Statistiche cumulative
L'estensione pg_stat_statements fornisce cumulativo statistiche su ogni query mai eseguita dal server. Per ogni query, mostra, tra le altre metriche, il numero totale di volte in cui è stata eseguita e il tempo totale impiegato per tutte le esecuzioni.
Per "catturare" query lente quando si verificano, è necessario recuperare periodicamente l'intero contenuto di pg_stat_statements visualizzare, archiviarlo in un database di serie temporali e confrontare i conteggi delle esecuzioni. Ad esempio, se hanno il contenuto di pg_stat_statements alle 10:00 e alle 10:10, è possibile selezionare quelle query che hanno un conteggio di esecuzione più elevato alle 10:10 rispetto alle 10:00. Per queste query, puoi calcolare il tempo medio di esecuzione durante questo intervallo, utilizzando:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Se questo tempo di esecuzione medio supera una soglia superiore, puoi attivare un avviso per intraprendere un'azione.
In pratica funziona abbastanza bene, ma avrai bisogno di una buona infrastruttura di monitoraggio o di un servizio dedicato come pgDash.
Parametri di query
pg_stat_statements non acquisisce i valori dei parametri di collegamento passati alle query.
Una delle cose che il pianificatore di query di Postgres stima per la selezione di un piano di esecuzione è il numero di righe che una condizione potrebbe filtrare. Ad esempio, se la maggior parte delle righe di una tabella ha il valore di una colonna indicizzata paese come "USA", il pianificatore potrebbe decidere di eseguire una scansione sequenziale dell'intera tabella per il dove clausola country = "US" e potrebbe decidere di utilizzare una scansione dell'indice per country = "UK" dal primo dove si prevede che la clausola corrisponda alla maggior parte delle righe della tabella.
Conoscere il valore effettivo dei parametri per i quali l'esecuzione della query è stata lenta può aiutare a diagnosticare più rapidamente i problemi di query lente.
Registrazione query lenta
L'alternativa più semplice è registrare le query lente. A differenza di un certo altro DBMS che semplifica le cose, PostgreSQL ci presenta un sacco di impostazioni di configurazione simili:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Questi sono descritti in dettaglio nella documentazione di Postgres. Ecco un punto di partenza ragionevole:
# next line says only log queries that take longer 5 seconds
log_min_duration_statement = 5s
log_parameter_max_length = 1024
log_parameter_max_length_on_error = 1024
Che si traduce in log come questi:
2022-04-14 06:17:11.462 UTC [369399] LOG: duration: 5.060 ms statement: select i.*, t."Name" as track, ar."Name" as artist
from "InvoiceLine" as i
join "Track" as t on i."TrackId" = t."TrackId"
join "Album" as al on al."AlbumId" = t."AlbumId"
join "Artist" as ar on ar."ArtistId" = al."ArtistId";
Se ci sono troppi log, puoi chiedere a Postgres di registrare solo (diciamo) il 50% delle query che durano più di 5 secondi:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Ovviamente dovresti leggere i documenti su cosa significano e implicano questi parametri prima di aggiungerli alla tua configurazione di Postgres. Tieni presente che le impostazioni sono bizzarre e non intuitive.
Piani di esecuzione delle query lente
In genere non è sufficiente sapere che si è verificata una query lenta, dovrai anche capire perché era lento. Per questo, in genere devi prima controllare il piano di esecuzione della query.
auto_explain è un'altra estensione di base di PostgreSQL (di nuovo, disponibile anche sulla maggior parte dei DBaaS) che può registrare i piani di esecuzione delle query che hanno appena terminato l'esecuzione. È documentato qui.
Per abilitare auto_explain, in genere lo aggiungi a shared_preload_libraries e riavvia Postgres. Ecco una configurazione di base di esempio:
# logs execution plans of queries that take 10s or more to run
auto_explain.log_min_duration = 10s
auto_explain.log_verbose = on
auto_explain.log_settings = on
auto_explain.log_format = json
auto_explain.log_nested_statements = on
# enabling these provide more information, but have a performance cost
#auto_explain.log_analyze = on
#auto_explain.log_buffers = on
#auto_explain.log_wal = on
#auto_explain.log_timing = on
#auto_explain.log_triggers = on
Ciò farà sì che i piani vengano registrati in formato JSON, che può quindi essere visualizzato in strumenti come questi.
Query ancora in esecuzione
Tutte le tecniche sopra elencate hanno una cosa in comune:producono output fruibile solo dopo una query ha terminato l'esecuzione. Non possono essere utilizzati per gestire query così lente questa volta da non aver ancora terminato l'esecuzione.
Ogni connessione a un server PostgreSQL è gestita da un backend , in particolare un backend client . Quando un tale back-end sta eseguendo una query, il suo stato è attivo . Potrebbe anche aver avviato una transazione ma poi è inattivo, chiamato transazione inattiva stato.
Il pg_stat_activity la vista di sistema qui documentata fornisce un elenco di tutti i backend Postgres in esecuzione. Puoi eseguire query in questa vista per ottenere query ancora in esecuzione:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
A proposito, senza utilizzare estensioni di terze parti, non c'è modo di conoscere il piano di esecuzione di una query che viene attualmente eseguita da un back-end.
Blocca
Se il piano di esecuzione di una query lenta non indica problemi evidenti, il back-end che esegue la query potrebbe essere stato ritardato da blocchi contesi.
I blocchi vengono ottenuti in modo esplicito o implicito durante l'esecuzione della query per una serie di motivi. C'è un intero capitolo nella documentazione di Postgres dedicato a questo.
Blocchi registrazione
In genere, viene impostato un limite massimo di tempo di attesa utilizzando l'opzione lock_timeout , solitamente lato cliente. Se una query ha atteso così a lungo per acquisire un blocco, Postgres annullerà l'esecuzione di questa query e registrerà un errore:
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 ERROR: canceling statement due to lock timeout
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 STATEMENT: cluster t;
Supponiamo che tu voglia impostare un timeout di blocco di 1 minuto, ma registra le query che attendono i blocchi per più di, diciamo, 30 secondi. Puoi farlo usando:
log_lock_waits = on
deadlock_timeout = 30s
Questo creerà log come questo:
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 LOG: process 70 still waiting for ShareLock on transaction 493 after 30009.004 ms
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 68. Wait queue: 70.
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 STATEMENT: select * from t for update;
L'uso di deadlock_timeout non è un errore di battitura:è il valore utilizzato dal meccanismo di registrazione dell'attesa del blocco. Idealmente, avrebbe dovuto esserci qualcosa come log_min_duration_lock_wait , ma purtroppo non è così.
In caso di deadlock effettivi, Postgres interromperà le transazioni bloccate dopo deadlock_timeout durata e registrerà le dichiarazioni incriminate. Non è necessaria alcuna configurazione esplicita.
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 LOG: process 68 detected deadlock while waiting for ShareLock on transaction 496 after 30007.633 ms
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 70. Wait queue: .
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 ERROR: deadlock detected
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process 68 waits for ShareLock on transaction 496; blocked by process 70.
Process 70 waits for ShareLock on transaction 495; blocked by process 68.
Process 68: select * from t where a=4 for update;
Process 70: select * from t where a=0 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 HINT: See server log for query details.
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
Scoperta dei blocchi correnti
L'intero elenco dei blocchi attualmente concessi è disponibile dalla vista di sistema pg_locks. Tuttavia, in genere è più semplice utilizzare la funzione pg_blocking_pids , insieme a pg_stat_activity , in questo modo:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
che può mostrare un output come questo:
stato state | pid | pg_blocking_pids | query
---------------------+--------+------------------+-------------------------------------------------
active | 378170 | {} | SELECT state, pid, pg_blocking_pids(pid), query+
| | | FROM pg_stat_activity +
| | | WHERE backend_type='client backend';
active | 369399 | {378068} | cluster "Track";
idle in transaction | 378068 | {} | select * from "Track" for update;
(3 rows)
che indica che esiste un back-end bloccato (quello che esegue l'istruzione CLUSTER) e che è stato bloccato dal PID 378068 (che ha eseguito un SELECT..FOR UPDATE ma è quindi inattivo all'interno della transazione).
