W każdym wdrożeniu zawsze jest kilka zapytań, które działają zbyt wolno.
Czytaj dalej, aby dowiedzieć się, jak wykrywać zapytania, których wykonanie trwa zbyt długo i jak dowiedzieć się, dlaczego są powolne.
Wystarczy użyć pg_stat_statements?
pg_stat_statements to popularne rozszerzenie, które jest zawarte w podstawowej dystrybucji PostgreSQL i jest domyślnie dostępne u prawie wszystkich dostawców DBaaS. Jest nieoceniony i jest mniej więcej jedynym sposobem na uzyskanie statystyk zapytań bez instalowania niestandardowych rozszerzeń.
Ma jednak kilka ograniczeń, jeśli chodzi o wykrywanie powolnych zapytań.
Statystyki skumulowane
Rozszerzenie pg_stat_statements zapewnia kumulację statystyki dotyczące każdego zapytania wykonanego kiedykolwiek przez serwer. Dla każdego zapytania pokazuje, między innymi, łączną liczbę wykonań i łączny czas wszystkich wykonań.
Aby „złapać” powolne zapytania, gdy się pojawią, musisz okresowo pobierać całą zawartość pg_stat_statements przeglądać, przechowywać je w bazie danych szeregów czasowych i porównywać liczbę wykonań. Na przykład, jeśli masz zawartość pg_stat_statements o godzinie 10.00 i 10.10, możesz wybrać te zapytania, które mają większą liczbę wykonań o godzinie 10.10 niż o godzinie 10.00. Dla tych zapytań możesz obliczyć średni czas wykonania w tym przedziale, używając:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Jeśli ten średni czas wykonania przekroczy górny próg, możesz wywołać alert, aby podjąć działanie.
W praktyce działa to dość dobrze, ale będziesz potrzebować dobrej infrastruktury monitorowania lub dedykowanej usługi, takiej jak pgDash.
Parametry zapytania
pg_stat_statements nie przechwytuje wartości parametrów wiązania przekazywanych do zapytań.
Jedną z rzeczy, które planer zapytań Postgres szacuje przy wyborze planu wykonania, jest liczba wierszy, które warunek prawdopodobnie odfiltruje. Na przykład, jeśli większość wierszy tabeli ma wartość indeksowanej kolumny kraj jako „USA”, planista może zdecydować się na wykonanie skanowania sekwencyjnego całej tabeli dla gdzie klauzula country = "US" i może zdecydować się na skanowanie indeksu dla country = "UK" od pierwszego gdzie oczekuje się, że klauzula będzie pasować do większości wierszy w tabeli.
Znajomość rzeczywistej wartości parametrów, dla których wykonanie zapytania było powolne, może pomóc szybciej zdiagnozować problemy z wolnymi zapytaniami.
Powolne rejestrowanie zapytań
Prostszą alternatywą jest rejestrowanie powolnych zapytań. W przeciwieństwie do niektórych innych DBMS, które to ułatwiają, PostgreSQL przedstawia nam kilka podobnie wyglądających ustawień konfiguracyjnych:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Zostały one szczegółowo opisane w dokumentacji Postgresa. Oto rozsądny punkt wyjścia:
# 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
Co daje takie logi:
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";
Jeśli jest zbyt wiele logów, możesz poprosić Postgresa o rejestrowanie tylko (powiedzmy) 50% zapytań, które są uruchamiane dłużej niż 5 sekund:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Powinieneś oczywiście przeczytać dokumentację o tym, co oznaczają te parametry i implikować, zanim dodasz je do swojej konfiguracji Postgres. Pamiętaj, że ustawienia są dziwaczne i nieintuicyjne.
Plany wykonania powolnych zapytań
Zwykle nie wystarczy wiedzieć, że nastąpiło wolne zapytanie, musisz też dowiedzieć się, dlaczego to było powolne. W tym celu zazwyczaj najpierw sprawdzasz plan wykonania zapytania.
auto_explain to kolejne podstawowe rozszerzenie PostgreSQL (ponownie dostępne w większości DBaaS), które może rejestrować plany wykonania zapytań, które właśnie zakończyły wykonywanie. Jest to udokumentowane tutaj.
Aby włączyć automatyczne wyjaśnianie, zazwyczaj dodajesz je do shared_preload_libraries i uruchom ponownie Postgresa. Oto przykładowa konfiguracja startowa:
# 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
Spowoduje to, że plany będą rejestrowane w formacie JSON, który można następnie wizualizować w takich narzędziach.
Nadal wykonywane zapytania
Wszystkie wymienione powyżej techniki mają jedną wspólną cechę:dają użyteczne wyniki dopiero po zapytanie zakończyło wykonywanie. Nie można ich użyć do obsługi zapytań, które tym razem są tak powolne, że nie zostały jeszcze zakończone.
Każde połączenie z serwerem PostgreSQL jest obsługiwane przez zaplecze , a konkretnie zaplecze klienta . Gdy taki backend wykonuje zapytanie, jego stan jest aktywny . Mógł również rozpocząć transakcję, ale jest wtedy bezczynny, nazywany bezczynnym w transakcji stan.
pg_stat_activity Udokumentowany tutaj widok systemu zawiera listę wszystkich działających backendów Postgresa. Możesz wysłać zapytanie do tego widoku, aby uzyskać zapytania, które wciąż są uruchomione:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Nawiasem mówiąc, bez korzystania z rozszerzeń innych firm nie ma możliwości poznania planu wykonania zapytania, które jest aktualnie wykonywane przez backend.
Zamki
Jeśli plan wykonania powolnego zapytania nie wskazuje na żadne oczywiste problemy, backend wykonujący zapytanie mógł zostać opóźniony przez rywalizujące blokady.
Blokady są uzyskiwane jawnie lub niejawnie podczas wykonywania zapytania z różnych powodów. Poświęcony temu jest cały rozdział w dokumentacji Postgresa.
Logowanie blokad
Zazwyczaj górny limit czasu oczekiwania jest ustawiany za pomocą opcji lock_timeout , zwykle po stronie klienta. Jeśli zapytanie czekało tak długo na uzyskanie blokady, Postgres anuluje wykonanie tego zapytania i zarejestruje błąd:
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;
Załóżmy, że chcesz ustawić limit czasu blokady na 1 minutę, ale rejestruj zapytania, które czekają na blokady dłużej niż, powiedzmy, 30 sekund. Możesz to zrobić za pomocą:
log_lock_waits = on
deadlock_timeout = 30s
Spowoduje to utworzenie takich dzienników:
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;
Korzystanie z deadlock_timeout nie jest literówką:jest to wartość, której używa mechanizm logowania lock wait. Idealnie powinno być coś takiego jak log_min_duration_lock_wait , ale niestety tak nie jest.
W przypadku faktycznego zakleszczenia Postgres przerwie zakleszczone transakcje po deadlock_timeout czas trwania i zarejestruje obraźliwe oświadczenia. Żadna wyraźna konfiguracja nie jest konieczna.
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;
Wykrywanie aktualnych blokad
Cała lista aktualnie przyznanych blokad jest dostępna w widoku systemowym pg_locks. Jednak zazwyczaj łatwiej jest użyć funkcji pg_blocking_pids , wraz z pg_stat_activity , tak:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
który może pokazać wyjście takie jak to:
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 wskazuje, że istnieje jeden backend, który jest zablokowany (ten, który wykonuje instrukcję CLUSTER) i że jest blokowany przez PID 378068 (który wykonał SELECT..FOR UPDATE, ale następnie jest bezczynny w ramach transakcji).
