При поиске проблем в RDBMs разработчик обычно подозревает медленные запросы. А что, если дело не в них? О том, какого типа запросы дают нагрузку на базу данных, не позволяя вашему приложению работать должным образом, рассказал в своем докладе на конференции Saint HighLoad++ Online 2020 администратор баз данных Data Egret Андрей Сальников. 

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

До момента всеобщей изоляции на поддержке Data Egret был сервис, на котором мастер-база держала где-то 50 тысяч транзакций в секунду.

Когда наступила изоляция, и онлайн-сервисы обрели особенную популярность, на этой базе данных компания уперлась в процессорный потолок, после чего появилось решение переехать на новое оборудование. Количество транзакций, обрабатываемых базой данных, после переезда скакнуло выше 100 тысяч в секунду, и это только на Master Server.

Что было сделано

• Переезд базы данных и приложений на более мощные сервера, у которых больше процессоров и памяти; 

• Увеличение количества приложений, потому что нужно обслуживать более мощную онлайн-нагрузку.

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

В этой статье пойдет речь о том, в чем причина увеличения транзакций, и какую проблему нашли специалисты Data Egret после переезда базы данных. 

В первую очередь в компании обратились к данным мониторинга:

• Среднее время выполнения запросов уменьшилось на 10 мс по сравнению с предыдущим оборудованием и предыдущей нагрузкой;

• Сетевой трафик почти не изменился;

• Количество запросов стало больше. Использование ресурсов трудно оценить, потому что изменилось оборудование, и однозначной оценки, больше или меньше ресурсов используется, в такой ситуации дать сложно;

• Не получилось оценить и изменение параметров сервера. 

Вроде бы, все хорошо. Но проблема осталась не решенной. 

Так как речь идет о базе данных, нужно было посмотреть, что изменилось с профилем нагрузки на БД, и что случилось с запросами. Мониторинг результатов не дал. Но есть и другие инструменты. 

Например, pg_stat_statements. 

В  Data Egret этот инструмент используется постоянно, так как в нем есть три приятных бонуса:

1. Отчеты за прошлые периоды обновляются каждые сутки;

2. pg_stat_statements логирует абсолютно все, в том числе, частые запросы. В отличие от pgBadger, который зависит от настроек;

3. Можно оценить влияние запросов на серверные ресурсы и соответственно на базу данных, потому что БД использует серверные ресурсы (дисковая память и процессорное время).

Что же удалось обнаружить в pg_stat_statements?

До того, как в компании начала расти нагрузка, стандартный отчет, который формируется на основании pg_stat_statements, выглядел так:

Есть общая нагрузка по количеству запросов, которая прилетела в база данных за сутки. Здесь это total queries: 3,555,539,206 (unique: 2,268).

Есть специальная позиция other, в которую группируются запросы, не дающие существенную нагрузку на БД: calls: 1,977,858,485 (43.42%) avg_time: 0.06ms (IO: 33.3%).

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

Все остальные запросы в отчете выглядят примерно так: SELECT field1, field2 FROM table1 WHERE field3 = ? and field4 between ? and ?

Они несложные: какая-то выборка по простым условиям, иногда 1-2 join’а — ничего сверхъестественного, что могло бы вредить базе данных и требует нашего разбирательства.

После того, как вырос онлайн, отчет изменился:

Что изменилось после начала самоизоляции

• Время на запросы уменьшилось

В отчетах есть общее время, за которое база данных потратила больше ресурсов на выполнение запросов. В старом на это ушло 90 часов, в новом — 60. 

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

• Количество запросов выросло

Общее количество запросов, которые прилетели в базу данных, стало существенно больше (примерно в 1,5 раза). Это видно на графиках.

• Отсутствие пропорций

Если сравнивать позицию по запросам, которые не оказывают существенного влияния на БД, то тут рост не такой пропорциональный:

Казалось бы, должно быть 3 млрд запросов, но на самом деле рост всего несколько процентов. Значит, что-то изменилось в нагрузке на базу данных, и нужно смотреть отчет дальше.

Смотрим вглубь

Просматривая отчет, мы долистали до 17 позиции и увидели запрос, который вызывается 1,5 млрд раз и выглядит как SELECT 1:

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

Казалось бы, запрос почти не тратит ресурсов, только чуть-чуть процессорного времени. Но на самом деле он может сыграть плохую роль. На время этого пинга, мы забираем коннект от базы данных и не шлем туда полезную информацию, которая может обслуживать наш бэкенд (допустим, небольшую выборку, отрисовку веб-формы и т.д).

В итоге SELECT 1, являясь стандартным пингом коннекта, и, в то же время, приводит к негативным результатам. Ведь на время этого пинга мы:

• Теряем возможность использовать это соединение для действительно полезного запроса;

• Даем  лишнюю нагрузку на CPU (серверные ресурсы БД);

• Имеем лишнюю нагрузку на сеть, потому что нам нужно пообщаться между бэкендом приложения и БД, чтобы выяснить, что произошло и доступна ли база данных. Это бестолковая трата ресурсов.

По факту произошло следующее: при переносе приложения потерялся патч на ORM, который немного срезал такие пинги.

После правок

Давайте посмотрим на график по количеству транзакций, после того, как были внесены правки в ORM:

Выглядит не очень впечатляюще. Подумаешь, стало на 20 тысяч транзакций меньше! Но с точки зрения процессорного времени на баунсерах, после выкатки патча стало гораздо лучше.

Можно отследить результат и по общей нагрузке:

До 4 апреля в приложении был не патченный ORM. После этого пика в 100 тысяч транзакций больше не было. База отдана только под полезные запросы, которые необходимо выполнять.

