От экспертов «1С-Рарус»: База «1С» растёт и всё тормозит. Что делать?

Большое предприятие общественного питания ведет свою деятельность в «1С:Общепит. Модуль для 1С:ERP и 1С:КА2». Через полгода эксплуатации стали поступать жалобы от пользователей об общем замедлении работы системы. При этом замедление наблюдалось буквально во всем: открытие форм списка, формирование отчетов, проведение документов и так далее.

Компания представляет собой группу организаций общим числом более 100. Организации разнесены по базам и на разные физические серверы, чтобы сбалансировать рабочую нагрузку: количество проведенных документов, формирование отчетов в единицу времени. Приблизительно по 20 организаций на базу. Базы начали свою работу в разное время, поэтому размеры баз разные.

Заметили, что существует тенденция к снижению производительности у баз большего размера. В качестве метода решения проблемы применялось увеличение лимита использования оперативной памяти MS SQL. Это улучшало ситуацию с производительностью.

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

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

Параметры и размеры баз

Общие параметры

• Клиентская база «1С:Общепит. Модуль для 1С:ERP и 1С:КА2» в клиент-серверном режиме, на которой воспроизводится проблемная ситуация.
• Операционная система: Windows Server 2012 R2.
• База данных: Microsoft SQL Server 2017 64х.

База без замедления

• Размер базы 30 Gb.
• Выделенная память для MS SQL 64 Gb.

База с замедлением

• Размер базы 200 Gb.
• Выделенная память для MS SQL 64 Gb.

Увеличение выделенной памяти для MS SQL до 96 Gb снимало проблему замедления работы.

Ищем проблему в MS SQL

Для начала посмотрим на ситуацию в реальном времени. Для этого во время возникновения проблем в системе откроем Activity Monitor. Взглянув на исполняющиеся в системе запросы, фиксируем наличие задержек вида PAGEIOLATCH:

Назначение PAGEIOLATCH в организации ожидания, пока страница данных загрузится с диска в буферный кэш сервера.

Стоит понимать — само по себе наличие таких блокировок в системе совершенно нормально и необходимо для штатной работы MS SQL Server. Однако, большое их количество приводит к существенному снижению производительности и увеличенной нагрузке на дисковую подсистему сервера, что и происходит в нашем конкретном случае.

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

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

Собираем данные о событиях в MS SQL, технологическом журнале «1С» и счетчиках производительности Windows

Выполним настройку механизма расширенных событий (extended events) MS SQL Server для отслеживания выполняющихся в системе запросов и параметров их выполнения.

Выберем информацию о выполняющихся в системе запросах, длительность которых более 1 секунды, которые выполняют более 100 логических чтений. Это обычная рекомендация для начала расследования, связанного с PAGEIOLATCH.

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

• rpc_completed
• batch_completed
• query_post_compilation_showplan

На закладке Global Fields для каждого события выбираем колонку sql_text, а на закладке Filter устанавливаем фильтры по:

• database_id = <id исследуемой базы>
• logical_reads > 100
• duration > 1000

Внешний вид настройки лога расширенных событий:

Для того, чтобы результаты работы extended events сохранить в файл для дальнейшего анализа на закладке Data Storage добавим тип event file.

Сохранять именно в файл критически важно, так как в режиме Watch Live Data далеко не все события попадают в анализ. Выберем место, куда система сохранит файл в формате xel, который затем можно будет прочитать в MS SQL Management Studio:

Также для того, чтобы получить контекст 1С выполняемых в MS SQL запросов настроим технологический журнал с событиями DBMSSQL и SDBL длительностью более 1 секунды:

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
	<log history="72" location="e:\chesdm\temp\Logs\">
		<property name="all"/>
		<event>
			<eq property="name" value="DBMSSQL"/> 
			<eq property="p:processName" value="ka"/>
			<gt property="duration" value="1000000"/>
		</event>
		<event>
			<eq property="name" value="SDBL"/> 
			<eq property="p:processName" value="ka"/>
			<gt property="duration" value="1000000"/>
		</event>
	</log>
</config>

И напоследок, настроим счетчики производительности Windows, чтобы отследить состояние буферного кэша, а также нагрузку на дисковую подсистему. Системные счетчики для отслеживания интенсивности работы с оперативной памятью и диском:

• Memory\ Available Mbytes.
• Memory\Pages/sec.
• Physical Disk\ Avg. Disk Queue Length.
• Physical Disk\ Avg. Disk sec transfer.

Счетчики MS SQL Server для отслеживания работы с буферным кэшем:

