Технологические вопросы крупных внедрений
24.03.2021

Методика расследования причин медленной работы операции на примере открытия управляемой формы

Ограничения применимости методики

Когда применяется методика:

• Операции с управляемой формой выполняются медленно, например, открытие формы или выполнение кода формы, требующего контекстного серверного вызова;
• Многократное выполнение операции в рабочей базе не приводит к значительному колебанию времени выполнения операции;
• Проблема воспроизводится на тестовой базе с наполнением данными, аналогичным продуктивному (с точностью до возможного обезличивания);
• Время выполнения операций пользователем с административными правами ничем не отличается от времени выполнения для любого другого пользователя;
• Замер производительности средствами конфигуратора не выявляет проблем и значительно отличается от замера времени, собранного подсистемой БСП (длительности, зафиксированной в регистре сведений "Замеры времени" или аналогичном);
• Замер производительности средствами конфигуратора при пошаговой отладке "зависает" на строках вида "КонецФункции", "КонецПроцедуры".

Проверка ограничений и подготовка к расследованию

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

1. Если в продуктивном контуре разрешена отладка (не рекомендуется), перейти к следующему пункту. Иначе развернуть копию продуктивной ИБ в том же или близком по настройкам контуре с возможностью отладки. При ограничении на развертывание в тестовом контуре продуктивной системы выполнить подготовку к переносу продуктивной БД в тестовый контур, выполнив обезличивание данных, но обязательно сохранив их количественный и качественный состав (число объектов и их связи друг с другом).
2. Проверить, что для данной (проблемной) операции настроен замер производительности средствами подсистем БСП, и он совпадает с замером по секундомеру вручную. Если не так – реализовать или исправить замер, чтобы расхождений не было. Правильно, если начало замера находится непосредственно перед открытием формы, например, в форме списка документов (для операции открытия формы документа). Некорректным будет замер, который начинается в обработчиках формы (любых, включая "ПриСозданииНаСервере" или "ПриОткрытии").
3. Повторить операцию под пользователем с административными правами, сравнить с длительностью для пользователей с ограниченными правами (отличия могут быть, но должны быть несущественными). Если отличия существенные – расследовать обычным способом возможное влияние RLS и провести оптимизацию.
4. Настроить как минимум клиентский технологический журнал на сбор событий SCALL, VRSREQUEST, VRSRESPONSE (все свойства) и выполнить замер производительности средствами конфигуратора. При этом длительности выполнения данной операции разными инструментами должны удовлетворять следующему неравенству: (замер конфигуратором) < (замер по ТЖ, событие SCALL) < (замер БСП, реальное время). Если что-либо из этого не выполняется, требуется провести оптимизацию по обычным методикам, расследуя проблемные места выявленные по ТЖ или замером конфигуратора.

Сбор и анализ стандартных данных

Разберем пример для операции открытия формы документа "Табель учёта рабочего времени".

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

Настройка технологического журнала на клиенте может быть такой:

Копировать в буфер обмена

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="D:\TJ_Logs\Client_Full" history="24">
    <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>

Фильтр по имени процесса для нашей задачи избыточен и нужен для того, чтобы в случае ошибочной настройки такого лога на сервере не получить сбор всех событий для серверных процессов, что может занять значительный объем. С другой стороны, при осознанном включении такой настройки на сервере (если клиентские приложения запускаются там же, где может быть развернут и сервер приложений 1С:Предприятие) мы в отдельном каталоге Client_Full увидим данные только клиентских приложений (хотя при этом подкаталоги других процессов тоже будут созданы, но они буду пустыми). Свойство Interface не собираем, так как оно дублируется более "человек читаемым" свойством IName (хотя даже последнее нам в данном примере не обязательно нужно).

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

Замеры времени средствами БСП будут выглядеть следующим образом:

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

Замер отладчиком конфигуратора изображен на следующем рисунке:

Как видно, сумма длительности всех строк, связанных с открытием формы составила всего 1,523 секунды.

