Ускорение
производительности 1С
Ускорение работы 1С на примере обработки
«Рабочее место менеджера по доставке» в 1С:ERP 2.4

Станислав Песков
Руководитель проектов, эксперт по технологическим вопросам

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

Мы подумали, подумали и сделали следующее.


Сокращения
ТЖ – Технологический журнал
1С:ЦУП – 1С:Центр управления производительностью
ИБ – информационная база
БСП – библиотека стандартных подсистем

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

Сбор данных технологического журнала
Прежде, чем перейти к описанию оптимизации непосредственно обработки, указанной в названии статьи, рассмотрим способы поиска проблемных операций в плане производительности.
Помимо опроса пользователей соберем данные технологического журнала на сервере 1С для анализа. Для этого необходимо подготовить конфигурационный файл logcfg.xml, содержащий параметры ТЖ. По умолчанию он располагается в каталоге %PROGRAMFILES%\1cv8\conf.
Настроить сбор ТЖ можно с помощью обработки «Сбор аналитики»

Настроить сбор ТЖ можно с помощью обработки «Сбор аналитики» https://its.1c.ru/db/metod8dev/content/5955.

Конфигурационный файл logcfg.xml, используемый нами (аналогичен по содержанию файлу, который генерирует обработка «Сбор аналитики») представлен ниже.
<?xml version="1.0"?>
<ns:config xmlns:ns="http://v8.1c.ru/v8/tech-log">
    <ns:log location="F:\LOGS\P_ERPtest_ForCup\all" history="4">
        <ns:event>
            <ns:eq property="Name" value="CALL"/>
            <ns:eq property="p:processName" value="P_ERP_TEST"/>
            <ns:ge property="Duration" value="50000"/>
        </ns:event>
        <ns:event>
            <ns:eq property="Name" value="TLOCK"/>
            <ns:eq property="p:processName" value="P_ERP_TEST"/>
        </ns:event>
        <ns:event>
            <ns:eq property="Name" value="TDEADLOCK"/>
            <ns:eq property="p:processName" value="P_ERP_TEST"/>
        </ns:event>
        <ns:event>
            <ns:eq property="Name" value="DBMSSQL"/>
            <ns:eq property="p:processName" value="P_ERP_TEST"/>
        </ns:event>
        <ns:event>
            <ns:eq property="Name" value="SDBL"/>
            <ns:eq property="p:processName" value="P_ERP_TEST"/>
        </ns:event>
		<ns:property name="all"/>
    </ns:log>
    <ns:plansql/>
    <ns:dbmslocks/>
</ns:config>

Собираются следующие события:
  • Серверные вызовы длительностью более 5 сек.
  • Транзакционные блокировки в управляемом режиме.
  • Взаимоблокировки в управляемом режиме.
  • Исполнение операторов SQL СУБД MS SQL Server.
  • Исполнение запросов к модели базы данных системы «1С:Предприятие».
Также указаны элементы для сбора планов запроса, формируемых при работе различных СУБД, и информации о блокировках СУБД.
Через несколько секунд после копирования logcfg.xml в папку conf начинается запись данных ТЖ в указанный в настройках каталог. Собираем данные несколько часов (в нашем файле время хранения данных ограничено 4 часами, но собирали для примера около 1 часа), затем переименовываем файл или удаляем, чтобы остановить сбор данных.  

Анализ данных технологического журнала
Проанализируем данные ТЖ двумя способами: с помощью конфигурации1С:ЦУП (Центр управления производительностью) и с помощью инструментов bash.

Анализ с помощью 1С:ЦУП
1С:ЦУП (Центр управления производительностью) - инструмент мониторинга и анализа производительности клиент-серверных информационных систем на платформе 1С:Предприятие 8. Входит в Корпоративный инструментальный пакет 8.

https://v8.1c.ru/tekhnologii/tekhnologii-krupnykh-vnedreniy/korporativnyy-instrumentalnyy-paket/tsentr-upravleniya-proizvoditelnostyu/

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

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

Для этого выполним команду «Загрузка технологических журналов».