Какова здесь мораль? Плохой запрос не всегда кажется таким, и не сразу можно увидеть негативный эффект с точки зрения повышенной нагрузки на дисковую и процессорную систему, или на сеть. Однако он есть.

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

SELECT 1 — реальный случай. На его месте могут быть более простые запросы. Например, в ситуации, когда для отрисовки веб-формы необходимо вычитывать справочники. Не смотря на то, что они дают полезную информацию, она никогда не меняется. Желательно кэшировать ее на стороне бэкенда, а не ходить за ней в базу данных.

Маленькие запросы могут принести большие проблемы, которые  можно сразу не разглядеть. 

Мы поговорили о быстрых запросах. Теперь перейдем к мертвым.

Быстрый и Мертвый

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

План действий тот же самый:

• Изучаем мониторинг;

• Смотрим статистику в pg_stat_statements;

• Чиним;

• Говорим об обнаруженной проблеме разработчикам.

Как выглядит отчет теперь?

В самой топовой позиции дается самая большая нагрузка. Исключение — other, там аккумулируется вся оставшаяся нагрузка, которая не является топовой. Он может находиться в любой позиции отчета.

Сразу видим pos:1  total time: 02:05:26 (20.3%, CPU: 38.6%, IO: 2.0%). База данных тратит на этот запрос 38% процессорного времени. 

Допустим, мы с определенной частотой ищем в платежной системе последние транзакции, созданные по каждому платежному сервису отдельно:

select distinct on (paymentsystem), * from transactions order by createdat desc;

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

Починка будет выглядеть так:

Из маленького запроса, который работает 1 с, мы получаем большой запрос на 2 мс. Идем в комнату к разработчикам и просим их переписать запрос. Деплоим, и ситуация возвращается в привычное русло.

Отчет pg_stat_statements позволяет довольно быстро находить запросы, которые портят нам жизнь.

Инструменты

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

pgBadger

Плюсы:

• Полная информация обо всех запросах;

• Красивые картинки. 

Посмотреть на работу pgBadger можно на тестовой странице.

Минусы:

• Специальный конфиг для логов;

• Дополнительная нагрузка на диски, потому что количество пишущихся логов резко возрастает;

• Анализ запросов постфактум;

• Для pgBadger нужно большое количество места.

pg_stat_statements

Плюсы:

• Стандартное расширение PostgreSQL, идет из коробки;

Независимо от того, в какой операционной системе вы работаете, в наборе стандартных пакетов всегда найдется pg_stat_statements. Его необходимо просто установить в PostgreSQL, дополнительно подключив подгрузку библиотеки pg_stat_statements.

• Собирает информацию по всем запросам;

• Группирует одинаковые запросы;

• Можно сбрасывать статистику;

• Можно сделать свой отчет на основе pg_stat_statements.

Минусы:

• Оверхед на выполнение запроса 2-5%;

• Запросы обезличенные;

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

• Несущественные запросы вымываются;

• Почти нет мониторингов, которые умеют с ним работать;

• Не видит разницы между SELECT … и SELECT … FOR UPDATE;

• В сыром виде данные неудобны для восприятия.

В мониторинге картинка по одному запросу выглядит следующим образом:

Такие картинки можно собирать по всем запросам, которые зафиксированы в pg_stat_statements, а потом смотреть в динамике, сколько времени тратится на выполнение того или иного запроса, какие ресурсы он потребляет, как часто вызывается.

Типичные проблемы

Какие же проблемные запросы можно встретить на практике?

Давайте рассмотрим самые распространенные из них. 

• Результат запроса нигде не используется;

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

• Неоптимально работающий запрос;

Например, distinct. 

• Постоянное обращение к справочникам;

Такая ситуация может возникнуть, когда мы постоянно обращаемся к справочнику пола, где у нас всего две позиции. 

• Нехватка индексов на простеньких запросах;

Что-то задеплоили, но забыли индекс. Это можно увидеть в отчете и исправить. 

• Смешивание нагрузки OLTP и OLAP на репликах.

Эта проблема связана с общением разработчиков с бизнес-экспертами. Последним бывает трудно объяснить, что OLAP нагрузка не может выполняться на реплике, которая отстает на 3 секунды.

Если отчет выполняется 2 часа, то информация в нем уже на 2 часа устарела. Соответственно, когда одного сервера не хватает, нагрузку OLTP и OLAP нужно разделять по разным серверам.

Не путайте причины проблем с запросами и с длительными транзакциями в базе данных.

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

Выглядит это так: существуют длительные транзакции, которые длятся 30-40 минут, и в это же время есть миллисекундные всплески запросов.

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

idle in transaction — это соединение, когда приложение открыло транзакцию в БД, выполнило один запрос и ушло заниматься своими делами, забыв закрыть транзакцию. Именно это, в основном, и является первопричиной многих проблем. Как только она решается, можно заниматься тем, с чего начинается статья: искать запросы, которые мешают вам жить.

Вместо заключения

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

Конференция HighLoad++ 2020 пройдет 20 и 21 мая 2021 года. Приобрести билеты можно уже сейчас.

Хотите бесплатно получить материалы конференции мини-конференции Saint HighLoad++ 2020? Подписывайтесь на нашу рассылку.

А интересующихся миром Java ждем на онлайн-митапе Luxoft TechFest #2: Java with Ontico. На нем поговорим о приватных полях-константах в Jira, неочевидных нюансах Java Reactive Stack и работе с распределенным кешем. А после своих выступлений звезды митапа ответят на самые животрепещущие из ваших вопросов. До встречи 10 февраля в 19:00 мск.