Når du arbejder med OLTP-databaser (OnLine Transaction Processing), er forespørgselsydeevne altafgørende, da det direkte påvirker brugeroplevelsen. Langsomme forespørgsler betyder, at applikationen føles ikke reagerer og langsom, og dette resulterer i dårlige konverteringsrater, utilfredse brugere og alle sæt problemer.
OLTP er en af de almindelige anvendelsesmuligheder for PostgreSQL, derfor ønsker du, at dine forespørgsler skal køre så glat som muligt. I denne blog vil vi gerne tale om, hvordan du kan identificere problemer med langsomme forespørgsler i PostgreSQL.
Forstå den langsomme log
Generelt set er den mest typiske måde at identificere ydeevneproblemer med PostgreSQL på at indsamle langsomme forespørgsler. Der er et par måder, du kan gøre det på. Først kan du aktivere det på en enkelt database:
pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;
ALTER DATABASEHerefter vil alle nye forbindelser til 'pgbench'-databasen blive logget ind i PostgreSQL-loggen.
Det er også muligt at aktivere dette globalt ved at tilføje:
log_min_duration_statement = 0til PostgreSQL-konfiguration og genindlæs derefter config:
pgbench=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)Dette muliggør logning af alle forespørgsler på tværs af alle databaserne i din PostgreSQL. Hvis du ikke kan se nogen logfiler, vil du måske også aktivere logging_collector =on. Logfilerne vil inkludere al den trafik, der kommer til PostgreSQL-systemtabeller, hvilket gør det mere støjende. Lad os til vores formål holde os til logføring på databaseniveau.
Det, du vil se i loggen, er poster som nedenfor:
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);Du kan se oplysninger om forespørgslen og dens varighed. Ikke meget andet, men det er bestemt et godt sted at starte. Det vigtigste at huske på er, at ikke hver langsom forespørgsel er et problem. Nogle gange skal forespørgsler have adgang til en betydelig mængde data, og det forventes, at de tager længere tid at få adgang til og analysere al den information, brugeren bad om. Et andet spørgsmål er, hvad "langsom" betyder? Dette afhænger mest af applikationen. Hvis vi taler om interaktive applikationer, er der højst sandsynligt noget, der er langsommere end et sekund, mærkbart. Ideelt set udføres alt inden for 100 - 200 millisekunders grænse.
Udvikling af en plan for udførelse af forespørgsler
Når vi har fastslået, at en given forespørgsel virkelig er noget, vi ønsker at forbedre, bør vi tage et kig på planen for udførelse af forespørgsler. Først og fremmest kan det ske, at der ikke er noget, vi kan gøre ved det, og vi bliver nødt til at acceptere, at en given forespørgsel bare er langsom. For det andet kan planerne for udførelse af forespørgsler ændre sig. Optimeringsværktøjer forsøger altid at vælge den mest optimale eksekveringsplan, men de træffer deres beslutninger baseret på blot et udsnit af data, derfor kan det ske, at forespørgselsudførelsesplanen ændrer sig med tiden. I PostgreSQL kan du tjekke udførelsesplanen på to måder. Først den estimerede udførelsesplan ved hjælp af 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)Som du kan se, forventes vi at få adgang til data ved hjælp af primærnøgleopslag. Hvis vi vil dobbelttjekke, hvordan forespørgslen præcist vil blive udført, kan vi bruge EXPLAIN ANALYZE:
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 har PostgreSQL udført denne forespørgsel, og den kan fortælle os ikke kun estimaterne, men nøjagtige tal, når det kommer til udførelsesplanen, antallet af rækker, der er tilgået og så videre. Husk, at logning af alle forespørgsler kan blive en alvorlig overhead på dit system. Du bør også holde øje med logfilerne og sikre, at de er roteret korrekt.
Pg_stat_statements
Pg_stat_statements er udvidelsen, der indsamler eksekveringsstatistikker for forskellige forespørgselstyper.
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)Som du kan se på dataene ovenfor, har vi en liste over forskellige forespørgsler og information om deres eksekveringstider - dette er kun en del af de data, du kan se i pg_stat_statements, men det er nok til til at forstå, at vores primære nøgleopslag nogle gange tager næsten 39 sekunder at fuldføre - dette ser ikke godt ud, og det er bestemt noget, vi gerne vil undersøge.
Hvis du ikke har pg_stat_statements aktiveret, kan du gøre det på en standard måde. Enten via konfigurationsfil og
shared_preload_libraries = 'pg_stat_statements'Eller du kan aktivere det via PostgreSQL-kommandolinjen:
pgbench=# CREATE EXTENSION pg_stat_statements;
CREATE EXTENSIONBrug af ClusterControl til at eliminere langsomme forespørgsler
Hvis du tilfældigvis bruger ClusterControl til at administrere din PostgreSQL-database, kan du bruge den til at indsamle data om langsomme forespørgsler.
Som du kan se, indsamler den data om udførelse af forespørgsler - rækker sendt og undersøgt, eksekveringstidsstatistikker og så videre. Med den kan du nemt lokalisere de dyreste forespørgsler og se, hvordan de gennemsnitlige og maksimale eksekveringstider ser ud. Som standard indsamler ClusterControl forespørgsler, der tog længere tid end 0,5 sekund at fuldføre, du kan ændre dette i indstillingerne:
Konklusion
Denne korte blog dækker på ingen måde alle de aspekter og værktøjer, der er nyttige til at identificere og løse problemer med forespørgselsydeevne i PostgreSQL. Vi håber, det er en god start, og at det vil hjælpe dig til at forstå, hvad du kan gøre for at finde årsagen til de langsomme forespørgsler.