Определим точное время начала и завершения операции по данным регистра замеров времени БСП.
Для этого необходимо любым удобным способом преобразовать данные колонок "Дата начала замера" и "Дата окончания" из миллисекунд UTC, начиная с 01.01.0001 00:00:00 (обычно эти значения получены с помощью функции ТекущаяУниверсальнаяДатаВМиллисекундах()).
Например, можно воспользоваться онлайн инструментами вроде https://www.epochconverter.com/ (нас будут интересовать минуты, секунды и миллисекунды, отличия в часовых поясах и годах не важны), либо можно преобразовать значение в дату с точностью до секунд с помощью функции вида:

'00010101' + ТекущаяУниверсальнаяДатаВМиллисекундах() / 1000

а для миллисекунд взять остаток от деления на 1000 (то есть просто последние три цифры, обратите внимание на "779" на следующей картинке).

Точное время начала замера (минут:секунд.миллисекунд): 25:10.779

Точное время окончания замера (минут:секунд.миллисекунд): 25:23.801

Найдем теперь записи технологического журнала, соответствующие данному замеру, они будут примерно следующими:

Здесь видно, что соответствующий нашему замеру серверный вызов SCALL завершился примерно за 10,1 секунды, это соответствует интервалу между запросом VRSREQUEST и ответом VRSRESPONSE.
Причем время начала замера почти совпадает с началом вызова, то есть событием VRSREQUEST, что собственно ожидаемо, так как замер БСП начинается на клиенте и должен быть непосредственно перед командой открытия формы. А вот окончание вызова сервера случилось раньше, чем окончание замера, что значит, что эта разница во времени пришлась на часть работы клиентского приложения.

Итак, промежуточный итог по длительностям замеров разными способами показывает соответствие нашей ситуации ограничениям и выполнение неравенства: 1,5 < 10,1 < 13.

Настройка дополнительных инструментов

Стандартными инструментами не удается увидеть причину проблем низкой производительности работы (открытия) управляемой формы, поэтому воспользуемся следующими помощниками:

• Отладчик операционной системы: Windows Performance Recorder для сбора метрик и Windows Performance Analyzer для их визуализации и анализа;
• Анализатор сетевых протоколов Wireshark или прокси-сервер Fiddler Web Debugger.

Установим и запустим Windows Performance Recorder ("C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit\WPRUI.exe"), укажем настройки:

После того, как их подготовили, перейдем в тонкий клиент 1С, откроем форму списка документов и непосредственно перед воспроизведением проблемной операции запустим сбор данных WPR (кнопка Start).

После открытия формы в тонком клиенте запись можно остановить и открыть ее для анализа. В открывшемся окне найдем по PID 5508 (его можно определить в диспетчере задач ОС или по логам ТЖ) наш тонкий клиент 1С и должны получить примерно следующую картинку:

По данным Windows Performance Analyzer видим, что у нас нет серьезной нагрузки по дискам, а поток тонкого клиента потребляет 100% ЦП на протяжении длительного времени вплоть до завершения замера.

Запомним этот результат и проанализируем траффик.

Запустим Wireshark и повторим проблемную операцию в тонком клиенте 1С:Предприятие с прямым подключением к серверу приложений 1С.

При сборе данных с помощью Wireshark (и отбору по пакетам с сервером-источником равным серверу приложений 1С:Предприятие) запуск открытия формы документа будет выглядеть примерно так:

Здесь каждая такая строка – это пакет (или если точнее, то "кадр", frame), который в свою очередь является частью общего большого пакета поверх протокола TCP (PDU – Protocol Data Unit). Если их сложить, получим пакет около 70 Кб. Стоит обратить внимание, что это будет размер с учётом сжатия, а если без него – то должны получить что-то около 2500 – 3500 Кб данных.

Если вернуться к анализу технологического журнала и посмотреть на "Content-Length" (или "Body"), то увидим также те самые 70577 байт. Познавательно, можно взять на заметку, но пока новой информации не дает. В таком дампе Wireshark бывает полезно анализировать каждый отдельный кадр и возможные повторы отправки пакетов или увидеть сбросы TCP-соединений, которые могут приводить к ошибкам в работе клиентов (например, из-за антивирусов, которые могут распознать такое содержимое как подозрительное). Однако для нашей проблемы удобнее воспользоваться другим инструментом – прокси-сервером Fiddler и проанализировать с его помощью уже http-траффик.

