Экспертный кейс. Расследование деградации производительности системы. Проведение документа “Поступление товаров и услуг” (1С:ERP 2)

Экспертный кейс. Расследование деградации производительности системы. Проведение документа “Поступление товаров и услуг” (1С:ERP 2)

Инфраструктура исследуемой системы

          Технологическая платформа 1С:Предприятие 8, версия 8.3.19.1417

          Конфигурация: 1С:ERP Управление предприятием 2, версия 2.5.6.291

Операционная система: Windows Server 2019 Standard

          СУБД: Microsoft SQL Server 2019

Проблема

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

Согласно данным подсистемы БСП “Оценка производительности”, время выполнения ключевой операции “Проведение документа поступление товаров и услуг” возрастало в процессе тестирования с 15-20 секунд в начале тестирования до 150-200 секунд  в его финале.
 

Задача

Выявить и устранить причины замедления выполнения операции.

Решение

1. Первым делом проверяем корректность записанных замеров и локализуем проблему: клиент или сервер? Для этого сравниваем выборочно длительности замеров подсистемы “Оценка производительности” с длительностью события CALL технологического журнала 1С на сервере. Данные совпадают, следовательно, клиентские замеры верны, проблему необходимо искать на сервере.

2. Далее анализируем данные счетчиков производительности. Определяем, справляется ли оборудование. По показателям видно – во время тестирования высокой нагрузки на сервере приложений 1C и СУБД не наблюдается. 

% использования CPU в среднем менее 50%:

Объем свободной оперативной памяти более 200ГБ:

Высоких очередей на диски нет:

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

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

Видим, что есть ожидания на управляемых блокировках (TLOCK) и запросы к базе данных (DBMSSQL), но их длительность в сумме составляют не более 15% от длительности клиент-серверного вызова. На что тратятся оставшиеся 85% времени, по-прежнему непонятно.

4. Для того, чтобы понять, куда уходит оставшееся время, делаем анализ так называемых “дырок” в логах - длительных интервалов времени, в которых не регистрировались никакие события и как будто бы ничего не происходило.

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

Получаем несколько проблемных контекстов, первый:

06:20.488056-37,SDBL,3,process=rphost,p:processName=erp,OSThread=10300,t:clientID=827,t:applicationName=1CV8C,t:computerName=ERP01,t:connectID=17392,SessionID=6210,Usr=user,AppID=1CV8C,DBMS=DBMSSQL,DataBase=db01\erp,Trans=0,Func=insertRecords,tableName=#T06036ff19e4b4edebb79e14a39f4ed41,Rows=0,Context='Форма.Записать : Документ.ПриобретениеТоваровУслуг.Форма.ФормаДокумента
Документ.ПриобретениеТоваровУслуг.МодульОбъекта : 375 : ОбщегоНазначенияУТ.ПроверитьЗаполнениеКоличества(ЭтотОбъект, ПроверяемыеРеквизиты, Отказ);
    ОбщийМодуль.ОбщегоНазначенияУТ.Модуль : 4090 : ПроверитьОкруглениеКоличества(Объект, Отказ, ПараметрыПроверки);
        ОбщийМодуль.ОбщегоНазначенияУТ.Модуль : 4333 : Выборка = Запрос.Выполнить().Выбрать();'

06:32.128002-1,DBMSSQL,5,process=rphost,p:processName=erp,OSThread=10300,t:clientID=827,t:applicationName=1CV8C,t:computerName=ERP01,t:connectID=17392,SessionID=6210,Usr=user,AppID=1CV8C,DBMS=DBMSSQL,DataBase=db01\erp,Trans=0,dbpid=58,Sql='SELECT TOP 2
T1._Fld34846
FROM dbo._Const34845 T1',Rows=1,RowsAffected=-1,Context='Форма.Записать : Документ.ПриобретениеТоваровУслуг.Форма.ФормаДокумента
Документ.ПриобретениеТоваровУслуг.МодульОбъекта : 375 : ОбщегоНазначенияУТ.ПроверитьЗаполнениеКоличества(ЭтотОбъект, ПроверяемыеРеквизиты, Отказ);
    ОбщийМодуль.ОбщегоНазначенияУТ.Модуль : 4090 : ПроверитьОкруглениеКоличества(Объект, Отказ, ПараметрыПроверки);
        ОбщийМодуль.ОбщегоНазначенияУТ.Модуль : 4333 : Выборка = Запрос.Выполнить().Выбрать();'

