Загадочный Postgres: история решения проблемы с невоспроизводимой производительностью

TL;DR

Примечание: это спойлер расследования ниже.

Первый сюрприз: некоторые драйверы Postgres (например, pgx в Go) используют подготовленные операторы «под капотом», без явного согласия пользователя.

Второй сюрприз: в Postgres запросы, выполняемые через подготовленный оператор, могут иметь другой план запроса, чем если бы они выполнялись напрямую. Планировщик запросов может использовать «общий» план запроса, который игнорирует значение параметров подготовленного оператора, что может привести к очень неэффективному плану запроса для отправляемых вами фактических значений.

Третий сюрприз: планировщик запросов Postgres имеет ошибку в оценке стоимости.

Следствие: у нас был запрос, который был особенно медленным в продакшене, но его было очень трудно воспроизвести, поскольку мы не знали, что наша ORM использует подготовленные операторы под капотом, и ничего не выглядело проблемным с простым EXPLAIN ANALYZE.

Исходный отчет об ошибке в приложении с использованием pgx
Отчет об ошибке для сообщества Postgres. Вывод таков: проблема действительно в планировщике запросов.

Фон

Birdie предоставляет технологии для поставщиков услуг по уходу на дому, чтобы обеспечить превосходный уход. В бэкенде наши сервисы должны осуществлять некоторый контроль доступа, чтобы гарантировать, что пользователи могут получить доступ только к тому, к чему им разрешено: для этого мы тестировали систему авторизации SpiceDB, реализацию Google's Zanzibar с открытым исходным кодом, которая у нас была признано подходящим для наших требований.

Задача SpiceDB — получать запросы типа «есть ли у пользователя X разрешение Y на ресурс Z?» и ответьте «да» или «нет». Мы настроили SpiceDB для использования Postgres в качестве хранилища данных.

Проблема

Когда я попытался направить некоторый теневой трафик в наше развертывание SpiceDB, все пошло не так. Ожидалось, что время отклика будет измеряться одноразрядными миллисекундами, но я заметил, что оно составляет минуты. Тайм-ауты и сбои были повсюду. Это не выглядело хорошо.

Я направляю свои глаза на самое очевидное, что приходит на ум: базу данных. Быстрый просмотр мониторинга AWS RDS дает подсказку: ЦП был загружен на 100%. На данный момент я уже обсуждаю с сопровождающими SpiceDB (прекрасная группа людей), предупреждая, что, похоже, что-то очень не так с адаптером Postgres (который в то время был своего рода бета-версией, CockroachDB был лучше поддерживаемым вариант).

В прошлом я уже вникал в махинации с Postgres, поэтому решил попытаться собрать как можно больше информации, чтобы совместно разобраться в проблеме. Первая остановка: AWS Performance Insights.

Анализ производительности

AWS Performance Insight — это сервис AWS для мониторинга вашей базы данных, в частности, он показывает самые популярные запросы по «типу ожидания» (что в основном представляет собой разные типы нагрузки): ЦП, чтение диска, запись на диск, блокировки… Это неинтуитивный инструмент. , ограниченный по функциональности, ужасно глючный, в основном не поддерживаемый, но все же один из самых полезных инструментов, которые нам нужны, чтобы выяснить, что не так в базе данных.

В то время вот что показал нам Performance Insight:

Много зелени. Зеленый означает ЦП. Мы уже знали, что ЦП БД был загружен до предела, поэтому не так много обучения. Единицу «средний активный сеанс» немного сложно интерпретировать, но этого достаточно, чтобы указать, что значение ›200 – это безумно высокое значение (наша здоровая база данных ниже 2).

Полезным свойством Performance Insight является то, что он точно сообщает, какие запросы к базе данных вызывают эту нагрузку. На данный момент у меня нет скриншота разбивки запросов, но выглядит это так:

В моем случае самым тяжелым запросом, который единолично отвечал за все это использование ЦП, был:

SELECT MIN(id), MAX(id) FROM relation_tuple_transaction
WHERE timestamp >= $1;

Первый выстрел в `EXPLAIN ANALYZE`

Хорошо, я легко определил запрос, который использует сумасшедшее количество ЦП, это хорошее начало. Это очень похоже на отсутствующий индекс, так что давайте EXPLAIN ANALYZE это. Копаясь в коде SpiceDB, я обнаружил, что это $1 всегда является одним и тем же значением (псевдокод ниже, фактический код здесь).