В открывшейся форме нужно указать путь к журналам. Рекомендуем располагать журналы на сервере (в нашем случае клиент 1С:ЦУП запускается на другой машине, а сервер на котором собирали ТЖ отличается от сервера, на котором развернута база 1С:ЦУП, пришлось скопировать данные ТЖ на сервер 1С, где развернута база 1С:ЦУП) для более быстрой работы с данными.

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

ЦУП проанализирует данные ТЖ, установит флажки напротив найденных видов проблем и заполнит список информационных баз из ТЖ. Если ИБ анализируется впервые необходимо подгрузить метаданные. Это нужно для конвертации имен таблиц и полей в терминах СУБД в имена в терминах ИБ (как они представлены в конфигураторе).

Метаданные можно выгрузить в формат XML с помощью обработки, входящей в комплект поставки ЦУП (1c\pmc\2_1_9_2\ВыгрузкаМетаданных_1.0.1.4.epf)

После загрузки метаданных необходимо нажать «Запустить анализ» и следить за ходом выполнения в форме «Монитор анализа».

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

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

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

В нашем случае в списке проблем часто встречается обработка РабочееМестоМенеджераПоДоставке. Самой длительной операцией является получение данных динамического списка ЗаданияНаПеревозкуВРаботе.

На закладке «Пользователи» видим, у каких пользователей чаще всего возникали длительные события. Уточняем у указанных пользователей, сталкиваются ли они с медленной работой 1С и подтверждаем информацию, что есть жалобы на долгое открытие обработки «Рабочее место менеджера по доставке», переключение между закладками и работу со списком «Задания на перевозку» .

Анализ с помощью bash
В качестве альтернативы поиска длительных событий с помощью 1С:ЦУП рассмотрим инструменты bash.

https://its.1c.ru/db/metod8dev/content/5927