Замечаем, что контекст у событий абсолютно одинаковый (выполнение пакетного запроса с формированием временных таблиц), а между событиями около 12 секунд.

Следующий контекст:

06:43.066016-63016,SDBL,4,process=rphost,p:processName=erp,OSThread=10300,t:clientID=827,t:applicationName=1CV8C,t:computerName=ERP01,t:connectID=17392,SessionID=6210,Usr=User,AppID=1CV8C,DBMS=DBMSSQL,DataBase=db01\erp,Trans=1,Sdbl='SELECT ALLOWED
****************************
INTO #Tfef0a9ac00bd44c890415f30c2ad08af
FROM
#T3300dee202d84412a982e91daf772310 Q_001_T_001 LEFT JOIN InfoRg45048 Q_001_T_002 ON (Q_001_T_001.Q_000_F_001  =  Q_001_T_002.Fld45050) INNER JOIN Reference351 Q_001_T_003 ON (Q_001_T_001.Q_000_F_001  =  Q_001_T_003.ID) INNER JOIN Reference352 Q_001_T_004 ON (Q_001_T_001.Q_000_F_000  =  Q_001_T_004.ID)
WHERE
(Q_001_T_004.Fld59648  =  351:00000000000000000000000000000000)
',Rows=1,Context='Форма.Записать : Документ.ПриобретениеТоваровУслуг.Форма.ФормаДокумента
Документ.ПриобретениеТоваровУслуг.МодульОбъекта : 855 : НоменклатураПартнеровСервер.ЗаполнитьПустоеСопоставлениеВНоменклатуреПартнераПоНоменклатуреИБ(Товары, Отказ);
    ОбщийМодуль.НоменклатураПартнеровСервер.Модуль : 335 : СопоставлениеНоменклатурыКонтрагентов.ЗаполнитьПустоеСопоставлениеВНоменклатуреКонтрагентаПоНоменклатуреИБ(ТаблицаТоваров, Отказ);
        ОбщийМодуль.СопоставлениеНоменклатурыКонтрагентов.Модуль : 298 : Выборка = Запрос.Выполнить().Выбрать();'

06:50.409005-45997,DBMSSQL,5,process=rphost,p:processName=erp,OSThread=10300,t:clientID=827,t:applicationName=1CV8C,t:computerName=ERP01,t:connectID=17392,SessionID=6210,Usr=User,AppID=1CV8C,DBMS=DBMSSQL,DataBase=db01\erp,Trans=1,dbpid=72,Sql='SELECT
T1._Q_001_F_000RRef,
****************************
',Rows=0,RowsAffected=0,Context='Форма.Записать : Документ.ПриобретениеТоваровУслуг.Форма.ФормаДокумента
Документ.ПриобретениеТоваровУслуг.МодульОбъекта : 855 : НоменклатураПартнеровСервер.ЗаполнитьПустоеСопоставлениеВНоменклатуреПартнераПоНоменклатуреИБ(Товары, Отказ);
    ОбщийМодуль.НоменклатураПартнеровСервер.Модуль : 335 : СопоставлениеНоменклатурыКонтрагентов.ЗаполнитьПустоеСопоставлениеВНоменклатуреКонтрагентаПоНоменклатуреИБ(ТаблицаТоваров, Отказ);
        ОбщийМодуль.СопоставлениеНоменклатурыКонтрагентов.Модуль : 298 : Выборка = Запрос.Выполнить().Выбрать();'

Опять контекст одинаковый, опять пакетный запрос и работа с временными таблицами…

5. Похоже, что это может быть проблемой на уровне технологической платформы 1С. Возможно, об этом уже сообщалось вендору и сообществу? Ищем что-то похожее в сервисе публикации ошибок 1С https://bugboard.v8.1c.ru/, а также на партнерском форуме https://partners.v8.1c.ru/forum.

6. В результате поисков  обнаруживаем похожую ошибку https://bugboard.v8.1c.ru/error/000109738 и обсуждение https://partners.v8.1c.ru/forum/topic/1981666. Так как ошибка исправлена в релизе платформы 1С версии 8.3.20.1549, обновляем тестовый стенд на последнюю актуальную версию платформы (на момент написания статьи – 8.3.20.1613). После чего заново проводим нагрузочное тестирование: деградация производительности больше не возникает.

Выводы и рекомендации

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

Расследование проводил: Георгий Бяков
Эксперт по технологическим вопросам
ИТ-Экспертиза