• Buffer manager\Page life expectancy.
• Buffer manager\Buffer cache hit ratio.
• Plan Cache\Plan cache hit ratio.
• Buffer Manager\Page reads/sec. 
• Buffer Manager\Page writes/sec.
• Buffer Manager\Lazy writes/sec.

Внешний вид настройки счетчиков производительности Windows:

Воспроизводим проблему и анализируем

Для того, чтобы воспроизвести ситуацию, уменьшаем количество доступной оперативной памяти MS SQL Server до исходных значений (когда воспроизводились PAGEIOLATCH и наблюдалось общее замедление работы системы) и включаем настроенные счетчики.

После сбора результатов, анализируем полученные замеры. Прежде всего откроем счетчики производительности Windows и взглянем на счетчик «Ожидаемый срок хранения страницы» (Page life expectancy).

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

Что мы видим в нашем случае:

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

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

Перейдем к более детальному анализу, откроем лог расширенных событий и сохраним его в таблицу для более детального анализа.

Для этого в MS SQL Management Studio необходимо открыть файл лога и экспортировать его при помощи команды Extended Events -> Export to -> Table, после чего выбрать базу данных и имя таблицы, в которую будут экспортированы данные:

В итоге получим таблицу следующей структуры:

Выполним несложный запрос, чтобы выбрать запросы с самым большим количеством логических чтений:

SELECT TOP (100) *
  FROM [chesdm_extended_events].[dbo].[logical_reads_1]
  ORDER BY [logical_reads] DESC

Начнем с самой верхней строки. Имеем запрос, выполнение которого произвело более 17 млн. логических чтений:

Текст запроса можно получить напрямую из поля sql_text данной таблицы или путем установки фильтра по точному времени выполнения запроса в открытом файле лога расширенных событий:

Далее по времени выполнения и тексту запроса находим соответствующее событие в логе технологического журнала по событию DBMSSQL. Контекст выполнения запроса выглядит следующим образом:

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

Находим потенциальную причину замедления работы «1С»

Переходим к анализу текста запроса SQL и обнаруживаем среди прочих используемых таблиц выборку данных из физической таблицы регистра накопления _AccumRg62208 с отбором по периоду, что соответствует регистру «Товары организаций».

Посмотреть значение параметров @P6 и @P7 в собранном extended events можно в поле statement, они равны 2019-06-01 23:59:59 и 3999-11-01 00:00:00 соответственно.

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

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

После того, как в базе были пересчитаны итоги, производим повторный сбор счетчиков во время интенсивной работы пользователей и повторяем анализ. Видим небольшое улучшение на графике счетчика page life expectancy, среднее время 136 секунд является все еще довольно низкий показателем:

Ищем дополнительные возможности ускорения «1С»

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

Обращаем внимание на то, что помимо большого количества чтений (более 25 млн.) также количество строк, возвращаемых запросом более 500 тыс. Выясняем контекст данного запроса по сопоставлению его текста с логами технологического журнала:

По контексту становится понятно, что речь идет о формировании отчета. Анализируем текст SQL запроса и делаем вывод, что происходит выборка из физической таблицы регистра накопления _AccumRg62196, что соответствует регистру «Товары на складах» за период с 23.12.2018 по 29.01.2020. Период формирования отчета узнали аналогично, по параметрам SQL запроса.

Также по логу технологического журнала можем выяснить пользователя, который сформировал отчет:

Делаем предположение о том, что отчет использует физическую таблицу регистра из-за того, что формируется с детализацией до регистратора, да еще и за очень большой период, не требующийся по бизнес-процессу предприятия. Передаем информацию клиенту и подтверждаем нашу догадку.

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

Клиенту рекомендовано уменьшить период формирования отчетов в системе для снижения нагрузки на буферный кэш и уменьшения количество обращений MS SQL Server к дисковой подсистеме для загрузки данных.

Неоптимальные бизнес-процессы могут приводить к замедлению работы баз «1С»

В данной статье были рассмотрены подходы к выяснения причин блокировок вида PAGEIOLATCH в MS SQL, приводящих к общей деградации производительности информационных систем «1С» на примере проблемы, с которой столкнулись пользователи решения «1С:Общепит. Модуль для 1С:ERP и 1С:КА2».

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

Помимо обслуживания базы и пересчета итогов необходимо прорабатывать бизнес-процессы на предприятии. В частности, не допускать запросов, которые будут выбирать слишком большой пул данных за одно обращение к СУБД. Большой пул данных — это не абсолютное понятие, оно зависит от размеров базы и конфигурации сервера и требует предварительного анализа.

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

Если вам интересна тема блокировок в MS SQL Server при работе «1С:Предприятия», то рекомендуем нашу предыдущую статью «Страничные блокировки в MS SQL Server при проведении документа в документе в «1С»».