В предыдущей статье мы познакомились с тестом 1С:ERP на 30 000 ВРМ от компании «ИТ-Экспертиза» и рассказали о первых запусках, а также о проблемах, которые пришлось решать команде Postgres Professional на старте: лишних инвалидациях и особенностях конфигурации окружения.
На этом работа над тестом не закончилась. В этой статье мы продолжим разбирать результаты последующих запусков и расскажем о проблемах, с которыми столкнулись при масштабировании нагрузки до 21 000 ВРМ, а также о том, какие решения помогли их устранить.
Проблема с PgStatsHash
Один из последующих запусков теста упал при переходе от 16 800 на 21 000 ВРМ, в начале пятого часа выполнения:
Ожидания, собранные с помощью расширения pg_wait_sampling, показали, что в течение последнего часа теста наблюдался резкий рост количества ожиданий типа LWLock:PgStatsHash и LWLock:PgStatsDSA, связанных со сбором статистики:
Мы предположили, что рост этих ожиданий связан с большим количеством операций создания и удаления временных таблиц, поскольку включение in-memory temp catalog (о нём рассказывали ранее) снижает накладные расходы на работу с временными таблицами, поэтому при таком профиле нагрузки количество операций с ними оказывается достаточно большим, чтобы заметно повлиять на сбор статистики.
Помимо роста количества ожиданий LWLock:PgStats*, ещё одним неприятным моментом стал рост потребления памяти в DSA (Dynamic Shared Area). При создании таблицы в DSA создаётся запись для хранения статистики по relation (например, количество сканов). При большом количестве операций с временными таблицами количество таких записей постоянно увеличивается, что приводит к постепенному росту потребления DSA. И при этом рост потребления памяти не отображается в RES отдельных PostgreSQL-процессов, поскольку память выделяется в общей DSA.
По мере увеличения количества записей в PgStatsHash растёт конкуренция между backend-процессами за соответствующий LWLock. В результате к концу теста наблюдается массовый переход backend-процессов в состояние ожидания LWLock:PgStatsHash.
Для проверки данной гипотезы был разработан патч, исключающий временные таблицы из сбора статистики для relation:
в pgstat_init_relation() для TEMP relations был отключен pgstat, после чего дальнейшая инициализация статистики не выполнялась:
if (rel->rd_rel->relpersistence == RELPERSISTENCE_TEMP) { rel->pgstat_enabled = false; rel->pgstat_info = NULL; return; }
в pgstat_create_relation() было отключено создание статистики для временных таблиц
Как показали дальнейшие тесты, патч проявил себя хорошо: утилизация CPU на последнем часе теста выровнялась, а события ожидания LWLock:PgStatsHash и LWLock:PgStatsDSA полностью исчезли:
Таким образом, операции с временными таблицами больше не приводили к созданию соответствующих записей статистики в PgStatsHash и их размещению в DSA.
Сломался план запроса во время теста
Ещё одна проблема, с которой мы столкнулись на запусках тестов с 21 000 ВРМ, выглядела следующим образом: в течение третьего часа характер нагрузки менялся и, несмотря на то что утилизация CPU оставалась на уровне ~80%, начинался резкий рост load average:
Присутствовал и рост остальных метрик:
Обратив внимание на статистику по использованию таблиц и индексов из представления pg_stat_database, мы заметили аномальный рост значения tup_returned — количества «живых» строк, выбранных при последовательном сканировании таблиц (это не количество строк, возвращённых клиенту):
Тогда у нас возникло предположение, что в некоторых запросах слетел план выполнения. Ещё одним косвенным подтверждением этого служит следующий импровизированный график, показывающий отношение количества строк, прочитанных из таблиц (tup_returned), к количеству блоков, найденных в общем и локальных кешах (blks_hit):
До возникновения проблемы мы в среднем получали около двух tuples на блок. После возникновения проблемы значение метрики выросло примерно до 8. Иными словами, на каждый найденный в кеше блок стало приходиться значительно больше возвращённых строк. Такое изменение могло быть косвенным признаком того, что запросы стали обрабатывать существенно больше строк.
При перезапуске теста со сбором ежеминутной статистики из pg_stat_statements и включением auto_explain каждые 10 минут на 30 секунд удалось локализовать один из проблемных запросов, для которого происходит переключение плана, что приводило к резкому замедлению. В изначальном плане время работы меньше секунды:
Переключение на Sequential Scan в Nested Loop, вызванное неверной оценкой количества строк на входе, приводило к тому что время исполнения запроса возрастало до 10 секунд:
Что ещё хуже, у данного запроса был ещё один план выполнения, с которым запрос выполнялся ещё медленнее:
Помимо уже имеющегося Nested Loop (-> Seq Scan t217), в этом плане возникает Merge Join по неудачному набору колонок. В результате формируется большое количество промежуточных комбинаций строк, значительная часть которых затем отбрасывается Join Filter. В частности, в плане видно более 92 млн строк, отброшенных на этом этапе (Rows Removed by Join Filter: 92128861), а Seq Scan по t217 выполняется 12 522 раза. Это приводит к резкому увеличению объёма работы и времени выполнения запроса.
В качестве workaround для решения этой проблемы мы решили изменить ряд параметров:
enable_mergejoin = off (по умолчанию = on);
cpu_tuple_cost= 0.1 (по умолчанию = 0.01).
При сравнении планов проблемного запроса до и после изменения настроек можно заметить, что теперь для проблемного запроса выбирается другой план: вместо Merge Join используется Hash Join, а Seq Scan по t217, выполнявшийся 12 522 раза, заменяется на Index Scan. В результате время выполнения запроса снижается с 32,6 до 2,5 секунды.
График характеристики tup_returned / blks_hit из pg_stat_database (снятой поминутно во время обоих замеров) подтверждает, что после 235-й минуты замера 1 эта характеристика (для всей базы) увеличилась с 2 до 6, тогда как в замере 2 (с применёнными настройками) эта характеристика не поменялась:
Попутно нашелся ещё один класс запросов с похожим шаблоном: Nested Loop + Seq Scan, который также улучшился после применения настроек.
Bottleneck в сетевой карте сервера приложения 1С
При увеличении нагрузки проявилась ещё одна проблема: спустя несколько часов теста загрузка CPU сервера базы данных начинала идти «пилой», но при этом каких-либо явных ошибок в логах не наблюдалось:
Для поиска причины мы использовали уже ставший классическим подход USE (Utilization, Saturation, Errors) Брендана Грегга, последовательно проверяя степень загрузки и наличие ошибок на основных серверах окружения. Явного насыщения CPU или дисковой подсистемы базы данных обнаружено не было, зато дальнейший анализ показал, что на одном из серверов приложений 1С, были характерные «полки» на графике исходящего трафика:
В эти же моменты фиксировался рост числа ретрансмиссий TCP-сегментов:
Дальнейшая проверка сетевого интерфейса показала, что сервер приложений был подключен к сети через интерфейс с пропускной способностью всего 1 Гбит/с:
ethtool eno1 Speed: 1000Mb/s
При росте нагрузки пропускная способность этого интерфейса становилась бутылочным горлышком, что и приводило к задержкам при передаче данных между сервером приложений и базой данных и, как следствие, к неравномерному поступлению нагрузки на базу данных. После замены сетевой карты на 10-гигабитную проблема ушла.
Этот случай ещё раз показал, как важно при масштабировании нагрузки учитывать особенности всех элементов инфраструктуры. Поскольку наше оборудование — это не какое-то топовое железо, специально собранное под задачу, а типовые рабочие серверы, «надёрганные» из нашей лаборатории, некоторые различия в них всё же имелись. Так что фиксируем: приведение конфигурации серверов и их компонентов к единому знаменателю до начала масштабного тестирования — это хорошая практика, которая поможет избежать неожиданных просадок производительности при нагрузке.
Проблема с большим количеством созданий файлов для временных таблиц
В ходе своей работы 1С создает довольно много временных таблиц, но, несмотря на то что эти таблицы являются временными, для них всё равно создаются файлы в файловой системе. По умолчанию, если данные временной таблицы помещаются в local buffers и их не требуется сбрасывать на диск, всё равно создается пустой файл relation, а если в таблице есть текстовое поле — дополнительно еще создается пустой 8 КБ файл для TOAST. Для индексов временных таблиц также создается отдельный одностраничный файл размером 8 КБ, заполненный нулями.
Эти файлы никак не участвуют в работе, пока в них не потребуется записать данные. Если за всё время работы сессии этого не произошло, файлы закрываются и удаляются.
Под большой нагрузкой даже такая, казалось бы, простая операция становится заметной: 30 тысяч сессий по 100+ таблиц одновременно — это до 3 миллионов файлов в каталоге, которые постоянно создаются и удаляются, что создаёт заметную нагрузку на файловую систему и замедляет работу СУБД.
В качестве решения нами был реализован подход, при котором файлы временных таблиц и их индексов не создавались на диске до тех пор, пока не произойдёт первая реальная запись в них, например при вытеснении буферов таблицы или индекса из local buffers.
Проблема замедления части бизнес-операций
В ходе дальнейших запусков мы обратили внимание, что на поминутном графике, отражающем число выполненных бизнес-операций и их APDEX, начиная примерно с четвёртого часа работы появляется характерная «пила». При этом со временем зубья становятся всё выше и появляются всё реже.
Аналогичная картина наблюдалась и в Grafana: периодически возникали всплески нагрузки как на серверах базы данных и 1С, так и по сетевой активности. По времени и характеру нагрузки была видна корреляция с утилизацией на серверах приложений.
При анализе отдельных операций удалось выделить два шага, поведение которых существенно отличалось от остальных:
Отчет.ВедомостьПоОС2_4.ВедомостьПоОС.Формирование;
Отчет.ВедомостьПоТоварамНаСкладах.ВедомостьПоТоварамНаСкладах.Формирование.
В начале теста среднее время их выполнения составляло порядка 4–5 секунд, однако примерно с середины теста оно начинало постепенно увеличиваться и в итоге достигало примерно 800 секунд:
Мы взяли операцию 'Отчет.ВедомостьПоОС2_4.ВедомостьПоОС.Формирование', и построили ещё два графика: по количеству операций в минуту с группировкой по времени окончания операции и по времени старта. График с группировкой по времени старта показывает, что старт операций на протяжении всего теста происходил достаточно равномерно и в ожидаемом объёме, что позволяет исключить проблему с генерацией нагрузки:
Похоже, что большое количество шагов одновременно упирается в некоторую точку синхронизации, после чего через несколько минут «отпускается» и генерирует большой поток завершений.
Первоначально мы проверили, не связана ли проблема с перегрузкой или блокировками в базе данных. Однако, по данным pg_stat_activity, не наблюдалось массовых блокировок или других ожиданий, которые бы систематически росли вместе с продолжительностью теста. Более 90% сессий большую часть времени находились в состоянии работы на CPU.
А вот анализ технологического журнала 1С показал явную корреляцию между проблемными шагами и работой механизма BackgroundJob. Поминутная статистика операций Start, Attach и Finish на разных серверах практически полностью совпадала с графиками зависаний: в определённые моменты обработка фоновых заданий одновременно замирала на несколько минут, после чего накопившиеся операции массово продолжали выполняться.
При обсуждении результатов с коллегами из «ИТ-Экспертиза» мы получили рекомендацию вынести клиентскую нагрузку с основной ноды кластера, поскольку основной сервер выполняет дополнительную административную работу, которая может конкурировать за ресурсы с клиентскими сеансами. Мы сравнили нагрузку на процессы rmngr на всех трёх серверах приложений 1С и действительно увидели существенную разницу: по данным atop, на основном сервере 1С потребление CPU в периоды зависаний составляло от 800 до 2000%, тогда как на остальных нодах было в несколько раз ниже.
Поскольку утилизация серверов приложений 1С уже и так была довольно высока, мы решили перевести их с bare-metal на виртуальные машины и заодно увеличить их количество. Переход к виртуализации позволял нам разместить на тех же мощностях в два раз больше 1С серверов — по одному серверу 1С на каждую NUMA-ноду. Кроме того, для запуска тестов мы выделили ещё один bare-metal-сервер, в результате чего получили 8 серверов приложений 1С.
После добавления новых серверов и реконфигурации кластера, клиентская нагрузка была убрана с основного сервера 1С. В последующих замерах проблема больше не воспроизводилась.
После применения всех патчей, описанных в данной статье, при нагрузке в 21 000 ВРМ нам удалось получить APDEX = 0.975.
