От экспертов «1С-Рарус»: Событийный мониторинг производительности кластера 1С в ГК «Ижевский радиозавод»

«Ижевский радиозавод» использует в работе программный продукт «1С:ERP Управление предприятием 2» (релиз 2.5.8.420 на момент расследования). Объем учетных операций достаточно большой — один только справочник «Номенклатура» (продукция, полуфабрикаты, материалы, покупные комплектующие изделия) состоит из более чем 1,5 млн позиций.

Для отслеживания производительности кластера 1С применяется общесистемный мониторинг. Плюс дополнительно на момент написания статьи уже более полугода используется «1С-Рарус: Мониторинг производительности» для событийного мониторинга. В статье мы расскажем о принципах работы «Мониторинга производительности» и двух примерах расследования инцидентов снижения производительности и оптимизации.

Описание окружения

Кластер 1С ГК состоит из трех рабочих серверов, все являются центральными. Каждый рабочий сервер имеет следующие параметры:

• Intel Xeon Gold 6248R 3.00 ГГц (44 ядра);
• 288 ГБ ОЗУ.

Релиз платформы 8.3.22.1923.

Сервер СУБД на базе Microsoft SQL 2019:

• Intel Xeon Gold 6248R 3.00 ГГц (44 ядра);
• 812 ГБ ОЗУ.

Это характеристики виртуальных серверов. Используется виртуализация VMWare vSphere Client version 7.0.1.00200.

Для общесистемного мониторинга используется Zabbix.

На серверах СУБД и 1С используется ОС Windows.

Количество действительных активных пользователей 380, сеансов в среднем — 800, при общем количестве действительных пользователей в справочнике более 5 000.

Объем базы больше 3 ТБ.

Общесистемный мониторинг

На заводе развернута мощная система общесистемного мониторинга.

Через PowerShell и v83.ComConnector происходит подключение Zabbix — получаются некоторые метрики со стороны 1С, в основном связанные с устойчивостью работы кластера. То же происходит и со счетчиками производительности со стороны СУБД. Графики позволяют отслеживать снижение производительности и своевременно реагировать на изменение ситуации.

На продуктивной базе 1С отключена отладка и это правильно, так как функционирование с включенным режимом отладки может давать серьезную просадку производительности. До внедрения специализированного пособытийного мониторинга производительности кластера сбор логов Технологического журнала (ТЖ) производился ситуационно по настройке «6.14.6.4. Действия администратора и ошибки» (its.1c.ru/db/v8323doc/bookmark/adm/TI000000157).

При расследования инцидентов со снижением производительности настройки ТЖ дополнялись необходимыми событиями и проводился разбор.

Дополнение общесистемного мониторинга специальным мониторингом производительности

Ситуационный сбор логов ТЖ в некоторых случаях мог приводить к серьезному увеличению времени разбора, а с учетом того, что некоторые инциденты возникали повторно, специалистами компании «1С-Рарус» было предложено развернуть «1С-Рарус: Мониторинг производительности».

Систему мониторинга можно представить двумя блоками:

1. Блок логирования — здесь осуществляется сбор логов ТЖ, передача через брокер сообщения в модуль обработки, парсинг, и загрузка в ClickHouse.
2. Блок вывода данных — модуль настройки диаграммного отображения информации из базы ClickHouse, с возможностью расшифровки детальных записей.

Блок логирования

Процесс сбора и обработки логов ТЖ происходит по алгоритму:

• Сбор логов ТЖ на стороне кластера 1С.
• Чтение этих логов по расписанию для получения только новых событий в логах с момента прошлого считывания.
• Упаковка собранных логов в архивы и передача их в брокер сообщений (мы используем RabbitMQ).
• Распаковка архивов из брокера и парсинг логов, который включает в себя:
  • Перевод логов в однострочное представление.
  • Нормализацию текстов запросов к СУБД, а именно:
    • удаление имен временных таблиц;
    • удаление значений параметров.
  • Преобразование данных в формат csv.
• Загрузка файла csv в базу ClickHouse.

Для реализации алгоритма сбора и отправки логов в брокер сообщений запускается специальный скрипт на языке Python по расписанию на стороне кластера 1С.

Алгоритм обработки логов реализуется с помощью сценария, шаги которого на стороне сервера парсинга логов по расписанию запускают специальные скрипты на языке Python.

Блок вывода данных

Далее данные из базы ClickHouse, по собранным и обработанным логам, в системе мониторинга выводятся в виде диаграмм и их расшифровок:

Также анализ собранных и обработанных логов можно выполнять с помощью встроенного в решение веб-интерфейса Tabix, который позволяет работать с данными с помощью sql-подобных запросов:

Настройка 1С-Рарус: Мониторинг производительности на ГК «Ижевский радиозавод»

Поскольку Мониторинг работает на постоянной основе, то возникает задача не переполнить диск, на котором располагается база ClickHouse. TTL (Time to live) таблицы в ClickHouse равен трем дням:

В настоящий момент максимально в базе ClickHouse хранится до 1,1 млрд записей. В течении рабочего дня в среднем из логов ТЖ загружается 350 млн записей.

Настройки ТЖ:

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log history="1" location="T:\TJ_1C">
	<event>
		<eq value="CALL" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="SCALL" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="ATTN" property="Name"/>
	</event>
	<event>
		<eq value="EXCP" property="Name"/>
	</event>
	<event>
		<eq value="EXCPCNTX" property="Name"/>
	</event>
	<event>
		<eq value="TLOCK" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="TDEADLOCK" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="TTIMEOUT" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="DBMSSQL" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="DBDA" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="SDBL" property="Name"/>
		<eq value="ERP" property="p:processName"/>
	</event>
	<event>
		<eq value="SESN" property="Name"/>
	</event>
	<event>
		<eq value="DBCOPIES" property="Name"/>
	</event>	
	<event>
		<eq value="CONN" property="Name"/>
	</event>	
	<event>
		<eq value="VRSREQUEST" property="Name"/>
	</event>
	<event>
		<eq value="VRSRESPONSE" property="Name"/>
	</event>
	<event>
		<eq value="CLSTR" property="Name"/>
	</event>	
	<property name="all"/>
</log>
</config>
 

Логи ТЖ приходят с трех серверов. Для разведения процессов парсинга, форматирования и упаковки данных в пакет, чтобы успевало обрабатываться, на одном сервере установлен интервал 3 минуты, на двух оставшихся 4 минуты. Выполнение полного экспорта пакета выполняется от 30 до 54 секунд. Небольшие пакеты пролетают и за 16 секунд. Разброс в пакетах довольно большой — в среднем от 500 МБ до 1,2 ГБ. Бывают и по 1,5 ГБ, и менее 300 МБ.

Большой объем записей требует ресурсов, поэтому на виртуальной машине обработки логов ТЖ пришлось увеличить память с 8 Гб до 32 Гб, количество ядер процессора увеличить до 8.

Также помимо увеличения аппаратных мощностей возникла необходимость ускорить обработку логов ТЖ. «1С-Рарус: Мониторинг производительности» позволяет сделать это создавая вспомогательные окружения. Сценарий для каждого окружения может выполняться в своем потоке.

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

Пример #1: Расследование увеличения времени расчета себестоимости с помощью «1С-Рарус: Мониторинг производистельности»

Анализ ситуации

Длительность очередного расчета себестоимости в какой-то момент увеличилась более, чем на 5 часов — в среднем расчет был 5–6 часов, а стал 10–11 часов.

Анализ протокола расчета выявил длительные шаги этапа «91. Партионный учет: ЗаписатьСформированныеДвижения».

Как подробно читать протокол расчета себестоимости можно узнать из статьи От экспертов «1С‑Рарус»: Выявляем причины долгого «Закрытия месяца» в 1С:ERP и ускоряем выполнение операции.

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

В текущем расчете шаги суммарно выполняются ~ 5 часов:

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

Расследование

На момент начала расследования уже был включен мониторинг потребления памяти в tempdb для операций синхронного обмена 1C:ERP и внешней производственной системы не на платформе 1С.

Анализ использования tempdb во время текущего расчета выявил большое потребление памяти при выполнении исследуемых запросов — в пиках 450 ГБ и 200 ГБ:

При расчете же в предыдущем периоде анализ использования tempdb не выявил больших потреблений памяти:

В статье От экспертов «1С‑Рарус»: Анализ потребления таблиц временных данных в MS SQL для 1С, отличия от pg_temp в PostgreSQL можно ознакомиться с более детальными способами мониторинга tempdb.

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

Для выявления подобных запросов в Мониторинге нужно смотреть диаграмму по событию DBMSSQL:

По клику на столбце система покажет отсортированные по длительности события ТЖ:

По контексту подтвердилось обнаруженное при помощи протокола расчета себестоимости место в коде:

ОбщийМодуль.ЗакрытиеМесяцаСервер.Модуль : 3753 : 
Обработки.ОперацииЗакрытияМесяца.ВыполнитьРасчетЭтапов(ПараметрыЗапуска); 
Обработка.ОперацииЗакрытияМесяца.МодульМенеджера : 2021 : 
ОбщегоНазначения.ВыполнитьМетодКонфигурации( 
ОбщийМодуль.ОбщегоНазначения.Модуль : 5359 : Выполнить ИмяМетода + "(" + 
ПараметрыСтрока + ")"; : 1 : 
РасчетСебестоимостиКорректировкаСтоимости.Выполнить_РасчетПартийИСебестоимости(Параметры[0]) 
ОбщийМодуль.РасчетСебестоимостиКорректировкаСтоимости.Модуль : 474 : 
РасчетСебестоимости.РассчитатьВсеВПопыткеИсключении(ПараметрыЗапуска); 
ОбщийМодуль.РасчетСебестоимости.Модуль : 534 : РассчитатьВсе(ПараметрыЗапуска, 
ПараметрыРасчета, ПараметрыОтладки);
ОбщийМодуль.РасчетСебестоимости.Модуль : 413 :  
РасчетСебестоимостиПрикладныеАлгоритмы.ЗаписатьСформированныеДвижения( 
ОбщийМодуль.РасчетСебестоимостиПрикладныеАлгоритмы.Модуль : 10731 : 
НачалоЗаписиДвижений(ПараметрыРасчета); 
ОбщийМодуль.РасчетСебестоимостиПрикладныеАлгоритмы.Модуль : 11811 : 
Запрос.Выполнить();

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

Из протокола расчета себестоимости видим, что длительными шагами оказались запросы выборки из регистров сведений «Детализация себестоимости партии товаров» и «Детализация себестоимости партии товаров постатейные затраты» в соединении с регистром накопления «Себестоимость товаров».

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

Получение плана запроса

Запрос 1С получилось воспроизвести с выявленными параметрами. Рассказ о воспроизведении запроса заслуживает отдельного описания, но выходит за рамки предлагаемой статьи.

Повторное выполнение в Консоли запросов 1С дало возможность увидеть план запроса через Activity Monitor. Заметим, что есть разные подходы к получению планов запросов и предлагаемый здесь не является единственно возможным:

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

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

Как исправили

Запрос в коде формируется по шаблону:

Структура регистра накопления «Себестоимость товаров»:

Структура регистра сведений «Детализация себестоимости партии товаров»:

Основная идея ускорения — свернуть сперва записи из регистра накопления «Себестоимость товаров» до полей соединения с суммированием количества. А уже потом соединяться с регистром сведений «Детализация себестоимости партии товаров». То же самое следует проделать с регистром сведений «Детализация себестоимости партии товаров постатейные затраты».

В итоге работа запросов даже ускорилась — с 44 минут до 18:

Пример #2: Расследуем потерю данных из‑за таймаутов с помощью «1С‑Рарус: Мониторинг производительности»

Анализ ситуации

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

В протоколе расчета себестоимости зафиксировано:

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

Расследование

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

Поскольку мы предполагаем, что потеря данных происходит из-за блокировки, то задача состоит в том, чтобы найти её и расследовать причины её возникновения. К счастью, повторять закрытие месяца нам не надо, поскольку Мониторинг осуществляет непрерывное логирование событий Технологического журнала и позволяет проводить удобный постфактумный анализ.

Запускаем базу «1С-Рарус: Мониторинг производительности». Открываем Мониторинг → Доска диаграмм, выбираем доску «Универсальный мониторинг ИРЗ». База Мониторинга дает возможность следить за многими кластерами, поэтому в нижнем левом углу уточняем Сценарий — Анализ технологического журнала (Диаграммы мониторинга) и Окружение — ERP_диаграммы. Выбираем страницу «Блокировки и ожидания». Находим временной интервал с нашими блокировками. Можно кликнуть по столбцу диаграммы и посмотреть детализацию:

В открывшейся таблице находим интересующую нас строку с блокировкой. Теперь необходимо найти виновника. В шапке таблицы выбираем в поле «Шаг обработки текущей строки» значение «Виновник блокировки», жмём «Обработать»:

В открывшемся окне находим строку с типом события «Виновник». Если у поля нет заполненного значения поля WaitConnections — значит это наш виновник.

В поле WaitConnections указывается номер t_connectid.

t_connectid — идентификатор соединения, не изменяющегося в пределах транзакции, ожидание которого имело место при попытке установки управляемой блокировки.

Если же оно заполнено, то надо повторить для соединения в поле WaitConnections предыдущие действия. Ищем блокировки с обнаруженным t_connectid. Запускаем шаг обработки «Виновник блокировки». Анализируем жертву и виновника:

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

В нашем случае фоновые задания падают с таймаутом ожидания выполнения кода в модуле:

РасчетСебестоимостиПрикладныеАлгоритмы.ВернутьСостояниеИтоговРегистров

В момент выполнения строки:

МенеджерРегистра.УстановитьМинимальныйИМаксимальныйПериодыРассчитанныхИтогов(СостояниеРегистра.МинимальныйПериод, СостояниеРегистра.МаксимальныйПериод)

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

Логика возникновения блокировок

Расчет себестоимости в момент записи движений отключает использование итогов для регистров накопления. Это распространяется на весь регистр без отбора по организации.

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

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

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

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

Настройка размера порции записи в параметрах операций закрытия месяца:

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

Каскадный случай блокировок на ожиданиях

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

Рассмотрим протокол расчета себестоимости с ошибкой конфликта блокировок:

Найдем в журнале регистрации сеанс расчета по дате фиксации протокола расчета:

В Мониторинге производительности воспользуемся расшифровкой событий TTIMEOUT и найдем нужную строку с sessionid 339558:

Выбираем в поле «Шаг обработки текущей строки» значение «Виновник блокировки», жмём «Обработать». Как видим, виновник также кого-то ожидает, так как поле WaitConnections не пустое.

По набору соединений (‘420762,416754’) найти виновника не получается, поэтому ищем по конкретным значениям. Поиск по 420762 приводит к новым waitconnections, в том числе к ожиданию набора соединений, но главный виновник не определяется:

Поиск по 416754 приводит к нужному результату:

И вот обнаружен главный виновник — в поле waitconnections пусто:

Взаимосвязь размера таблицы регистра накопления Себестоимость товаров и размера периода расчёта

Метод менеджера регистра накопления

УстановитьМинимальныйИМаксимальныйПериодыРассчитанныхИтогов

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

Периодичность расчета — месяц.

В нашем случае эта операция происходит долго из-за размера таблицы регистра накопления Себестоимость товаров. На тестовой базе (менее производительной) операция заняла почти 2 часа в случае добавления следующего месяца (например, переходим с сентября на октябрь) и 4–11 минут при возврате обратно (переходим с октября на сентябрь):

Это самая большая таблица и ее размер уже больше 850 ГБ:

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

Все таблицы регистра накопления Себестоимость товаров:

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

В последних версиях платформы для каждого регистра накопления создается собственная таблица настроек хранения итогов.

Таблица настроек хранения итогов (_AccumRgOpt) с полями:

1. _RegID — идентификатор регистра.
2. _Period — периодичность хранения итогов.
3. _ActualPeriod — хранение актуальных итогов.
4. _Periodicity — периодичность регистра.
5. _RepetitionFactor — кратность.
6. _UseTotals — использовать итоги.
7. _MinPeriod — минимальный период с которого надо пересчитывать итоги.
8. _MinCalculatedPeriod — минимальный период, по которому нужно рассчитывать итоги.
9. _UseSplitter — использовать разделитель итогов (для обеспечения параллельности проведения документов).
10. _Fld<n> — общие реквизиты.

Помимо того, что блокировку показал «1С-Рарус: Мониторинг производительности», получилось увидеть ее и в ходе эксперимента на тестовой базе. В первом сеансе запустили установку периода рассчитанных итогов, во втором попытались провести документ Этап производства с записью движений регистра накопления Себестоимость товаров.

Получили попытку установки разделяемой блокировки:

И как итог получение таймаута:

Возможные подходы по исправлению и что выбрали на проекте

• Доработать функционал системы таким образом, чтобы при запущенных нескольких расчетах себестоимости работа с итогами выполнялась только при начале первого расчета и по окончании последнего. Риск такого подхода — при отключенных итогах множество запросов чтения в процессе расчетов будут выполнятся без использования таблиц итогов, что, безусловно, сильно увеличит продолжительность.
• Увеличить «Максимальное количество попыток записи сформированных движений» . В типовом решении максимальное значение этого параметра 5. Снять ограничение и установить, например, 1000. Или добавить настройку бесконечного числа попыток с возможностью отключения во время работающего расчета.
• Функционал выключения итогов находится в «Параметрах операций» закрытия месяца, «Операция Распределение затрат и расчет себестоимости» — «Раздел Управление итогами регистров» — параметр «Отключать итоги регистра перед записью движений». Можно попробовать отключить функционал выключения итогов на время записи результатов расчета себестоимости. Блокировки ожидания должны исчезнуть на таблице итогов, но есть риск существенного замедления записи движений. Стоит проверить насколько произойдет замедление и, если не критично, принять это.
  

В итоге остановились на третьем варианте, как на приемлемом — время записи увеличилось несильно:

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

Заключение

Давайте подведем некоторые итоги:

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