Bij het werken met OLTP-databases (OnLine Transaction Processing) is de prestatie van query's van het grootste belang, aangezien dit rechtstreeks van invloed is op de gebruikerservaring. Trage zoekopdrachten betekenen dat de applicatie niet reageert en traag aanvoelt en dit resulteert in slechte conversiepercentages, ontevreden gebruikers en allerlei problemen.
OLTP is een van de meest voorkomende gebruiksscenario's voor PostgreSQL, daarom wilt u dat uw zoekopdrachten zo soepel mogelijk verlopen. In deze blog willen we het hebben over hoe je problemen met trage zoekopdrachten in PostgreSQL kunt identificeren.
Het langzame logboek begrijpen
Over het algemeen is de meest typische manier om prestatieproblemen met PostgreSQL te identificeren het verzamelen van langzame query's. Er zijn een aantal manieren waarop u dit kunt doen. Ten eerste kunt u het inschakelen op een enkele database:
pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;
ALTER DATABASEHierna worden alle nieuwe verbindingen met de 'pgbench'-database aangemeld in het PostgreSQL-logboek.
Het is ook mogelijk om dit globaal in te schakelen door toe te voegen:
log_min_duration_statement = 0naar PostgreSQL-configuratie en laad vervolgens config:
pgbench=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)Hiermee kunnen alle zoekopdrachten in alle databases in uw PostgreSQL worden vastgelegd. Als u geen logboeken ziet, wilt u wellicht ook logging_collector =inschakelen. De logs bevatten al het verkeer dat naar PostgreSQL-systeemtabellen komt, waardoor het meer ruis krijgt. Laten we ons voor onze doeleinden houden aan het loggen op databaseniveau.
Wat u in het logboek ziet, zijn de onderstaande vermeldingen:
2020-02-21 09:45:39.022 UTC [13542] LOG: duration: 0.145 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 29817899;
2020-02-21 09:45:39.022 UTC [13544] LOG: duration: 0.107 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 11782597;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.065 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 16318529;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.082 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + 3063 WHERE tid = 3244;
2020-02-21 09:45:39.022 UTC [13526] LOG: duration: 16.450 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 1359 WHERE bid = 195;
2020-02-21 09:45:39.023 UTC [13523] LOG: duration: 15.824 ms statement: UPDATE pgbench_accounts SET abalance = abalance + -3726 WHERE aid = 5290358;
2020-02-21 09:45:39.023 UTC [13542] LOG: duration: 0.107 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -2716 WHERE tid = 1794;
2020-02-21 09:45:39.024 UTC [13544] LOG: duration: 0.112 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3814 WHERE tid = 278;
2020-02-21 09:45:39.024 UTC [13526] LOG: duration: 0.060 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (4876, 195, 39955137, 1359, CURRENT_TIMESTAMP);
2020-02-21 09:45:39.024 UTC [13529] LOG: duration: 0.081 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 3063 WHERE bid = 369;
2020-02-21 09:45:39.024 UTC [13523] LOG: duration: 0.063 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
2020-02-21 09:45:39.024 UTC [13542] LOG: duration: 0.100 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + -2716 WHERE bid = 210;
2020-02-21 09:45:39.026 UTC [13523] LOG: duration: 0.092 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3726 WHERE tid = 67;
2020-02-21 09:45:39.026 UTC [13529] LOG: duration: 0.090 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (3244, 369, 16318529, 3063, CURRENT_TIMESTAMP);Je kunt informatie over de zoekopdracht en de duur ervan bekijken. Niet veel anders, maar het is zeker een goede plek om te beginnen. Het belangrijkste om in gedachten te houden is dat niet elke langzame zoekopdracht een probleem is. Soms hebben zoekopdrachten toegang tot een aanzienlijke hoeveelheid gegevens en wordt verwacht dat ze meer tijd nodig hebben om toegang te krijgen tot alle informatie die de gebruiker heeft gevraagd en deze te analyseren. Een andere vraag is wat "langzaam" betekent? Dit is grotendeels afhankelijk van de toepassing. Als we het hebben over interactieve toepassingen, is hoogstwaarschijnlijk iets langzamer dan een seconde merkbaar. Idealiter wordt alles uitgevoerd binnen een limiet van 100 - 200 milliseconden.
Een plan voor het uitvoeren van query's ontwikkelen
Zodra we hebben vastgesteld dat een bepaalde query inderdaad iets is dat we willen verbeteren, moeten we het uitvoeringsplan voor de query bekijken. Allereerst kan het gebeuren dat we er niets aan kunnen doen en dat we moeten accepteren dat een bepaalde zoekopdracht gewoon traag is. Ten tweede kunnen de uitvoeringsplannen voor query's veranderen. Optimizers proberen altijd het meest optimale uitvoeringsplan te kiezen, maar ze nemen hun beslissingen op basis van slechts een steekproef van gegevens, daarom kan het gebeuren dat het uitvoeringsplan voor query's in de tijd verandert. In PostgreSQL kunt u het uitvoeringsplan op twee manieren controleren. Eerst het geschatte uitvoeringsplan, met EXPLAIN:
pgbench=# EXPLAIN SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4)
Index Cond: (aid = 5290358)Zoals je kunt zien, wordt van ons verwacht dat we toegang krijgen tot gegevens via het opzoeken van de primaire sleutel. Als we willen controleren hoe de query precies wordt uitgevoerd, kunnen we EXPLAIN ANALYZE gebruiken:
pgbench=# EXPLAIN ANALYZE SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4) (actual time=0.046..0.065 rows=1 loops=1)
Index Cond: (aid = 5290358)
Planning time: 0.053 ms
Execution time: 0.084 ms
(4 rows)Nu heeft PostgreSQL deze query uitgevoerd en het kan ons niet alleen de schattingen vertellen, maar ook exacte cijfers als het gaat om het uitvoeringsplan, het aantal rijen dat is geopend, enzovoort. Houd er rekening mee dat het loggen van alle query's een serieuze overhead op uw systeem kan worden. Je moet ook de houtblokken in de gaten houden en ervoor zorgen dat ze goed worden gedraaid.
Pg_stat_statements
Pg_stat_statements is de extensie die uitvoeringsstatistieken verzamelt voor verschillende soorten zoekopdrachten.
pgbench=# select query, calls, total_time, min_time, max_time, mean_time, stddev_time, rows from public.pg_stat_statements order by calls desc LIMIT 10;
query | calls | total_time | min_time | max_time | mean_time | stddev_time | rows
------------------------------------------------------------------------------------------------------+-------+------------------+----------+------------+---------------------+---------------------+-------
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2 | 30437 | 6636.83641200002 | 0.006533 | 83.832148 | 0.218051595492329 | 1.84977058799388 | 30437
BEGIN | 30437 | 231.095600000001 | 0.000205 | 20.260355 | 0.00759258796859083 | 0.26671126085716 | 0
END | 30437 | 229.483213999999 | 0.000211 | 16.980678 | 0.0075396134310215 | 0.223837608828596 | 0
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2 | 30437 | 290021.784321001 | 0.019568 | 805.171845 | 9.52859297305914 | 13.6632712046825 | 30437
UPDATE pgbench_tellers SET tbalance = tbalance + $1 WHERE tid = $2 | 30437 | 6667.27243200002 | 0.00732 | 212.479269 | 0.219051563294674 | 2.13585110968012 | 30437
SELECT abalance FROM pgbench_accounts WHERE aid = $1 | 30437 | 3702.19730600006 | 0.00627 | 38.860846 | 0.121634763807208 | 1.07735927551245 | 30437
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, $4, CURRENT_TIMESTAMP) | 30437 | 2349.22475800002 | 0.003218 | 61.372127 | 0.0771831901304325 | 0.971590327400244 | 30437
SELECT $1 | 6847 | 60.785467 | 0.002321 | 7.882384 | 0.00887767883744706 | 0.105198744982906 | 6847
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 5000 | 18.592042 | 0.001572 | 0.741427 | 0.0037184084 | 0.0137660355678027 | 5000
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 3000 | 7.323788 | 0.001598 | 0.40152 | 0.00244126266666667 | 0.00834442591085048 | 3000
(10 rows)Zoals je kunt zien aan de bovenstaande gegevens, hebben we een lijst met verschillende zoekopdrachten en informatie over hun uitvoeringstijden - dit is slechts een deel van de gegevens die je kunt zien in de pg_stat_statements, maar het is genoeg voor we moeten begrijpen dat het opzoeken van de primaire sleutel soms bijna 39 seconden duurt - dit ziet er niet goed uit en het is zeker iets dat we willen onderzoeken.
Als je pg_stat_statements niet hebt ingeschakeld, kun je dit op een standaard manier doen. Ofwel via configuratiebestand en
shared_preload_libraries = 'pg_stat_statements'Of je kunt het inschakelen via de PostgreSQL-opdrachtregel:
pgbench=# CREATE EXTENSION pg_stat_statements;
CREATE EXTENSIONClusterControl gebruiken om trage zoekopdrachten te elimineren
Als je ClusterControl gebruikt om je PostgreSQL-database te beheren, kun je het gebruiken om gegevens te verzamelen over langzame zoekopdrachten.
Zoals u kunt zien, verzamelt het gegevens over het uitvoeren van query's - rijen verzonden en onderzocht, uitvoeringstijdstatistieken enzovoort. Hiermee kunt u eenvoudig de duurste zoekopdrachten lokaliseren en zien hoe de gemiddelde en maximale uitvoeringstijden eruit zien. Standaard verzamelt ClusterControl zoekopdrachten die langer dan 0,5 seconde duurden, u kunt dit wijzigen in de instellingen:
Conclusie
Deze korte blog behandelt lang niet alle aspecten en hulpmiddelen die nuttig zijn bij het identificeren en oplossen van problemen met de prestatie van query's in PostgreSQL. We hopen dat dit een goed begin is en dat het u zal helpen begrijpen wat u kunt doen om de oorzaak van de trage zoekopdrachten te achterhalen.