Håndtering af langsomme forespørgsler med PostgreSQL

I hver implementering er der altid nogle få forespørgsler, der kører for langsomt.

Læs videre for at se, hvordan du opdager forespørgsler, der tager for lang tid at udføre, og hvordan du finder ud af, hvorfor de er langsomme.

Brug bare pg_stat_statements?

pg_stat_statements er en populær udvidelse, der er inkluderet i kernepostgreSQL-distributionen og tilgængelig som standard på næsten alle DBaaS-udbydere. Det er uvurderligt og er mere eller mindre den eneste måde at få statistik over forespørgsler på uden at installere tilpassede udvidelser.

Det har dog et par begrænsninger, når det kommer til at opdage langsomme forespørgsler.

Kumuleret statistik

Udvidelsen pg_stat_statements giver kumulativ statistik om hver forespørgsel, der nogensinde er udført af serveren. For hver forespørgsel viser den blandt andre metrics det samlede antal gange, den er blevet udført, og den samlede tid, der er taget på tværs af alle henrettelser.

For at "fange" langsomme forespørgsler, når de sker, skal du med jævne mellemrum hente hele indholdet af pg_stat_statements se, gem det i en tidsseriedatabase og sammenlign antallet af eksekveringer. Hvis f.eks. har indholdet af pg_stat_statements kl. 10.00 og kl. 10.10, kan du vælge de forespørgsler, der har et højere antal eksekveringer kl. 10.10 end kl. 10.00. For disse forespørgsler kan du beregne den gennemsnitlige udførelsestid i dette interval ved at bruge:

(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
 

Hvis denne gennemsnitlige udførelsestid overstiger en øvre tærskel, kan du udløse en advarsel for at handle.

Dette fungerer rimeligt godt i praksis, men du skal bruge en god overvågningsinfrastruktur eller en dedikeret tjeneste som pgDash.

Forespørgselsparametre

pg_stat_statements fanger ikke værdierne af bindeparametre, der sendes til forespørgsler.

En af de ting, som Postgres-forespørgselsplanlæggeren anslår for at vælge en udførelsesplan, er antallet af rækker, som en betingelse sandsynligvis vil filtrere fra. For eksempel hvis de fleste rækker i en tabel har værdien af ​​en indekseret kolonne land som "US", kan planlæggeren beslutte at lave en sekventiel scanning af hele tabellen for hvor klausul country = "US" , og kan beslutte at bruge en indeksscanning for country = "UK" siden det første hvor klausul forventes at matche de fleste rækker i tabellen.

At kende den faktiske værdi af de parametre, for hvilke forespørgselsudførelsen var langsom, kan hjælpe med at diagnosticere problemer med langsomme forespørgsler hurtigere.

Langsom logføring af forespørgsler

Det nemmere alternativ er at logge langsomme forespørgsler. I modsætning til en bestemt anden DBMS, der gør dette nemt, præsenterer PostgreSQL os for en masse lignende konfigurationsindstillinger:

• log_statement
• log_min_duration_statement
• log_min_duration_sample
• log_statement_sample_rate
• log_parameter_max_length
• log_parameter_max_length_on_error
• log_duration

Disse er beskrevet detaljeret i Postgres-dokumentationen. Her er et rimeligt udgangspunkt:

# 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
 

Hvilket resulterer i logfiler som disse:

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";
 

Hvis der er for mange logfiler, kan du bede Postgres om kun at logge (f.eks.) 50 % af forespørgsler, der kører længere end 5 sekunder:

log_min_duration_sample = 5s
log_statement_sample_rate = 0.5   # 0..1 => 0%..100%
 

Du bør selvfølgelig læse dokumenterne igennem om, hvad disse parametre betyder og indebærer, før du tilføjer dem til din Postgres-konfiguration. Vær advaret om, at indstillingerne er skæve og ikke-intuitive.

Udførelsesplaner for langsomme forespørgsler

Det er generelt ikke tilstrækkeligt at vide, at en langsom forespørgsel skete, du skal også finde ud af hvorfor det var langsomt. Til dette vil du typisk først tjekke udførelsesplanen for forespørgslen.

auto_explain er en anden kerne PostgreSQL-udvidelse (igen, også tilgængelig på de fleste DBaaS), der kan logge eksekveringsplanerne for forespørgsler, der lige er afsluttet. Det er dokumenteret her.

For at aktivere auto_explain vil du typisk tilføje det til shared_preload_libraries og genstart Postgres. Her er et eksempel på en startkonfiguration:

# 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
 

Dette vil medføre, at planer logges som JSON-format, som derefter kan visualiseres i værktøjer som disse.

Forespørgsler, der stadig udføres

Alle de ovennævnte teknikker har én ting til fælles:de producerer kun handlingsvenligt output efter en forespørgsel er afsluttet. De kan ikke bruges til at håndtere forespørgsler, der er så langsomme denne ene gang, at de ikke er færdige med eksekveringen endnu.

Hver forbindelse til en PostgreSQL-server håndteres af en backend , specifikt en klient-backend . Når en sådan backend udfører en forespørgsel, er dens tilstand aktiv . Det kan også have startet en transaktion, men er derefter inaktiv, kaldet inaktiv i transaktion tilstand.

pg_stat_activity systemvisning dokumenteret her giver en liste over alle kørende Postgres backends. Du kan forespørge i denne visning for at få forespørgsler, der stadig kører:

SELECT client_addr, query_start, query
  FROM pg_stat_activity
 WHERE state IN ('active', 'idle in transaction')
   AND backend_type = 'client backend';
 

Forresten, uden at bruge tredjepartsudvidelser, er der ingen måde at kende eksekveringsplanen for en forespørgsel, der i øjeblikket udføres af en backend.

Låse

Hvis eksekveringsplanen for en langsom forespørgsel ikke indikerer nogen åbenlyse problemer, kan den backend, der udfører forespørgslen, være blevet forsinket på grund af anfægtede låse.

Låse opnås enten eksplicit eller implicit under udførelse af forespørgsler af forskellige årsager. Der er et helt kapitel i Postgres-dokumentationen dedikeret til dette.

Logningslåse

Typisk er en øvre grænse for, hvor længe der skal vente, indstillet ved hjælp af muligheden lock_timeout , normalt hos klienten. Hvis en forespørgsel har ventet så længe på at få en lås, vil Postgres annullere udførelsen af ​​denne forespørgsel og logge en fejl:

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;
 

Lad os sige, at du vil indstille en låsetimeout på 1 minut, men logforespørgsler, der venter på låse i mere end f.eks. 30 sekunder. Du kan gøre dette ved at bruge:

log_lock_waits = on
deadlock_timeout = 30s
 

Dette vil oprette logfiler som denne:

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;
 

Brugen af ​​deadlock_timeout er ikke en tastefejl:det er den værdi, som låsevent-logningsmekanismen bruger. Ideelt set skulle der have været noget som log_min_duration_lock_wait , men det er desværre ikke tilfældet.

I tilfælde af faktiske deadlocks vil Postgres afbryde de fastlåste transaktioner efter deadlock_timeout varighed, og vil logge de stødende udtalelser. Ingen eksplicit konfiguration er nødvendig.

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;
 

Opdagelse af nuværende låse

Hele listen over aktuelt tildelte låse er tilgængelig fra pg_locks-systemvisningen. Det er dog typisk nemmere at bruge funktionen pg_blocking_pids , sammen med pg_stat_activity , sådan her:

SELECT state, pid, pg_blocking_pids(pid), query
 FROM pg_stat_activity
WHERE backend_type='client backend';
 

som kan vise et output som dette: