Bij elke implementatie zijn er altijd een paar query's die te traag worden uitgevoerd.
Lees verder om te zien hoe u zoekopdrachten kunt ontdekken die te lang duren om uit te voeren en hoe u erachter kunt komen waarom ze traag zijn.
Alleen pg_stat_statements gebruiken?
pg_stat_statements is een populaire extensie die is opgenomen in de kerndistributie van PostgreSQL en standaard beschikbaar is op bijna alle DBaaS-providers. Het is van onschatbare waarde en is min of meer de enige manier om statistieken over zoekopdrachten te krijgen zonder aangepaste extensies te installeren.
Het heeft echter een aantal beperkingen als het gaat om het ontdekken van langzame zoekopdrachten.
Cumulatieve statistieken
De extensie pg_stat_statements biedt cumulatieve statistieken over elke query die ooit door de server is uitgevoerd. Voor elke zoekopdracht toont het, naast andere statistieken, het totale aantal keren dat het is uitgevoerd en de totale tijd die nodig is voor alle uitvoeringen.
Om langzame zoekopdrachten te 'vangen' wanneer ze plaatsvinden, moet u periodiek de volledige inhoud van de pg_stat_statements ophalen bekijken, opslaan in een tijdreeksdatabase en het aantal uitvoeringen vergelijken. Als u bijvoorbeeld de inhoud van pg_stat_statements om 10.00 uur en 10.10 uur hebt, kunt u die query's selecteren die om 10.10 uur meer worden uitgevoerd dan om 10.00 uur. Voor deze query's kunt u de gemiddelde uitvoeringstijd tijdens dit interval berekenen met:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Als deze gemiddelde uitvoeringstijd een bovengrens overschrijdt, kunt u een waarschuwing activeren om actie te ondernemen.
Dit werkt in de praktijk redelijk goed, maar je hebt een goede monitoring-infrastructuur nodig, of een toegewijde service zoals pgDash.
Queryparameters
pg_stat_statements legt niet de waarden vast van bindingsparameters die aan query's zijn doorgegeven.
Een van de dingen die de Postgres-queryplanner schat voor het selecteren van een uitvoeringsplan, is het aantal rijen dat een voorwaarde waarschijnlijk zal uitfilteren. Als de meeste rijen van een tabel bijvoorbeeld de waarde hebben van een geïndexeerde kolom land als “VS” kan de planner besluiten om een sequentiële scan . uit te voeren van de hele tabel voor de waar clausule country = "US" , en kan besluiten om een indexscan te gebruiken voor country = "UK" sinds de eerste waar clausule zal naar verwachting overeenkomen met de meeste rijen in de tabel.
Als u de werkelijke waarde kent van de parameters waarvoor de uitvoering van de query traag was, kan dit helpen om problemen met trage query's sneller te diagnosticeren.
Langzame logging van zoekopdrachten
Het eenvoudigere alternatief is om langzame query's te loggen. In tegenstelling tot een bepaald ander DBMS dat dit gemakkelijk maakt, presenteert PostgreSQL ons een aantal gelijkaardige configuratie-instellingen:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Deze worden in detail beschreven in de Postgres-documentatie. Hier is een redelijk uitgangspunt:
# 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
Wat resulteert in logs zoals deze:
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";
Als er te veel logbestanden zijn, kunt u Postgres vragen om slechts (zeg) 50% van de zoekopdrachten te loggen die langer dan 5 seconden duren:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
U moet natuurlijk de documenten doorlezen over wat deze parameters betekenen en impliceren voordat u ze toevoegt aan uw Postgres-configuratie. Wees gewaarschuwd dat de instellingen eigenzinnig en niet-intuïtief zijn.
Uitvoeringsplannen van langzame query's
Het is over het algemeen niet voldoende om te weten dat er een langzame zoekopdracht is uitgevoerd, u moet ook uitzoeken waarom het ging langzaam. Hiervoor controleer je meestal eerst het uitvoeringsplan van de query.
auto_explain is een andere kernuitbreiding van PostgreSQL (opnieuw ook beschikbaar op de meeste DBaaS) die de uitvoeringsplannen kan loggen van query's die net zijn uitgevoerd. Het is hier gedocumenteerd.
Als u auto_explain wilt inschakelen, voegt u dit doorgaans toe aan shared_preload_libraries en herstart Postgre. Hier is een voorbeeld van een starterconfiguratie:
# 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
Dit zorgt ervoor dat plannen worden vastgelegd in JSON-indeling, die vervolgens kunnen worden gevisualiseerd in tools zoals deze.
Query's die nog steeds worden uitgevoerd
Alle hierboven genoemde technieken hebben één ding gemeen:ze produceren pas uitvoerbare uitvoer na een query is voltooid. Ze kunnen niet worden gebruikt voor het afhandelen van zoekopdrachten die deze ene keer zo traag zijn dat ze nog niet zijn uitgevoerd.
Elke verbinding met een PostgreSQL-server wordt afgehandeld door een backend , specifiek een client-backend . Wanneer zo'n backend een query uitvoert, is de status actief . Het kan ook een transactie zijn gestart, maar is dan inactief, genaamd idle in transactie staat.
De pg_stat_activity hier gedocumenteerde systeemweergave geeft een lijst weer van alle actieve Postgres-backends. U kunt een query uitvoeren op deze weergave om query's te krijgen die nog actief zijn:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Trouwens, zonder het gebruik van extensies van derden, is er geen manier om het uitvoeringsplan te kennen van een query die momenteel wordt uitgevoerd door een backend.
Sloten
Als het uitvoeringsplan van een langzame query geen duidelijke problemen aangeeft, is de backend die de query uitvoert mogelijk vertraagd door betwiste vergrendelingen.
Vergrendelingen worden om verschillende redenen expliciet of impliciet verkregen tijdens het uitvoeren van query's. In de Postgres-documentatie is hier een heel hoofdstuk aan gewijd.
Loggingsloten
Meestal wordt een bovengrens voor hoe lang te wachten ingesteld met behulp van de optie lock_timeout , meestal aan de kant van de klant. Als een zoekopdracht al zo lang wacht om een vergrendeling te verkrijgen, zal Postgres de uitvoering van deze zoekopdracht annuleren en een fout registreren:
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;
Stel dat u een vergrendelingstime-out van 1 minuut wilt instellen, maar logquery's in die langer dan bijvoorbeeld 30 seconden op vergrendelingen wachten. U kunt dit doen met:
log_lock_waits = on
deadlock_timeout = 30s
Dit maakt logs als volgt:
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;
Het gebruik van deadlock_timeout is geen typfout:het is de waarde die het log-wachtmechanisme voor vergrendeling gebruikt. Idealiter had er zoiets als log_min_duration_lock_wait . moeten zijn , maar helaas is dat niet het geval.
In het geval van daadwerkelijke deadlocks, zal Postgres de deadlock-transacties afbreken na deadlock_timeout duur, en zal de beledigende verklaringen loggen. Er is geen expliciete configuratie nodig.
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;
Huidige sloten ontdekken
De volledige lijst met momenteel verleende vergrendelingen is beschikbaar in de systeemweergave pg_locks. Het is echter meestal gemakkelijker om de functie pg_blocking_pids . te gebruiken , samen met pg_stat_activity , zoals dit:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
die een uitvoer als deze kan tonen:
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)
wat aangeeft dat er één backend is die is geblokkeerd (degene die de CLUSTER-instructie uitvoert), en dat deze wordt geblokkeerd door PID 378068 (die een SELECT..FOR UPDATE heeft uitgevoerd maar vervolgens inactief is binnen de transactie).