pg.query(
	"SELECT MIN(id), MAX(id) FROM relation_tuple_transaction WHERE timestamp >= $1",
	["now() - interval '5s'"]
)

«5s» на самом деле настраивается, но я уверен, что это значение используется для моего развертывания SpiceDB. Запустим EXPLAIN ANALYZE:

EXPLAIN ANALYZE SELECT MIN(id), MAX(id) FROM relation_tuple_transaction
WHERE timestamp >= now() - interval '5 seconds';
Aggregate  (cost=8.38..8.39 rows=1 width=16) (actual time=0.009..0.009 rows=1 loops=1)
  ->  Index Scan using ix_relation_tuple_transaction_by_timestamp on relation_tuple_transaction  (cost=0.42..8.37 rows=1 width=8) (actual time=0.005..0.006 rows=0 loops=1)
        Index Cond: ("timestamp" >= '2022-03-17 11:17:34'::timestamp without time zone)
Planning Time: 0.183 ms
Execution Time: 0.035 ms

Хм. Это быстро.

«Стоимость», т.е. оценка того, насколько затратным будет этот запрос, невысока: 8,39 — это немного в «единицах стоимости».
«Фактическое время» быстрое: 9 микросекунд.
План запроса кажется вполне разумным

Я уверен, что это проблемный запрос, я также уверен, что мы всегда запрашиваем с now() - interval '5s'. Тогда… почему моя база данных перегружена, когда этот запрос кажется таким быстрым и дешевым? Объем (запросов в секунду) является очевидной гипотезой, но встроенные метрики подтверждают, что мы не наблюдаем большого объема запросов: похоже, что мы имеем дело с разумным объемом запросов, очень интенсивно использующих ЦП. Что противоречит моему EXPLAIN ANALYZE. Что меня смущает.

Выстрел в темноте

Я понятия не имею, что происходит, и мне не во что копаться. Другими словами, я в темноте: давайте стрелять в темноте, чтобы, надеюсь, попасть в что-то, во что мы сможем вникнуть.

Среди различных вещей, которые я пробовал, я выполнил запрос, который дал мне интересный результат:

-- Same query, with a different value for `timestamp`
EXPLAIN ANALYZE SELECT MIN(id), MAX(id) FROM relation_tuple_transaction
WHERE timestamp >= '2022-03-15 00:00:00';
Result  (cost=1.07..1.08 rows=1 width=16) (actual time=28103.240..28103.242 rows=1 loops=1)
  InitPlan 1 (returns $0)
    ->  Limit  (cost=0.43..0.54 rows=1 width=8) (actual time=28103.219..28103.220 rows=1 loops=1)
          ->  Index Scan using pk_rttx on relation_tuple_transaction  (cost=0.43..193195.54 rows=1823603 width=8) (actual time=28103.218..28103.218 rows=1 loops=1)
                Index Cond: (id IS NOT NULL)
                Filter: ("timestamp" >= '2022-03-15 00:00:00'::timestamp without time zone)
                Rows Removed by Filter: 548517
  InitPlan 2 (returns $1)
    ->  Limit  (cost=0.43..0.54 rows=1 width=8) (actual time=0.016..0.016 rows=1 loops=1)
          ->  Index Scan Backward using pk_rttx on relation_tuple_transaction relation_tuple_transaction_1  (cost=0.43..193195.54 rows=1823603 width=8) (actual time=0.015..0.015 rows=1 loops=1)
                Index Cond: (id IS NOT NULL)
                Filter: ("timestamp" >= '2022-03-15 00:00:00'::timestamp without time zone)
Planning time: 0.375 ms
Execution time: 28103.275 ms

Установка временной метки на другое значение, в частности дату, которая находится дальше в прошлом (пару дней назад), дает мне совсем другой результат.

Выполнение запроса заняло очень много времени, здесь 28 сек.
План запроса сильно отличается и намного сложнее
Интересно, расчетная стоимость по-прежнему очень низкая. Это даже ниже, чем оценка, которую я получил, используя «5 секунд назад» в качестве фильтра.

Это супер интересный результат. Я еще не уверен, насколько это относится к моей проблеме, но это выглядит достаточно изменчиво, и я хотел бы посмотреть, смогу ли я провести какие-то корреляции с моей проблемой. Вот что приходит мне в голову:

Это время выполнения согласуется со временем отклика, которое я наблюдаю в реальности. 28s должен означать, что тратится много ресурсов ЦП (весьма вероятно, из-за этого Rows Removed by Filter: 548517). Этот план запроса согласуется с тем, что показывает мне мониторинг базы данных.
«Ориентировочная стоимость» очень низкая, но запрос на самом деле очень сильно загружает ЦП: это пахнет проблемой планировщика запросов. Это плохие новости: как известно, планировщик запросов Postgres — это черный ящик, который у меня очень мало контроля, если есть проблема, я не смогу найти обходной путь.
Фактическое значение timestamp, используемое в WHERE, похоже, имеет большое значение для планировщика запросов.

Это дает мне направление для исследования: возможно ли каким-то образом, что план запроса, который я получаю при выполнении EXPLAIN ANALYZE с фильтром «5 с назад», не тот, который используется для SpiceDB? Даже если я абсолютно уверен, что SpiceDB также использует «5 с назад»?

Покопайтесь в статистике планировщика

Говоря о вариантах планов запросов, обычно подозревают, что Postgres использует статистику.

Postgres ведет некоторые статистические данные о содержимом ваших таблиц (количество строк, распределение значений…), чтобы помочь в создании оптимизированных планов запросов. Эти статистические данные меняются при записи (например, таблица увеличивается в размере), и планировщик запросов может решить начать использовать другой план запроса для данного запроса. Невозможно точно предвидеть это изменение, и нет способа заставить другой план запроса: вот почему планировщик запросов Postgres считается черным ящиком.

Поэтому, когда я сталкиваюсь с проблемой «изменения планов запросов», «статистика» вызывает у меня паучье чутье.

Однако в данном случае моя гипотеза состоит в том, что я получаю разные планы запросов для одного и того же запроса в одной и той же базе данных и в тот же набор данных. На самом деле это не похоже на распространенную проблему изменения статистики.

Для душевного спокойствия я запускаю VACUUM ANALYZE FULL (⚠️ это заблокирует вашу таблицу на некоторое время), чтобы определенно очистить статистику и шум, связанный с мертвыми кортежами. Без изменений. Похоже, это не проблема статистики.

У меня закончились теории: похоже, у моего Postgres-fu есть слепое пятно. пришло время посетить postgresql.org и stackoverflow.com, чтобы узнать больше о планировании запросов.

Потянув за нить

Честно говоря, ни документация, ни Stackoverflow не дают мне прозрения. Кажется, ничто не объясняет, как данный запрос к данному набору данных может привести к различным планам запроса.

Но я чую слабый след. Хотя это, кажется, не применимо к моему делу, есть кое-что, что продолжает появляться в моих исследованиях: подготовленные утверждения (например, эта спасительная ветка StackExchange).

Во всем Интернете единственное явление, связанное с противоречивыми планами запросов, — это подготовленные операторы. Тема StackExchange хорошо объясняет это:

PostgreSQL имеет встроенную эвристику для [подготовленных] операторов, чьи планы могут быть кэшированы: он планирует их с фактическими значениями параметров в течение первых 5 раз, а затем переключается на общий план, если этот план обещает не выполняться. хуже

Это было бы объяснением. Если каким-либо образом задействованы подготовленные операторы, PG примет во внимание фактическое значение параметра timestamp для первых 5 исполнений: это будет быстро. Начиная с 6-го выполнения, он не учитывает, какое значение на самом деле имеет timestamp, и всегда применяет общий план запроса: этот общий план запроса, вероятно, такой же, как я наблюдал с другим значением для timestamp: он намного медленнее и Нагружает ЦП.

Отличная теория! Кроме…

Нигде в коде SpiceDB не использует подготовленные операторы. Специалисты по сопровождению SpiceDB подтверждают, что не используют планы запросов.
Postgres «переключается на общий план, если этот план обещает не ухудшить производительность», но «общий план», кажется, работает намного хуже. ни в коем случае этот план запроса не лучше даже для разных значений фильтра timestamp: почему Postgres решил переключиться на него?

Скрытые подготовленные операторы

