Leave a Comment
PostgreSQL EXPLAIN
При работе с MySql’овским EXPLAIN’ОМ всё просто (а может просто привычно).
Postgres предоставляет больше информации, но с ним сложнее разобраться.
Далее — вольный перевод статьи про PostgreSQL EXPLAIN (ссылка на оригинал в конце статьи).
Разберём небольшой пример:
|
1 2 3 4 5 |
EXPLAIN SELECT * FROM CUSTOMER; QUERY PLAN -------------------------------------------------------------- Seq Scan on customer (cost=0.00..60.48 rows=2048 width=107) (1 row) |
Это означает, что оптимизатор решил произвести последовательное чтение записей из таблицы. Он также оценил,что первая строка будет выведена через 0.00, а все — через 60.48. При этом будет возвращено 2048 строк средней длиной 107 байт.
EXPLAIN не запускает сам запрос, это лишь оценка. Для получения точных результатов нужно запустить EXPLAIN ANALYZE:
|
1 2 3 4 5 6 |
EXPLAIN ANALYZE SELECT * FROM CUSTOMER; QUERY PLAN ------------------------------------------------------------------------------------------------------------ Seq Scan on customer (cost=0.00..60.48 rows=2048 width=107) (actual time=0.033..6.577 rows=2048 loops=1) Total runtime: 7.924 ms (2 rows) |
Теперь появился второй набор данных: реальное время, затраченное на выполнение последовательного чтения, реальное число строк и количество повторов чтения этих строк (про повторы позже). Также появилась информация о полном времени выполнения запроса.
Можно заметить, что числа в реальном времени не очень то соответствуют предсказанным. Это потому, что оценка измеряется не во времени, а в специальных единицах. Одна единица равна времени, затраченному на последовательное чтение одной страницы с диска.
Но это слишком скучный запрос, перейдём к более интересным.
|
1 2 3 4 5 6 |
EXPLAIN SELECT * FROM customer ORDER BY city; QUERY PLAN -------------------------------------------------------------------- Sort (cost=173.12..178.24 rows=2048 width=107) Sort Key: city -> Seq Scan on customer (cost=0.00..60.48 rows=2048 width=107) |
Теперь план запроса включает 2 шага: сортировку и последовательное чтение. Хотя это и кажется нелогичным, запрос выполняется снизу вверх (если смотреть на план), т.е. результат последовательного чтения подаётся на вход оператору сортировки (оператор сортировки использует результаты последовательного чтения как входные данные).
Если взглянуть на шаг сортировки, можно заметить, что оптимизатор говорит, по какому полю проводится сортировка («Sort Key»). Разные виды обработки могут выводить дополнительную информацию вроде этой. Также стоит обратить внимание на то, что затраты на вывод первой строки оператором сортировки очень велики, они почти равны затратам на вывод всех столбцов. Это из-за того, что сначала он должен отсортировать все строки, что и занимает большую часть времени.
Если шагов выполнения запроса несколько, то показываемые затраты на шаг содержат не только затраты на выполнение этого шага, но и всех шагов ниже. В нашем примере затраты на шаг сортировки равны 173.12-60.48 для вывода первого результата, и 178.24-60.48 для вывода всех результатов. 60.48 вычитается из-за того, что сортировке необходимо получить все данные от последовательного чтения, прежде чем вернуть хоть что-то. В общем, когда видите очень похожие числа в затратах вывода первого и всех результатов, это означает, что операции требуются все данные предыдущих операций.
Теперь рассмотрим ещё более интересный пример:
|
1 2 3 4 5 6 7 8 9 |
EXPLAIN ANALYZE SELECT * FROM customer JOIN contact USING (last_name); QUERY PLAN ------------------------------------------------------------------------------------------------------------ Hash Join (cost=1.02..92.23 rows=2048 width=351) (actual time=1.366..58.684 rows=4096 loops=1) Hash Cond: (("outer".last_name)::text = ("inner".last_name)::text) -> Seq Scan on customer (cost=0.00..60.48 rows=2048 width=107) (actual time=0.079..21.658 rows=2048 loops=1) -> Hash (cost=1.02..1.02 rows=2 width=287) (actual time=0.146..0.146 rows=2 loops=1) -> Seq Scan on contact (cost=0.00..1.02 rows=2 width=287) (actual time=0.074..0.088 rows=2 loops=1) Total runtime: 62.233 ms |
Наконец-то что-то похожее на настоящий запрос. Обратите внимание на отступы. Они используются, чтобы показать, что результаты одних шагов используются в качестве входных данных для других. В нашем примере можно увидеть, что hash join принимает на вход результаты выполнения последовательного чтения и hash-операции. Последняя, в свою очередь, сама работает с результатами последовательного чтения. Заметьте, что hash-операция имеет одинаковые затраты на вывод первого и всех результатов — ей нужны все результаты до того, как вернуть что-либо. В этом плане интересно то, что затраты на вывод первого результата hash join зависит от суммарных затрат hash-операции, но начинается одновременно с последовательным чтением таблицы customer. Это потому, что hash join может возвращать результаты сразу, как только получит первый результат от обеих операций, дающих ему данные на вход.
Вернёмся к объяснению того, что такое повторы или циклы (loops), для этого рассмотрим пример:
|
1 2 3 |
-> Nested Loop (cost=5.64..14.71 rows=1 width=140) (actual time=18.983..19.481 rows=4 loops=1) -> Hash Join (cost=5.64..8.82 rows=1 width=72) (actual time=18.876..19.212 rows=4 loops=1) -> Index Scan using pg_class_oid_index on pg_class i (cost=0.00..5.88 rows=1 width=72) (actual time=0.051..0.055 rows=1 loops=4) |
Вложенный цикл — это то, что хорошо знакомо программистам, пишущим на процедурных языках; это что-то вроде:
|
1 2 3 4 5 |
for each row in input_a for each row in input_b do something next next |
Если в input_a 4 элемента, то внутренний цикл ( по input_b) будет выполнен 4 раза. Это именно то, о чём нам говорит оптимизатор в примере выше. Если умножить 0.055 на 4, то получится чуть меньше, чем разница между общим временем выполнения hash join’а и общим временем выполнения вложенного цикла (остаток времени скорее всего пошёл на накладные расходы, связанные с вычислением всего этого).
Что же это означает на практике? Обычно запрос запускают с EXPLAIN, пытаясь улучшить производительность. Ключом к этому является поиск шага, который занимает большую часть времени (а потом надо попытаться переписать медленную часть или весь запрос). Давайте взглянем на следующий пример и попытаемся найти проблемный шаг. (Этот запрос может запустить каждый и получит такой же результат).
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
EXPLAIN ANALYZE SELECT * FROM pg_indexes WHERE tablename='pg_constraint'; QUERY PLAN --------------------------------------------------------------------------------------------------------------- Nested Loop Left Join (cost=5.64..16.89 rows=1 width=260) (actual time=19.552..20.530 rows=4 loops=1) Join Filter: ("inner".oid = "outer".reltablespace) -> Nested Loop Left Join (cost=5.64..15.84 rows=1 width=200) (actual time=19.313..20.035 rows=4 loops=1) Join Filter: ("inner".oid = "outer".relnamespace) -> Nested Loop (cost=5.64..14.71 rows=1 width=140) (actual time=18.983..19.481 rows=4 loops=1) -> Hash Join (cost=5.64..8.82 rows=1 width=72) (actual time=18.876..19.212 rows=4 loops=1) Hash Cond: ("outer".indrelid = "inner".oid) -> Seq Scan on pg_index x (cost=0.00..2.78 rows=78 width=8) (actual time=0.037..0.296 rows=80 loops=1) -> Hash (cost=5.63..5.63 rows=1 width=72) (actual time=18.577..18.577 rows=1 loops=1) -> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.00..5.63 rows=1 width=72) (actual time=18.391..18.464 rows=1 loops=1) Index Cond: (relname = 'pg_constraint'::name) Filter: (relkind = 'r'::"char") -> Index Scan using pg_class_oid_index on pg_class i (cost=0.00..5.88 rows=1 width=72) (actual time=0.051..0.055 rows=1 loops=4) Index Cond: (i.oid = "outer".indexrelid) Filter: (relkind = 'i'::"char") -> Seq Scan on pg_namespace n (cost=0.00..1.06 rows=6 width=68) (actual time=0.014..0.045 rows=6 loops=4) -> Seq Scan on pg_tablespace t (cost=0.00..1.02 rows=2 width=68) (actual time=0.010..0.018 rows=2 loops=4) Total runtime: 65.294 ms |
Вложенный цикл имеет самое большое время выполнения — 20.035мс. Он, в свою очередь, использует результаты другого вложенного цикла и последовательного чтения, и уже этот вложенный цикл — самый долгий (19.481 мс).
Следовательно, сейчас «путь» к «дорогому» шагу следующий:
|
1 2 3 4 5 |
Nested Loop Left Join (cost=5.64..16.89 rows=1 width=260) (actual time=19.552..20.530 rows=4 loops=1) Join Filter: ("inner".oid = "outer".reltablespace) -> Nested Loop Left Join (cost=5.64..15.84 rows=1 width=200) (actual time=19.313..20.035 rows=4 loops=1) Join Filter: ("inner".oid = "outer".relnamespace) -> Nested Loop (cost=5.64..14.71 rows=1 width=140) (actual time=18.983..19.481 rows=4 loops=1) |
В этом примере эти шаги расположены последовательно, но это не всегда так.
Нижний вложенный цикл берёт данные отсюда:
|
1 2 3 4 5 6 7 8 9 10 |
-> Hash Join (cost=5.64..8.82 rows=1 width=72) (actual time=18.876..19.212 rows=4 loops=1) Hash Cond: ("outer".indrelid = "inner".oid) -> Seq Scan on pg_index x (cost=0.00..2.78 rows=78 width=8) (actual time=0.037..0.296 rows=80 loops=1) -> Hash (cost=5.63..5.63 rows=1 width=72) (actual time=18.577..18.577 rows=1 loops=1) -> Index Scan using pg_class_relname_nsp_index on pg_class (cost=0.00..5.63 rows=1 width=72) (actual time=18.391..18.464 rows=1 loops=1) Index Cond: (relname = 'pg_constraint'::name) Filter: (relkind = 'r'::"char") -> Index Scan using pg_class_oid_index on pg_class i (cost=0.00..5.88 rows=1 width=72) (actual time=0.051..0.055 rows=1 loops=4) Index Cond: (i.oid = "outer".indexrelid) Filter: (relkind = 'i'::"char") |
Заметим, что большую часть времени занимает hash join. Он берёт данные из последовательного чтения и hash-операции. Эта hash-операция занимает большую часть времени:
|
1 2 3 4 5 |
-> Hash (cost=5.63..5.63 rows=1 width=72) (actual time=18.577..18.577 rows=1 loops=1) -> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.00..5.63 rows=1 width=72) (actual time=18.391..18.464 rows=1 loops=1) Index Cond: (relname = 'pg_constraint'::name) Filter: (relkind = 'r'::"char") |
Мы наконец нашли самую дорогую часть запроса: сканирование индекса pg_class_relname_nsp_index. К сожалению, практически невозможно ускорить сканирование индекса для поиска одной строки. Но и занимает оно всего 18.464 мс, вряд ли когда-нибудь понадобится настолько улучшать производительность.
Ещё одно замечание: затраты на EXPLAIN ANALYZE достаточно значительны. Они могут занимать до 30% времени выполнения запроса. Поэтому EXPLAIN — это инструмент для измерения относительной производительности, а не абсолютной.
Оригинал статьи — Introduction to VACUUM, ANALYZE, EXPLAIN, and COUNT
Similar Posts
LEAVE A COMMENT
Для отправки комментария вам необходимо авторизоваться.