Устанавливаем и запускаем Fiddler, на панели инструментов ищем "Browse", выбираем любимый браузер и запускаем в нем необходимое нам приложение (информационную базу 1С:Предприятие). После запуска переходим в форму списка документов (готовимся воспроизвести сценарий), возвращаемся в Fiddler и включаем сбор траффика (кнопка F12), переходим в браузер и открываем форму документа. После её открытия сбор траффика можно отключить и заняться его анализом. Мы должны получить примерно следующее:

В данном дампе достаточно быстро находится относительно большой пакет искомого размера, выбираем его в списке слева, а в правой части окна переключаемся на страницу Inspectors, выбираем там просмотр заголовков (Headers), и так как у нас пакет является сериализованным json (Content-Type: application/json), то попросим Fiddler десериализовать его для нас.

После этого в окне предпросмотра отобразится древовидная структура ответа (response), которая передается с сервера на клиент и содержит так много данных. Далее нам необходимо проанализировать её и найти наиболее проблемные места. Может помочь кнопка Expand All, которая развернёт все элементы дерева, но это может занять некоторое время. Чтобы его сократить, сначала поймем, что именно нужно искать.

Подведем промежуточный итог:

• Проблем с медленной работой прикладного кода 1С или запросов нет.
• Большая часть времени открытия формы состоит из сетевого взаимодействия.
• Размер пакета с формой подозрительно велик.
• После получения пакетов имеем высокую утилизацию ЦП тонким клиентом 1С (или веб-клиентом).
• Потерянное время находится где-то между окончанием/началом работы прикладного кода 1С и сетевой передачей.

Из всех этих пунктов для нас наиболее полезным и требующим дополнительного анализа является тезис "Размер пакета с формой подозрительно велик".
Какие могут быть причины для такой ситуации? В общем случае их несколько:

• Сама по себе большая и сложная форма с большим количеством экранных элементов и реквизитов. Наверное, редкий и точно не очень правильный случай, лучше такого избегать на этапе проектирования систем.
• Простая форма, но много данных в реквизитах формы (включая данные объекта), в особенности:
  • Хранилище значения, Строка(0);
  • Большие коллекции (Таблица, Дерево, Список);
  • Произвольный тип (концентрация проблем).

Так как наша проблема (у вас может быть по-другому) воспроизводится даже при очень небольшом количестве данных в ТЧ, и реквизитов у документа (т.е. объекта формы) совсем не много, то их мы не рассматриваем. Остаются реквизиты формы, не равные основному реквизиту "Объект".

Среди них находится несколько реквизитов, имеющих произвольный тип. Могут выглядеть так:

Сопоставляем эти данные с уже собранным ранее замером с помощью конфигуратора, и видим заполнение этих структур достаточно большим количеством элементов (например, можно 5059 в реквизите "СвойстваИзмерений").
Снова вернемся к дампу траффика в Fiddler и найдем там элемент, отвечающий за параметры формы (response/props). Увидим там примерно следующее:

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

Найдем прикладной код, заполняющий эти параметры, и убедимся, что данных там действительно достаточно много (2-3 Мб), и они представляют собой большое количество сложных вложенных структур.

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

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

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

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

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

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

• Ограничивать количество элементов коллекции до некоторого приемлемого количества (например, по замерам видно, что если их количество будет до 1000, то влияние на производительность будет не существенным).
• Это можно обеспечить за счёт учета уже введенных в форме значений, например, в документе Табель имеется обязательное к заполнению поле "Организация", которое является владельцем у справочника "Территории", т.е. можно было бы организовать соответствующий отбор, что поможет значительно сократить количество элементов. Плюс можно было сделать связь с выбранным подразделением.
• Если в справочнике присутствуют помеченные на удаление элементы - то добавление соответствующего отбора тоже может оказать влияние, если таких элементов много.
• В конце концов, можно пересмотреть логику работы формы и не хранить в её реквизитах то, что можно быстро получить на сервере.
• В частности, процедуру ДанныеДляРедактированияВХранилище (это контекстная серверная процедура) можно было бы реализовать бесконтекстной и таким образом избавиться от сериализации/десериализации свойств.