Заметки эксперта. Расследование длительного выполнения отчета “Движение ТМЦ и затрат в производстве” (1С:ERP 2)

Заметки эксперта. Расследование длительного выполнения отчета “Движение ТМЦ и затрат в производстве” (1С:ERP 2)

Кратко: в ходе проведения нагрузочного тестирования “1С:ERP 2” под ОС Linux на СУБД Postgres выявлено существенное замедление формирования отчета “Движение ТМЦ и затрат в производстве” - до 60 минут. После проведенного расследования и точечной корректировки СКД в отчете, без изменения бизнес-логики результатов его работы, работа отчета была ускорена в 80 раз - средний показатель формирования составил 30 секунд.

Мы опубликовали в предыдущих двух статьях на наш взгляд интересные и довольно необычные кейсы расследования деградации производительности. Эта статья про случай попроще, но мы считаем, что и он заслуживает вашего внимания. Во-первых, и тут есть существенная проблема с быстродействием. Во-вторых, этот пример показателен тем, что далеко не всегда нужно вообще что-то “переписывать” в конфигурациях 1С. Надеемся, вам будет интересно ;)

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

• Технологическая платформа 1С:Предприятие 8, версия 8.3.19.1264
• Конфигурация: 1С:ERP Управление предприятием 2, версия 2.5.6.234
• Операционная система: Astra Linux Орел 2.12
• СУБД: Postgres Pro Enterprise 13
• Размер базы данных: около 500 Гб
• Количество пользователей: около 2200

Проблема

В ходе проведения нагрузочного тестирования прикладного решения “1С:ERP 2” в рамках программы перехода на операционную систему Linux с использованием СУБД Postgres выявлено длительное формирование отчета "Движение ТМЦ и затрат в производстве”.

Если установить в отчете параметры отбора “Период (месяц)” и “Подразделение”, после чего запустить его формирование – это занимает от 40 до 60 минут. Причем, формирование “под нагрузкой” (одновременная работа пользователей) такого отчета у части пользователей завершается с ошибкой “Недостаточно памяти для получения результата запроса к базе данных”.

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

Задача

Выявить и устранить причины крайне медленного формирования отчета “Движение ТМЦ и затрат в производстве” в инфраструктуре 1С:ERP 2 / Linux / Postgres.

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

На момент выполнения такого рода расследования, у нас должна быть подключена подсистема БСП “Оценка производительности”, включен технологический журнал 1С (ТЖ 1С), желательно включить подробное логирование в журнале регистраци 1С (ЖР 1С).

Для начала ищем самый длительный замер по ключевой операции формирования этого отчета, полученный подсистемой БСП “Оценка производительности” - запоминаем “Номер сеанса”:

После чего в ТЖ 1С ищем событие CALL (клиент-серверный вызов), соответствующее данному замеру: ”SessionID=11811(2218)”

22:38.093000-2359346998,CALL,1,Usr=ЭкономистПроизводства_012,SessionID=11811(2218),p:processName=erp,Func=Background job,Module=ДлительныеОперации,Method=ВыполнитьСКонтекстомКлиента,Memory=-858220508,MemoryPeak=15575941249,InBytes=117587968,OutBytes=133120366,CpuTime=336095413

Действительно: вызов длился почти 40 минут.

Обращаем внимание на еще один момент: в пике ему потребовалось почти 15 Гб оперативной памяти (свойство MemoryPeak). Это еще одна причина, которая требует расследования (многовато выходит для отчета, который в итоге ничего не выводит).

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

Для анализа ситуации смотрим на запросы, которые выполняются при формировании запроса к базе данных, анализируем события ТЖ 1С  DBPOSTGRS для данного клиент-серверного вызова (сопоставляем по тому же SessionID=11811):

45:09.657000-108177999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=7838,t:clientID=2832,t:applicationName=BackgroundJob,t:computerName=erp02,t:connectID=15586,SessionID=11811,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=27776,Sql="<...>",RowsAffected=42998,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'
57:10.549000-720529999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=7838,t:clientID=2832,t:applicationName=BackgroundJob,t:computerName=erp02,t:connectID=15586,SessionID=11811,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=27776,Sql="<...>",RowsAffected=2841404,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'
04:07.978000-292160999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=7838,t:clientID=2832,t:applicationName=BackgroundJob,t:computerName=erp02,t:connectID=15586,SessionID=11811,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=28219,Sql="<...>",RowsAffected=3023307,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'