В нашем случае используется git bash https://git-scm.com/downloads.
В каталоге с собранными данными ТЖ размещаем файл со скриптом следующего содержания.
cat rphost*/*.log | 
grep -P ',CALL,.+,Context=' | 
sed -r 's/\xef\xbb\xbf//g; s/^[0-9]+:[0-9]+.[0-9]+-//; s/CALL,.+,Context=/CALL,Context=/; s/,Interface=.+$//' | 
gawk -F',CALL,' '{{Dur[$2]+=$1; Execs[$2]+=1}} END {for (i in Dur) print Dur[i] "," Execs[i] "," i }' | 
sort -rnb | 
head -n 1000  > top_call_context.txt
Выполняя скрипт получаем файл с результатами
С помощью Excel отображаем данные в более наглядном виде
Из полученных данных видно, что обработка РабочееМестоМенеджераПоДоставке несколько раз встречается среди самых длительных операций в собранном ТЖ. В частности, длительное время тратится на получение данных динамического списка.

Сбор статистики и замеры времени ключевой операции

Для анализа статистики по времени выполнения ключевой операции (открытие формы обработки «Рабочее место менеджера по доставке») за более широкий интервал времени (чем собранный ТЖ) обратимся к регистру сведений «Замеры времени» (входит в БСП).


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

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

Среднее время открытия формы (без установленных отборов) под пользователем с полными правами составляет 33 секунды. Под пользователем с ограниченными правами 86 секунд.

Произведем замеры с помощью конфигуратора (Сервис > Замер производительности) и сравним результаты.

Замеры с помощью конфигуратора показали среднее время выполнения операции под пользователем с полными правами 21 секунду.

Замеры с помощью конфигуратора показали среднее время выполнения операции под пользователем с ограниченными правами – 31 секунду.

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

Промежуточные выводы
Собрав информацию можно сделать следующие промежуточные выводы и запланировать дальнейшие шаги по оптимизации.
· Получение данных динамического списка ЗаданияНаПеревозкуВРаботе – необходимо проанализировать запрос, являющийся источником данных динамического списка, для поиска узких мест в плане производительности
· Выполнение тяжелого запроса по результатам замера конфигуратором (первая строка в форме замера) – необходимо проанализировать выполняемый запрос для поиска узких мест в плане производительности
· Передача больших коллекций значений между клиентом и сервером – необходимо проверить возможность ограничения количества передаваемых элементов в коллекциях
Разберем каждую проблему подробнее.

Анализ запроса динамического списка
Отроем текст запроса динамического списка ЗаданияНаПеревозкуВРаботе. В данном случае запрос небольшой и его возможно проанализировать без получения и разбора плана выполнения запроса SQL.

Пример плана запроса, полученного с помощью ЦУП представлен на скриншоте

Вернемся к тексту запроса. Мы видим, что присутствуют доработки: добавлено соединение с вложенным запросом, в котором табличная часть Распоряжения документа ЗаданияНаПеревозкуВРаботе соединяется с другим вложенным запросом, выбирающим обороты регистра накопления без отбора на период, с отбором по измерению с составным типом данных. Причем этот отбор содержит большое количество значений.
После уточнения у пользователей, актуальны ли для них нетиповые колонки, приходим к следующему выводу. Необходимо оптимизировать запрос, получающий данные для динамического списка. Для этого предлагается для документа ЗаданиеНаПеревозку добавить реквизит КоличествоМест и заполнять его при записи документа. В этом случае будет выполняться запрос к регистру ЗаказыКлиентов с отбором только по тем значениям первого измерения ЗаказКлиента, которые содержатся в табличной части Распоряжения документа ЗаданияНаПереработу. А запрос динамического списка будет обращаться только к данным документа ЗаданияНаПеревозкуВРаботе.

Анализ тяжелого запроса из замера производительности
В предыдущих разделах мы приводили скриншоты замеров производительности, выполненных с помощью конфигуратора. Видно, что первую строку занимает выполнение пакета запросов. Под полными правами 25% времени, под ограниченными 50% времени.

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

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

Рекомендации по оптимизации следующие: установить отборы, которые указывает пользователь, на результат запроса, формирующего временную таблицу либо переработать решение, чтобы данные выбирались корректно из подходящих таблиц. Например, создать новый регистр накопления, в котором будут хранится неотгруженные заказы и вместо выбора всех заказов потребуется выбрать только остатки по этому регистру.
Анализ причин медленного открытия формы на клиенте
Соберем данные ТЖ на клиенте. Для этого на клиенте необходимо использовать следующую настройку сбора logcfg.xml.
<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="E:\psn\TJ_Logs\Client_Full" history="4">
   <event>
       <eq property="process" value="1cv8"/>
       <ne property="name" value=""/>
   </event>
   <event>
       <eq property="process" value="1cv8c"/>
       <ne property="name" value=""/>
   </event>
   <property name="Interface">
       <event>
           <eq property="name" value=""/>
       </event>
   </property>
   <property name="all"/>
</log>
</config>

Необходимо включить сбор ТЖ, выполнить операцию и завершить сбор, чтобы удобнее анализировать небольшой объем информации.

Получаем ТЖ следующего содержания.

Время серверного вызова занимает около 22 секунд (соответствует интервалу между запросом VRSREQUEST и ответом VRSRESPONSE), что совпадает с замером времени, полученного в конфигураторе. Замер БСП и секундомер при этом показывает 33 секунды.

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

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

Для этого необходимо опубликовать базу 1С на веб-сервере, а на клиенте установить инструмент отладки веб-траффика Fiddler (https://www.telerik.com/download/fiddler).

В нашем случае веб-сервер 1С работает по протоколу https, поэтому необходимо выполнить дополнительные настройки Fiddler и браузера для сбора траффика.

Откроем настройки Tools > Options.

Далее нужно перейти на закладку HTTS, установить флаги Capture HTTPS CONNECTs, Decrypt HTTPS traffic, указать Protocols <client>;ssl3;tls1.0;tls1.2. Затем нажать Actions > Export Root Certificate to Desktop.

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

Можно приступать к сбору траффика. Для этого открываем в браузере исследуемую базу 1С, перед выполнением ключевой операции выбираем в Fiddler File > Capture Traffic (F12), затем после выполнения операции прекращаем сбор траффика также нажатием F12.

В собранном журнале находим относительно большой пакет (в нашем случае 10 Мб), выбираем его и в правой части формы Fiddler открываем закладку Inspectors. Затем выбираем режим просмотра JSON и пытаемся проанализировать полученные данные.

При разворачивании и изучении свойств (параметров формы response/props) удается найти коллекцию с количеством элементов более 18 тыс., что достаточно много.

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

Для более быстрого поиска воспользуемся результатами замера производительности конфигуратором (скриншоты в предыдущем разделе). В списке операций находим строки, которые выполнялись более 18 тыс. раз и переходим в соответствующую процедуру. Затем в конце этой процедуры устанавливаем точку останова и с помощью Отладка > Вычислить выражение (Shift+F9) проверяем количество элементов в коллекциях.

Находим таблицу значений ТоварыРаспоряженийКДоставке с количеством элементов более 18 тыс. и для проверки влияния на скорость открытия формы устанавливаем заглушку в коде, которая ограничивает количество элементов в таблице до 1000.

Эксперимент показал, что скорость открытия формы увеличилась на 10 секунд и общее время замера конфигуратором практически совпадает с замером БСП. Сериализиация и десериализация большой коллекции значений (таблица с количеством строк более 18 тыс.) при передаче данных с сервера на клиент оказывает значительное влияние на скорость открытия формы.

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

1.      Неоптимальный тяжелый запрос при получении данных динамического списка ЗаданияНаПеревозкуВРаботе.
Решение: добавить необходимые реквизиты в документ ЗаданиеНаПеревозку (которые заполнять при записи) и выбирать данные из них

2.      Неоптимальный тяжёлый запрос при открытии формы, который заполняет таблицы значений.
Решение: установить отборы, которые указывает пользователь, на результат запроса, формирующего временную таблицу, чтобы значительно сократить количество возвращаемых элементов

3.      Большое количество элементов в таблице формы ТоварыРаспоряженийКДоставке приводит к значительным задержкам при открытии формы.
Решение: сократить количество элементов в таблице ТоварыРаспоряженийКДоставке. При разборе проблемы оказалось, что таблица заполняется по данным запроса из пункта 2. Таким образом, оптимизировав результат запроса с помощью отборов мы решаем проблему медленного открытия формы.
По результатам произведенного анализа и рекомендаций по оптимизации выполнены доработки:

1.      Для документа ЗаданияНаПеревозку добавлены реквизиты, которые заполняются при записи документа. Таким образом значительно упростился запрос динамического списка: данные выбираются из таблицы Документ.ЗаданиеНаПеревозку без необходимости с соединениями с регистрами накопления.

2.      Доработан запрос, выполняющийся при открытии формы обработки. Ранее он собирал во временных таблицах большое количество данных, возвращал большие коллекции значений на форму, которые затем фильтровались на стороне клиента. После оптимизации фильтры применяются в самом запросе, сервер возвращает на клиента только те данные, которые необходимы пользователю. Уменьшилось время выполнения запроса, скорость открытия формы.

В тестовой базе время открытия формы обработки под пользователем с полными правами с 33 секунд сократилось до 3 секунд. Под пользователем с ограниченными правами с 86 секунд до 8 секунд.

Результаты замера времени выполнения ключевой операции в продуктивной базе представлены на графике. До оптимизации время выполнения составляло 10-20 секунд. После оптимизации 3-8 секунд.
Время выполнения операции в продуктивной среде сократилось более, чем в 2 раза
После применения изменений получили следующий отзыв от пользователя:

«Всё работает просто прекрасно:
быстро и без ошибок!
Спасибо огромное!!!»
Остались вопросы? Свяжитесь с нами!
Даже если вы просто спросите, как у нас дела, нам будет приятно :)
Телефон: 8 (495) 505 63 78
Почта: cloud@1cniki.ru
Москва, ул. Большая Новодмитровская, д. 36, стр. 12, вход 6 Дизайн-завод FLACON


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