V každém nasazení je vždy několik dotazů, které běží příliš pomalu.
Čtěte dále a zjistěte, jak odhalit dotazy, jejichž provedení trvá příliš dlouho, a jak zjistit, proč jsou pomalé.
Stačí použít pg_stat_statements?
pg_stat_statements je oblíbené rozšíření, které je součástí základní distribuce PostgreSQL a je standardně dostupné u téměř všech poskytovatelů DBaaS. Je to neocenitelné a je to víceméně jediný způsob, jak získat statistiky o dotazech bez instalace vlastních rozšíření.
Má však několik omezení, pokud jde o zjišťování pomalých dotazů.
Kumulativní statistiky
Rozšíření pg_stat_statements poskytuje kumulativní statistiky o každém dotazu, který kdy server provedl. U každého dotazu zobrazuje kromě jiných metrik celkový počet provedení a celkový čas všech provedení.
Abyste „chytili“ pomalé dotazy, když k nim dojde, musíte pravidelně načítat celý obsah pg_stat_statements zobrazit, uložit do databáze časových řad a porovnat počty provedení. Pokud máte například obsah pg_stat_statements v 10:00 a 10:10, můžete vybrat ty dotazy, které mají vyšší počet provedení v 10:10 než v 10:00. Pro tyto dotazy můžete vypočítat průměrnou dobu provádění během tohoto intervalu pomocí:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Pokud tato průměrná doba provádění překročí horní práh, můžete spustit výstrahu a provést akci.
V praxi to funguje poměrně dobře, ale budete potřebovat dobrou monitorovací infrastrukturu nebo specializovanou službu, jako je pgDash.
Parametry dotazu
pg_stat_statements nezachycuje hodnoty parametrů vazby předávané dotazům.
Jednou z věcí, které plánovač dotazů Postgres odhaduje pro výběr plánu provádění, je počet řádků, které podmínka pravděpodobně odfiltruje. Pokud má například většina řádků tabulky hodnotu indexovaného sloupce země jako „US“, plánovač se může rozhodnout provést sekvenční skenování z celé tabulky pro kde klauzule country = "US" a může se rozhodnout použít skenování indexu pro country = "UK" od prvního kde Očekává se, že klauzule bude odpovídat většině řádků v tabulce.
Znalost skutečné hodnoty parametrů, pro které bylo provádění dotazu pomalé, může pomoci rychleji diagnostikovat problémy s pomalým dotazem.
Pomalé protokolování dotazů
Jednodušší alternativou je protokolování pomalých dotazů. Na rozdíl od některých jiných DBMS, které to zjednodušují, nám PostgreSQL nabízí spoustu podobně vypadajících konfiguračních nastavení:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Ty jsou podrobně popsány v dokumentaci Postgres. Zde je rozumný výchozí bod:
# 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
Výsledkem jsou protokoly jako tyto:
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";
Pokud je protokolů příliš mnoho, můžete Postgres požádat, aby protokoloval pouze (řekněme) 50 % dotazů, které běží déle než 5 sekund:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Než je přidáte do konfigurace Postgres, měli byste si samozřejmě přečíst v dokumentaci, co tyto parametry znamenají a naznačují. Upozorňujeme, že nastavení jsou svérázná a neintuitivní.
Plány provádění pomalých dotazů
Obecně nestačí vědět, že došlo k pomalému dotazu, budete také muset zjistit proč bylo to pomalé. Za tímto účelem obvykle nejprve zkontrolujete plán provádění dotazu.
auto_explain je další základní rozšíření PostgreSQL (opět dostupné na většině DBaaS), které může zaznamenávat plány provádění dotazů, které právě skončily. Je to zdokumentováno zde.
Chcete-li aktivovat auto_explain, obvykle jej přidáte do shared_preload_libraries a restartujte Postgres. Zde je ukázková konfigurace startéru:
# 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
To způsobí, že plány budou protokolovány ve formátu JSON, který pak lze vizualizovat v nástrojích, jako jsou tyto.
Stále se provádějí dotazy
Všechny výše uvedené techniky mají jedno společné:produkují akční výstup až po dotaz byl dokončen. Nelze je použít ke zpracování dotazů, které jsou tentokrát tak pomalé, že ještě neskončily.
Každé připojení k PostgreSQL serveru je řešeno backendem , konkrétně klientský backend . Když takový backend provádí dotaz, jeho stav je aktivní . Možná také zahájil transakci, ale poté je nečinný, což se nazývá nečinný v transakci stavu.
pg_stat_activity zde zdokumentovaný systémový pohled poskytuje seznam všech běžících backendů Postgres. Chcete-li získat dotazy, které stále běží, můžete se dotazovat na toto zobrazení:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Mimochodem, bez použití rozšíření třetích stran neexistuje způsob, jak zjistit plán provádění dotazu, který je aktuálně prováděn backendem.
Zámky
Pokud plán provádění pomalého dotazu nenaznačuje žádné zjevné problémy, mohl být backend provádějící dotaz zdržen spornými zámky.
Zámky se získávají buď explicitně, nebo implicitně během provádění dotazu z různých důvodů. V dokumentaci Postgres je tomu věnována celá kapitola.
Zámky protokolování
Obvykle se horní limit doby čekání nastavuje pomocí možnosti lock_timeout , obvykle na straně klienta. Pokud dotaz na získání zámku čekal tak dlouho, Postgres zruší provádění tohoto dotazu a zaznamená chybu:
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;
Řekněme, že chcete nastavit časový limit zámku na 1 minutu, ale zaznamenáváte dotazy, které čekají na uzamčení déle než, řekněme 30 sekund. Můžete to udělat pomocí:
log_lock_waits = on
deadlock_timeout = 30s
Tím se vytvoří protokoly jako tento:
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;
Použití deadlock_timeout není překlep:je to hodnota, kterou používá mechanismus protokolování čekání na zámek. V ideálním případě by tam mělo být něco jako log_min_duration_lock_wait , ale bohužel tomu tak není.
V případě skutečného uváznutí Postgres přeruší zablokované transakce po deadlock_timeout trvání a zaprotokoluje problematické výroky. Není nutná žádná explicitní konfigurace.
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;
Zjištění aktuálních zámků
Celý seznam aktuálně udělených zámků je dostupný ze systémového pohledu pg_locks. Obvykle je však jednodušší použít funkci pg_blocking_pids spolu s pg_stat_activity , takto:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
který může zobrazit výstup jako tento:
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)
což znamená, že existuje jeden backend, který je blokován (ten, který provádí příkaz CLUSTER) a že je blokován PID 378068 (který provedl SELECT..FOR UPDATE, ale pak je v rámci transakce nečinný).