Видим, что два запроса выполняются долго - в листинге выше: 720529999 мкс второй запрос, 292160999 мкс третий запрос. Кроме этого, они еще и возвращают в итоге около 3 миллионов строк каждый: RowsAffected=2841404 во втором запросе, RowsAffected=3023307 в третьем запросе.

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

Переходим к самому отчету в конфигурации 1С.

Помним: в варианте отчета, вызывающем проблему, отбор устанавливается по периоду и по подразделению.

Открываем настройки схемы компоновки данных (СКД) для данного отчета и видим: отбор по подразделению указан не для отчета, а в отдельных группировках.

Такая настройка СКД приводит к избыточному чтению данных из СУБД: из базы данных сначала выбираются все данные, без отбора по подразделению. И только после этого компоновщик СКД для каждой группировки накладывает отбор по подразделению.

Решение

Проанализировав полученные выше данные по работе 1С с СУБД в контексте этого отчета и структуру его СКД, делаем вывод: основной отбор по подразделению можно перенести в сам отчет, не нарушая логику его работы. Вот так:

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

Применяем изменения в конфигурации 1С и проверяем формирование отчете в рамках следующей итерации нагрузочного тестирования:

52:05.794000-1516999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=4120,t:clientID=253,t:applicationName=BackgroundJob,t:computerName=erp01,t:connectID=2740,SessionID=2298,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=30344,Sql="<...>",RowsAffected=0,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'                        
52:22.199000-15617999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=4120,t:clientID=253,t:applicationName=BackgroundJob,t:computerName=erp01,t:connectID=2740,SessionID=2298,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=30668,Sql="<...>",RowsAffected=0,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'
52:25.135000-2789999,DBPOSTGRS,5,process=rphost,p:processName=erp,OSThread=4120,t:clientID=253,t:applicationName=BackgroundJob,t:computerName=erp01,t:connectID=2740,SessionID=2298,Usr=ЭкономистПроизводства_012,DBMS=DBPOSTGRS,DataBase=erp04\erp,Trans=0,dbpid=30562,Sql="<...>",RowsAffected=0,Result=PGRES_TUPLES_OK,Context='
ОбщийМодуль.ДлительныеОперации.Модуль : 1063 : ВызватьПроцедуру(ВсеПараметры.ИмяПроцедуры, ВсеПараметры.ПараметрыПроцедуры);
    ОбщийМодуль.ДлительныеОперации.Модуль : 1073 : ОбщегоНазначения.ВыполнитьМетодКонфигурации(ИмяПроцедуры, ПараметрыВызова);
        ОбщийМодуль.ОбщегоНазначения.Модуль : 5180 : Выполнить(Текст);
             : 1 : ВариантыОтчетов.СформироватьОтчетВФоне(Параметры[0],Параметры[1])
                ОбщийМодуль.ВариантыОтчетов.Модуль : 2773 : Формирование = СформироватьОтчет(Параметры, Ложь, Ложь);
                    ОбщийМодуль.ВариантыОтчетов.Модуль : 1718 : ОтчетОбъект.СкомпоноватьРезультат(Результат.ТабличныйДокумент, Результат.Расшифровка);
                        Отчет.ПроизводственныеЗатраты.МодульОбъекта : 81 : ПроцессорВывода.Вывести(ПроцессорКомпоновки);'
52:25.333001-25484999,CALL,1,Usr=ЭкономистПроизводства_012,SessionID=2298(766),p:processName=erp,Func=Background job,Module=ДлительныеОперации,Method=ВыполнитьСКонтекстомКлиента,Memory=-184943301,MemoryPeak=14490779,InBytes=0,OutBytes=0,CpuTime=5387584

Видим, что отбор сразу применился на уровне запроса к базе данных (RowsAffected=0). Потребление памяти при этом снизилось до 15 Мб (MemoryPeak=14490779).

Отчет сформировался за 30 секунд:

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