Při práci s databázemi OLTP (OnLine Transaction Processing) je výkon dotazů prvořadý, protože přímo ovlivňuje uživatelskou zkušenost. Pomalé dotazy znamenají, že aplikace nereaguje a je pomalá, což má za následek špatné konverzní poměry, nešťastné uživatele a všechny sady problémů.
OLTP je jedním z běžných případů použití pro PostgreSQL, proto chcete, aby vaše dotazy běžely co nejplynuleji. V tomto blogu bychom chtěli mluvit o tom, jak můžete identifikovat problémy s pomalými dotazy v PostgreSQL.
Pochopení pomalého protokolu
Obecně řečeno, nejtypičtějším způsobem identifikace problémů s výkonem u PostgreSQL je shromažďování pomalých dotazů. Můžete to udělat několika způsoby. Nejprve jej můžete povolit v jedné databázi:
pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;
ALTER DATABASEPoté budou všechna nová připojení k databázi ‚pgbench‘ zaznamenána do protokolu PostgreSQL.
Toto je také možné povolit globálně přidáním:
log_min_duration_statement = 0na konfiguraci PostgreSQL a poté znovu načtěte konfiguraci:
pgbench=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)To umožňuje protokolování všech dotazů napříč všemi databázemi ve vašem PostgreSQL. Pokud nevidíte žádné protokoly, možná budete chtít povolit také logging_collector =on. Protokoly budou zahrnovat veškerý provoz přicházející do systémových tabulek PostgreSQL, takže budou hlučnější. Pro naše účely se držme protokolování na úrovni databáze.
V protokolu uvidíte níže uvedené záznamy:
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);Můžete zobrazit informace o dotazu a jeho trvání. Nic moc jiného, ale rozhodně je to dobré místo, kde začít. Hlavní věc, kterou je třeba mít na paměti, je, že ne každý pomalý dotaz je problém. Někdy musí dotazy zpřístupňovat značné množství dat a očekává se, že jim bude trvat déle, než zpřístupní a analyzují všechny informace, které uživatel požaduje. Další otázkou je, co znamená „pomalý“? To většinou závisí na aplikaci. Pokud se bavíme o interaktivních aplikacích, s největší pravděpodobností je patrné cokoli pomalejšího než sekunda. V ideálním případě je vše provedeno do limitu 100 - 200 milisekund.
Vývoj plánu provádění dotazů
Jakmile zjistíme, že daný dotaz je skutečně něco, co chceme zlepšit, měli bychom se podívat na plán provádění dotazu. V první řadě se může stát, že se s tím nedá nic dělat a budeme se muset smířit s tím, že daný dotaz je prostě pomalý. Za druhé, plány provádění dotazů se mohou změnit. Optimalizátoři se vždy snaží vybrat nejoptimálnější plán provádění, ale rozhodují se pouze na základě vzorku dat, takže se může stát, že plán provádění dotazu se časem změní. V PostgreSQL můžete zkontrolovat plán provádění dvěma způsoby. Nejprve odhadovaný plán provádění pomocí 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)Jak vidíte, očekává se, že k datům budeme přistupovat pomocí vyhledávání primárního klíče. Pokud chceme znovu zkontrolovat, jak přesně bude dotaz proveden, můžeme použít 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)Nyní PostgreSQL provedl tento dotaz a může nám říci nejen odhady, ale i přesná čísla, pokud jde o plán provádění, počet zpřístupněných řádků a tak dále. Mějte prosím na paměti, že protokolování všech dotazů může představovat vážnou režii vašeho systému. Měli byste také sledovat protokoly a zajistit, aby byly správně otočeny.
Výkazy_statických_stavů
Pg_stat_statements je rozšíření, které shromažďuje statistiky provádění pro různé typy dotazů.
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)Jak můžete vidět na údajích výše, máme seznam různých dotazů a informace o dobách jejich provádění - to je jen část údajů, které můžete vidět v pg_stat_statements, ale stačí pro abychom pochopili, že naše vyhledávání primárního klíče trvá někdy téměř 39 sekund – nevypadá to dobře a rozhodně to chceme prozkoumat.
Pokud nemáte povoleno pg_stat_statements, můžete to udělat standardním způsobem. Buď prostřednictvím konfiguračního souboru a
shared_preload_libraries = 'pg_stat_statements'Nebo to můžete povolit pomocí příkazového řádku PostgreSQL:
pgbench=# CREATE EXTENSION pg_stat_statements;
CREATE EXTENSIONPoužití ClusterControl k odstranění pomalých dotazů
Pokud náhodou používáte ClusterControl ke správě databáze PostgreSQL, můžete ji použít ke sběru dat o pomalých dotazech.
Jak vidíte, shromažďuje data o provádění dotazu – odeslané řádky a zkoumané, statistiky doby provádění a tak dále. S ním můžete snadno určit nejdražší dotazy a zjistit, jak vypadá průměrná a maximální doba provádění. Ve výchozím nastavení ClusterControl shromažďuje dotazy, jejichž dokončení trvalo déle než 0,5 sekundy, můžete to změnit v nastavení:
Závěr
Tento krátký blog v žádném případě nepokrývá všechny aspekty a nástroje užitečné při identifikaci a řešení problémů s výkonem dotazů v PostgreSQL. Doufáme, že je to dobrý začátek a že vám pomůže pochopit, co můžete udělat, abyste určili hlavní příčinu pomalých dotazů.