I varje distribution finns det alltid några frågor som går för långsamt.
Läs vidare för att se hur du upptäcker frågor som tar för lång tid att köra och hur du tar reda på varför de är långsamma.
Använd bara pg_stat_statements?
pg_stat_statements är ett populärt tillägg som ingår i kärndistributionen av PostgreSQL och tillgängligt som standard på nästan alla DBaaS-leverantörer. Det är ovärderligt och är mer eller mindre det enda sättet att få statistik på frågor utan att installera anpassade tillägg.
Det har dock ett par begränsningar när det gäller att upptäcka långsamma frågor.
Kumulerad statistik
Tillägget pg_stat_statements tillhandahåller kumulativ statistik om varje fråga som någonsin körts av servern. För varje fråga visar den bland annat det totala antalet gånger den har körts och den totala tiden som tagits för alla körningar.
För att "fånga" långsamma frågor när de inträffar måste du regelbundet hämta hela innehållet i pg_stat_statements visa, lagra den i en tidsseriedatabas och jämför antalet körningar. Om till exempel har innehållet i pg_stat_statements kl. 10.00 och 10.10, kan du välja de frågor som har ett högre antal exekveringar kl. 10.10 än kl. 10.00. För dessa frågor kan du beräkna den genomsnittliga körningstiden under detta intervall med:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Om denna genomsnittliga körningstid överskrider en övre tröskel kan du utlösa en varning för att vidta åtgärder.
Detta fungerar ganska bra i praktiken, men du behöver en bra övervakningsinfrastruktur eller en dedikerad tjänst som pgDash.
Frågeparametrar
pg_stat_statements fångar inte värdena för bindningsparametrar som skickas till frågor.
En av de saker som Postgres-frågeplaneraren uppskattar för att välja en exekveringsplan är antalet rader som ett villkor sannolikt kommer att filtrera bort. Till exempel om de flesta rader i en tabell har värdet av en indexerad kolumn land som "US" kan planeraren bestämma sig för att göra en sekventiell genomsökning av hela tabellen för var klausul country = "US" och kan välja att använda en indexskanning för country = "UK" sedan den första var klausul förväntas matcha de flesta rader i tabellen.
Att känna till det faktiska värdet av parametrarna för vilka frågan kördes långsamt kan hjälpa till att diagnostisera långsamma frågeproblem snabbare.
Långsam frågeloggning
Det enklare alternativet är att logga långsamma frågor. Till skillnad från en viss annan DBMS som gör detta enkelt, presenterar PostgreSQL oss med en massa liknande konfigurationsinställningar:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Dessa beskrivs i detalj i Postgres-dokumentationen. Här är en rimlig utgångspunkt:
# 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
Vilket resulterar i loggar som dessa:
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";
Om det finns för många loggar kan du be Postgres att endast logga (säg) 50 % av frågorna som körs längre än 5 sekunder:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Du bör naturligtvis läsa igenom dokumenten om vad dessa parametrar betyder och innebär innan du lägger till dem i din Postgres-konfiguration. Varnas för att inställningarna är udda och icke-intuitiva.
Utförandeplaner för långsamma frågor
Det räcker i allmänhet inte att veta att en långsam fråga inträffade, du måste också ta reda på varför det var långsamt. För detta kontrollerar du vanligtvis exekveringsplanen för frågan.
auto_explain är ett annat centralt PostgreSQL-tillägg (återigen, tillgängligt på de flesta DBaaS också) som kan logga exekveringsplanerna för frågor som precis har körts. Det finns dokumenterat här.
För att aktivera auto_explain lägger du vanligtvis till den i shared_preload_libraries och starta om Postgres. Här är ett exempel 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
Detta gör att planer loggas som JSON-format, som sedan kan visualiseras i verktyg som dessa.
Frågor som fortfarande körs
Alla tekniker som listas ovan har en sak gemensamt:de producerar handlingsbart resultat först efter en fråga har slutförts. De kan inte användas för att hantera frågor som är så långsamma den här gången att de inte har körts färdigt än.
Varje anslutning till en PostgreSQL-server hanteras av en backend , särskilt en klient-backend . När en sådan backend kör en fråga är dess tillstånd aktivt . Den kan också ha startat en transaktion men är då inaktiv, kallad inaktiv i transaktion tillstånd.
pg_stat_activity systemvyn som dokumenteras här ger en lista över alla Postgres-backends som körs. Du kan fråga den här vyn för att få frågor som fortfarande körs:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Förresten, utan att använda tillägg från tredje part, finns det inget sätt att veta exekveringsplanen för en fråga som för närvarande körs av en backend.
Lås
Om exekveringsplanen för en långsam fråga inte indikerar några uppenbara problem, kan den backend som kör frågan ha blivit försenad av påstådda låsningar.
Lås erhålls antingen explicit eller implicit under exekvering av en fråga av en mängd olika anledningar. Det finns ett helt kapitel i Postgres-dokumentationen som ägnas åt detta.
Loggningslås
Vanligtvis ställs en övre gräns för hur länge man ska vänta med alternativet lock_timeout , vanligtvis på kundsidan. Om en fråga har väntat så länge på att få ett lås, avbryter Postgres körningen av denna fråga och loggar ett felmeddelande:
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;
Låt oss säga att du vill ställa in en tidsgräns för låsning på 1 minut, men logga frågor som väntar på låsningar i mer än säg 30 sekunder. Du kan göra detta med:
log_lock_waits = on
deadlock_timeout = 30s
Detta kommer att skapa loggar så här:
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;
Användningen av deadlock_timeout är inte ett stavfel:det är värdet som loggningsmekanismen för lås väntan använder. Helst borde det ha funnits något som log_min_duration_lock_wait , men det är tyvärr inte fallet.
I händelse av faktiska dödlägen kommer Postgres att avbryta de låsta transaktionerna efter deadlock_timeout varaktighet och loggar de kränkande uttalandena. Ingen explicit konfiguration behövs.
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;
Upptäcka nuvarande lås
Hela listan över för närvarande beviljade lås är tillgänglig från systemvyn pg_locks. Det är dock vanligtvis lättare att använda funktionen pg_blocking_pids , tillsammans med pg_stat_activity , så här:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
som kan visa en utdata så här:
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)
som indikerar att det finns en backend som är blockerad (den som exekverar CLUSTER-satsen), och att den blockeras av PID 378068 (som har kört en SELECT..FOR UPDATE men som sedan går på tomgång i transaktionen).