Давайте сосредоточимся на первом открытом вопросе: «нигде в коде SpiceDB не использует подготовленные операторы». Я уверен в этом, но все же… такое поведение подготовленного утверждения слишком близко совпадает с моими наблюдениями, и больше ничего не соответствует: мой внутренний Холмс кричит: «когда ты устранил все невозможное, тогда все, что осталось, каким бы невероятным оно ни было, должно быть правдой». Даже если я не понимаю, как подготовленные заявления могут быть причиной, кажется, что только подготовленные заявления объясняют то, что я наблюдаю *.*

Примерно в это же время я замечаю то, что должен был заметить намного раньше. Вернемся к самому началу моего расследования, я определил этот запрос как виновника загрузки процессора:

SELECT MIN(id), MAX(id) FROM relation_tuple_transaction
WHERE timestamp >= $1;

Обратите внимание на это $1? На самом деле я ничего об этом не думал, но теперь... Это не говорит now() - interval '5s', хотя я знаю, что это значение всегда используется, оно говорит $1. И эта штука $ — это подготовленная инструкция: это заполнитель параметра.

Я не понимаю, как могут быть задействованы подготовленные операторы, но сейчас я почти уверен, что они есть.

Этот вопрос StackOverflow, который объясняет похожую проблему, дает мне еще одну подсказку. В нем упоминается pgx, библиотека Go, которую использует SpiceDB. Новая гипотеза: возможно ли, что pgx автоматически создает подготовленные операторы для запросов?

"Да, это". В README в качестве функции упоминается автоматическая подготовка и кэширование операторов. Поэтому, хотя я ожидал (как и сопровождающие SpiceDB), что вызов pgx с оператором и параметрами приведет к чему-то похожему на PQExecParams libpq, на самом деле он создает подготовленный оператор, более похожий на PQExecPrepared.

Какие-то дырявые абстракции.

На данный момент у нас было достаточно информации для Джейка из Authzed (сопровождающего SpiceDB), чтобы управлять последовательным воспроизведением проблемы: https://dbfiddle.uk/5N7GmTuz.

Неверный общий план запроса

Теперь мы знаем, откуда взялся этот плохой план запроса. Остается еще один открытый вопрос: почему Postgres решил переключиться на общий план запросов, который намного хуже работает?

На самом деле мы уже ответили на этот вопрос: оценка стоимости этого плана запроса полностью неверна, что делает его кандидатом по сравнению с пользовательским планом запроса, несмотря на то, что в реальности он ужасно медленный. Другими словами, он обещает не быть хуже, но не выполняет обещание. Другими словами, это ошибка в планировщике запросов.

Работа над проблемой

Хорошо, я знаю, откуда берется этот плохой план запроса: это общий план подготовленного оператора. У нас есть несколько вариантов исправить это в порядке от «простого, но обходного пути» до «сложного, но устраняющего основную причину»:

Я могу исправить это для моего конкретного развертывания SpiceDB. К счастью, одна из немногих вещей, которые планировщик запросов делает и дает вам некоторый контроль, — это использование универсальных планов запросов. Включив настройку с plan_cache_mode на force_custom_plan, я полностью отключу использование универсальных планов запросов для всей базы данных: подготовленные операторы всегда будут использовать пользовательский план запросов. Это сработало: ЦП сразу падает до нуля, а время отклика увеличивается с минут до миллисекунд. Ууууууу.
Другие пользователи SpiceDB Postgres, конечно же, столкнутся с той же проблемой. SpiceDB может обойти эту проблему, убедившись, что подготовленный оператор не используется для этого конкретного запроса.
Ничего из этого не было бы проблемой, если бы планировщик запросов Postgres не выдавал плохой план запроса. Это баг планировщика запросов, сейчас он в руках сообщества Postgres.

Этот отчет об ошибке быстро прошел мимо меня, но все пришли к соглашению, что в планировщике запросов действительно есть проблема. Из этого вышел патч, но, как упоминалось в цепочке писем, «это просто пластырь, который помогает именно в этом сценарии. Это мало что делает для плохой оценки стоимости, которая является корнем проблемы».

Хотя похоже, что это не будет исправлено в ближайшее время, я надеюсь, что эта статья показала, как можно отлаживать проблемы с производительностью Postgres!

Мы набираем сотрудников на различные должности в инженерной сфере. Посмотрите их здесь:

https://www.birdie.care/join-us#jobs-live