W artykule przedstawiamy trzy sposoby odnajdywania wolnych zapytań w bazie PostgreSQL. Poznaj specyfikę każdego z nich i dowiedz się, w jakich sytuacjach sprawdzą się najlepiej.
PostgreSQL slow query log
Opis
Jest to metoda stosunkowo najprostsza w implementacji. Umożliwia konfigurację serwera tak, aby zapisywał w pliku logu zapytania według potrzeby.
Można ustawić logowanie treści wszystkich zapytań trwających dłużej niż określony czas. Należy pamiętać, że taki zapis do logu kosztuje:
- I/O zapisu na dysk;
- cykle CPU – do wykonania operacji;
- miejsce w pliku logu.
Wartość log_min_duration_statement = 0, która umożliwia zapisywanie wszystkich wykonywanych zapytań do pliku logu, stosowana jest raczej na środowiskach testowych. Na obciążonych środowiskach produkcyjnych może istotnie spowolnić działanie systemu oraz spowodować nadmierne wykorzystanie (a nawet wyczerpanie) miejsca przeznaczonego na logowanie.
W środowiskach produkcyjnych stosuje się wyższe wartości, które zapewnią wychwycenie tych najwolniejszych zapytań. Dobrym początkiem może być ustawienie log_min_duration_statement = 5000, czyli 5 sekund, ale często mogą to być wartości 1 lub 10 sekund – w zależności od charakterystyki systemu.
Powyższe ustawienia zapewniają zbieranie informacji o zapytaniach trwających dłużej niż określony czas, który uznamy za długi w wypadku naszego systemu. Nie umożliwiają zebrania próbki wszystkich zapytań i oceny ile i jakich zapytań jest.
Jeżeli np. spowolnienie bazy jest spowodowane występowaniem tysięcy, czy milionów zapytań poniżej sekundy, to nie dowiemy się o tym fakcie przy pomocy tej metody.
Pewnym rozwiązaniem może być włączenie logowania czasu trwania zapytania log_duration = on. Pozwoli to nam zorientować się w ilości zapytań, gdyż w tym momencie logowane są czasy wykonania wszystkich zapytań oraz treść wedle ustawień parametrów wcześniej wymienionych:
2022-06-22 12:37:45.839 CEST [18399] LOG: duration: 0.903 ms
2022-06-22 12:37:54.489 CEST [18399] LOG: duration: 9.415 ms
2022-06-22 12:38:42.144 CEST [18399] LOG: duration: 0.149 ms
2022-06-22 12:38:44.213 CEST [18399] LOG: duration: 0.125 ms
2022-06-22 12:38:46.270 CEST [18399] LOG: duration: 0.145 ms
2022-06-22 12:38:48.318 CEST [18399] LOG: duration: 0.126 ms
2022-06-22 12:44:49.238 CEST [18399] LOG: duration: 7.742 ms
2022-06-22 12:44:51.067 CEST [18399] LOG: duration: 5.153 ms
2022-06-22 12:44:51.252 CEST [18399] LOG: duration: 5.726 ms
2022-06-22 12:44:53.923 CEST [18399] LOG: duration: 4.626 ms
2022-06-22 12:44:53.928 CEST [18399] LOG: duration: 5.081 ms
Od wersji 12 można ustawić, dla jakiego procenta wszystkich wykonywanych transakcji będzie dokonywany zapis pełnej treści transakcji (log_transaction_sample_rate).
W wersji 13 zostały dodane nowe możliwości ograniczania liczby logowanych zapytań:parametr log_statement_sample_rate określa, dla jakiego procenta zapytań trwających dłużej niż log_min_duration_sample ma zostać zapisana pełna treść zapytania.
Niezależnie od wyżej wymienionych działa parametr: log_statement – loguje wszystkie zapytania ustawionego typu. Jeżeli używamy parametrów opartych o czas i procent, ten parametr możemy pozostawić domyślny (none), lub ddl.
Parametry konfiguracyjne
| log_min_duration_statement | Loguj treść zapytania, które trwa dłużej niż tyle milisekund. |
| log_duration | Loguj czas trwania każdego zapytania, dla zapytań trwających krócej niż log_min_duration_statement logowany jest sam czas, bez treści. |
| log_transaction_sample_rate | Loguj treść zapytania dla takiego procenta wszystkich wykonywanych transakcji. |
| log_statement_sample_rate | Loguj treść zapytania dla takiego procenta zapytań trwających dłużej niż log_min_duration_sample. |
| log_min_duration_sample | Loguj treść zapytania, które trwa dłużej niż tyle milisekund, odnosi się do log_statement_sample_rate, nie ma związku z log_min_duration_statement. |
| log_statement | Loguj wszystkie zapytania typu:
none – nie loguj żadnego;
ddl – tylko zapytania Data Definition Language;
mod – tylko zapytania modyfikujące dane (w tym i DDL);
all -zapisuje wszystkie zapytania. |
Uruchomienie
- Wpis w pliku postgresql.conf
log_min_duration_statement=3000;
+ reload bazy
postgres=# ALTER SYSTEM SET log_min_duration_statement=3000;
ALTER SYSTEM
postgres=# Select pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)
- Zmiana dla konkretnego użytkownika
postgres=# CREATE USER test;
CREATE ROLE
postgres=# ALTER USER test SET log_min_duration_statement =10000;
ALTER ROLE
postgres=# \c postgres test
You are now connected to database "postgres" as user "test".
postgres=> SHOW log_min_duration_statement ;
log_min_duration_statement
----------------------------
10s
(1 row)
- Zmiana dla konkretnej bazy
postgres=# SHOW log_min_duration_statement ;
log_min_duration_statement
----------------------------
3s
(1 row)
postgres=# CREATE DATABASE test;
CREATE DATABASE
postgres=# ALTER DATABASE test SET log_min_duration_statement
FROM CURRENT TO
postgres=# ALTER DATABASE test SET log_min_duration_statement TO 5000;
ALTER DATABASE
postgres=# \c test
You are now connected to database "test" as user "postgres".
test=# SHOW log_min_duration_statement ;
log_min_duration_statement
----------------------------
5s
(1 row)
pg_stat_statements
Opis
Rozszerzenie to umożliwia zbieranie wszystkich wystąpień instrukcji SQL wykonywanych w obrębie serwera łącznie z informacjami statystycznymi odnośnie ich wykonania.
Dane zawarte w widoku pg_stat_statements pozwalają na wyselekcjonowanie zapytań, które byłoby najefektywniej zoptymalizować, a także dostarczają wiedzę o potencjalnym problemie.
postgres=# \d pg_stat_statements
View "public.pg_stat_statements"
Column | Type | Collation | Nullable | Default
---------------------+------------------+-----------+----------+---------
userid | oid | | |
dbid | oid | | |
toplevel | boolean | | |
queryid | bigint | | |
query | text | | |
plans | bigint | | |
total_plan_time | double precision | | |
min_plan_time | double precision | | |
max_plan_time | double precision | | |
mean_plan_time | double precision | | |
stddev_plan_time | double precision | | |
calls | bigint | | |
total_exec_time | double precision | | |
min_exec_time | double precision | | |
max_exec_time | double precision | | |
mean_exec_time | double precision | | |
stddev_exec_time | double precision | | |
rows | bigint | | |
shared_blks_hit | bigint | | |
shared_blks_read | bigint | | |
shared_blks_dirtied | bigint | | |
shared_blks_written | bigint | | |
local_blks_hit | bigint | | |
local_blks_read | bigint | | |
local_blks_dirtied | bigint | | |
local_blks_written | bigint | | |
temp_blks_read | bigint | | |
temp_blks_written | bigint | | |
blk_read_time | double precision | | |
blk_write_time | double precision | | |
wal_records | bigint | | |
wal_fpi | bigint | | |
wal_bytes | numeric | | |
W nadchodzącej wersji 15 znajdą się dodatkowe kolumny zawierające informacje o czasie spędzonym na zapisach/odczytach plików tymczasowych oraz statystyki funkcjonalności “Just in time compilation”.
temp_blk_read_time | double precision | | |
temp_blk_write_time | double precision | | |
jit_functions | bigint | | |
jit_generation_time | bigint | | |
jit_inlining_count | bigint | | |
jit_inlining_time | bigint | | |
jit_optimization_count | bigint | | |
jit_optimization_time | bigint | | |
jit_emission_count | bigint | | |
jit_emission_time | bigint | | |
Przykładowe informacje, które można uzyskać za pomocą rozszerzenia:
- Wyszukanie zapytań najczęściej zadawanych SELECT query, calls FROM pg_stat_statements ORDER BY 2 DESC;
- Wyszukanie zapytań, których łączny czas zapytania jest największy SELECT query, calls,total_exec_time + total_plan_time FROM pg_stat_statements ORDER BY 3 DESC;
- Wyszukanie zapytań najintensywniej używających plików tymczasowych SELECT query, calls,pg_size_pretty(temp_blks_written) FROM pg_stat_statements ORDER BY temp_blks_written DESC.
Oczywiście przedstawione przykłady nie wyczerpują wszystkich możliwości wykonania zapytań.
Parametry konfiguracyjne
| pg_stat_statements.max | Maksymalna ilość wierszy widoczna w widoku pg_stat_statements; jeżeli na serwerze wykonywanych jest więcej niż tyle różnych instrukcji SQL, to informacje o pozostałych nie będą przechowywane. |
| pg_stat_statements.track | Określa, dla jakich zapytań mają być zbierane statystyki:
top – bezpośrednie zapytania;
all – również zagnieżdżone – np. w funkcjach;
none – wyłączenie śledzenia statystyk. |
| pg_stat_statements.track_utility | Określa, czy zbierane są tzw. utility commands (inne niż select, insert, update, delete) – lista znajduje się tu: https://pgpedia.info/categories/utility-command.html. |
| pg_stat_statements.track_planning | Włączenie/wyłączenie śledzenia operacji planowania zapytań, ma wpływ na wydajność. |
| pg_stat_statements.save | Określa, czy statystyki mają być przechowywane pomiędzy restartami serwera, domyślnie tak. |
Uruchomienie
Aby można było uruchomić rozszerzenie musi być wczytana odpowiednia biblioteka w pliku
postgresql.conf: shared_preload_libraries = 'pg_stat_statements’.
W celu wczytania biblioteki konieczny jest restart serwera.
Następnie należy uruchomić rozszerzenie:
CREATE EXTENSION pg_stat_statements();
auto_explain
Opis
Czasem możemy spotkać się z sytuacjami, kiedy posiadamy już wytypowane instrukcje do optymalizacji i przeprowadzamy wspomnianą optymalizację. Następnie po ręcznym ich uruchomieniu działają prawidłowo, jednak uruchamiane automatycznie przez system nie działają optymalnie. Powody mogą być różne, np. dane, na których było wykonywane zapytanie, zmieniły się, już ich nie ma lub następuje nieoptymalne wywołanie z aplikacji (np. niezgodne typy danych).
Rozważmy taką sytuację:
postgres=# CREATE TABLE explain_test (id int GENERATED ALWAYS AS IDENTITY PRIMARY KEY, numerek int);
CREATE TABLE
postgres=# INSERT INTO explain_test (numerek ) SELECT * FROM generate_series(1, 1000000);
INSERT 0 1000000
postgres=# EXPLAIN ANALYZE SELECT id FROM explain_test WHERE id < 1000;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------
Index Only Scan using explain_test_pkey on explain_test (cost=0.42..28.49 rows=918 width=4) (actual time=0.043..0.474 rows=999 loops=1)
Index Cond: (id < 1000)
Heap Fetches: 0
Planning Time: 0.483 ms
Execution Time: 0.769 ms
(5 rows)
Zapytanie zgodnie z oczekiwaniami używa indexu. Zobaczmy kolejne zapytanie:
postgres=# EXPLAIN ANALYZE SELECT id FROM explain_test WHERE id < 1000000;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------
Seq Scan on explain_test (cost=0.00..16925.00 rows=999999 width=4) (actual time=0.028..490.079 rows=999999 loops=1)
Filter: (id < 1000000)
Rows Removed by Filter: 1
Planning Time: 0.197 ms
Execution Time: 741.269 ms
(5 rows)
Zapytanie zostanie zalogowane w strukturze pg_stat_statements tak samo jak poprzednie, będzie miało inny plan zapytania (również zgodnie z oczekiwaniami), ale nie dowiemy się o tym z informacji dostarczanych poprzez wspomniane rozszerzenie.
Z pomocą w takiej sytuacji przychodzi rozszerzenie auto_explain (podaje plan zapytania) lub PostgreSQL slow query log (podaje postać zapytania – z konkretnymi parametrami wywołania).
Parametry konfiguracyjne
| auto_explain.log_min_duration | Loguj zapytania trwające dłużej niż. |
| auto_explain.log_analyze | Włącza zapis wyjścia komendy EXPLAIN ANALYZE w miejsce domyślnej EXPLAIN. |
| auto_explain.log_buffers | Ekwiwalent opcji BUFFERS dla polecenia EXPLAIN. |
| auto_explain.log_wal | Ekwiwalent opcji WAL dla polecenia EXPLAIN. |
| auto_explain.log_timing | Ekwiwalent opcji TIMING dla polecenia EXPLAIN. |
| auto_explain.log_triggers | Uwzględnienie statystyk uwolnionych triggerów. |
| auto_explain.log_verbose | Ekwiwalent opcji VERBOSE dla polecenia EXPLAIN. |
| auto_explain.log_settings | Włączenie powoduje dodanie do planu informacji o zmienionych ustawieniach w stosunku do defaultowych. |
| auto_explain.log_format | Definiuje format zwracanego wyniku dla polecenia EXPLAIN {text,xml,json,yaml}. |
| auto_explain.log_level | Określa poziom logowania rozszerzenia auto_explain { DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE, WARNING, LOG}. |
| auto_explain.log_nested_statements | Powoduje załączenie planów zapytań wykonywanych wewnątrz funkcji. |
| auto_explain.sample_rate | Powoduje zalogowanie tylko określonej części zapytań z sesji. Nie obejmuje zapytań zagnieżdżonych – w tym wypadku logowane są wszystkie lub żadne (zgodnie z ustawieniami parametru auto_explain.log_nested_statements). |
Uruchomienie
- Dla indywidualnej sesji (użytkownik musi mieć uprawnienia administratora)
postgres=# LOAD 'auto_explain';
LOAD
postgres=# SET auto_explain.log_min_duration = 0;
SET
postgres=# SET auto_explain.log_analyze = true;
SET
postgres=# SELECT count(*)
postgres-# FROM pg_class, pg_index
postgres-# WHERE oid = indrelid AND indisunique;
W pliku logu pojawi się wpis typu:
duration: 0.731 ms plan:
Query Text: SELECT count(*)
FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique;
Aggregate (cost=28.19..28.20 rows=1 width=8) (actual time=0.713..0.719 rows=1 loops=1)
-> Hash Join (cost=21.91..27.84 rows=143 width=0) (actual time=0.463..0.665 rows=143 loops=1)
Hash Cond: (pg_index.indrelid = pg_class.oid)
-> Seq Scan on pg_index (cost=0.00..5.55 rows=143 width=4) (actual time=0.019..0.104 rows=143 loops=1)
Filter: indisunique
Rows Removed by Filter: 12
-> Hash (cost=16.96..16.96 rows=396 width=4) (actual time=0.429..0.430 rows=402 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 23kB
-> Seq Scan on pg_class (cost=0.00..16.96 rows=396 width=4) (actual time=0.010..0.221 rows=402 loops=1)
duration: 3.069 ms
- Dla całej instancji, jako biblioteka ładowana przy starcie systemu, wymagany wpis
shared_preload_libraries = ‘auto_explain’ oraz restart bazy danych.
- Dla całej instancji, jako biblioteka ładowana przy starcie sesji, wymagany wpis
session_preload_libraries = ‘auto_explain’ oraz reload bazy danych.
W takim wypadku moduł zostanie uruchomiony dla nowych sesji, sesje już istniejące nie będą nim objęte.
- Dla użytkownika / bazy danych – na poziomie użytkownika lub bazy danych można zmieniać poszczególne ustawienia, np.:
ALTER USER auto_explain SET auto_explain.log_min_duration TO 0;
oczywiście rozszerzenie musi być włączone jednym z dwóch poprzednich sposobów.