Акт по журналу 1С: справка с 817 до 145 мс, проверка заказа с 301 до 2 мс, 9353 руб. в год

Договор «оплата от выгоды» держится на одном документе: акте, где записано, сколько времени операция занимала до работ, сколько после, и как из этой разницы получены часы и рубли. Я собрала такой акт на файловой базе «Нано-УТ 2.0»: включила технологический журнал, семь раз выполнила один и тот же сценарий до оптимизации кода и семь раз после, а таблицу для акта получила скриптом tj_baseline.py. Частоту операций и ставку часа я задала сама, как это делает приложение к договору.

Стенд и порядок работы

Выводы относятся к файловой базе и к одному виду исправления. На клиент-серверном варианте с несколькими пользователями скрипт не запускался, и акт для такой базы потребует отдельного замера.

Три операции для замера

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

В обеих изменённых процедурах до правки запрос выполнялся на каждую строку внутри цикла. Для проверки доступности это выглядело так:

1
2
3

Для Каждого Пара Из Потребность Цикл
    Если ПолучитьОстаток(Пара.Ключ, Заказ.Склад) < Пара.Значение Тогда Возврат Ложь; КонецЕсли;
КонецЦикла;

После правки один запрос по списку номенклатуры возвращает остатки всех строк, а цикл читает их из соответствия:

1
2
3
4
5
6
7
8

Список = Новый Массив;
Для Каждого Пара Из Потребность Цикл Список.Добавить(Пара.Ключ); КонецЦикла;
Запрос = Новый Запрос("ВЫБРАТЬ Номенклатура КАК Номенклатура, ЕСТЬNULL(СУММА(КоличествоОстаток),0) КАК Остаток ИЗ РегистрНакопления.ТоварыНаСкладах.Остатки(, Склад=&Склад И Номенклатура В (&Товары)) СГРУППИРОВАТЬ ПО Номенклатура");
Запрос.УстановитьПараметр("Склад", Заказ.Склад);
Запрос.УстановитьПараметр("Товары", Список);
Выборка = Запрос.Выполнить().Выбрать();
Остатки = Новый Соответствие;
Пока Выборка.Следующий() Цикл Остатки.Вставить(Выборка.Номенклатура, Выборка.Остаток); КонецЦикла;

Справка переписана так же: два запроса на строку (остатки и резервы) заменены двумя запросами на весь список. Полный текст обоих вариантов собирает stand/make_stand.py из архива инструмента.

Прежде чем сравнивать время, я сравнила результаты. Хеши результатов справки на 1, 7, 150 и 300 строках и ответы проверки доступности на 1, 150 и 300 строках (с нехваткой остатка и без) в обоих вариантах совпали (evidence/equality.txt). Оба варианта прошли /CheckModules без ошибок.

Как собирается журнал

Журнал включается файлом logcfg.xml. В нём два отбора, по событиям SDBL (обращения к данным) и DBV8DBEng (файловый движок), и фильтр по подстроке контекста, чтобы чужие сеансы в журнал не попали:

1
2
3
4
5
6
7

<config xmlns="http://v8.1c.ru/v8/tech-log">
  <log location="C:\tj\baseline" history="1">
    <event><eq property="name" value="sdbl"/><like property="context" value="%ЗамерСценарий%"/></event>
    <event><eq property="name" value="dbv8dbeng"/><like property="context" value="%ЗамерСценарий%"/></event>
    <property name="all"/>
  </log>
</config>

В каталог conf установки платформы на этом компьютере записать нельзя, и платформа прочитала файл из C:\ProgramData\1C\1cv8\conf. Опыт создаёт этот каталог на время повторов и удаляет после них. После опыта я проверила каталоги, куда платформа могла бы читать общий файл: в C:\Program Files (x86)\1cv8\conf, в bin\conf версии 8.3.27.2130 и в ProgramData файла logcfg.xml нет (evidence/logcfg-location.txt).

Порядок одного повтора: записать logcfg.xml, запустить новый процесс 1С через COM, выполнить три операции, закрыть процесс, сложить каталог журнала в before-rN или after-rN. Хеши SHA-256 всех четырнадцати файлов журнала записаны в evidence/tj-sha256.txt: для договора это способ зафиксировать период «до», чтобы стороны подписали его до начала работ.

Что показал журнал

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

Граница между двумя вызовами в журнале не записана, и надёжно найти её по произвольному журналу нельзя: простой порог паузы этого не доказывает. Поэтому инструмент принимает журнал, где каждая операция выполнена в повторе один раз, как в этом опыте: один повтор это один новый процесс, в нём по одному вызову каждой операции. Если одна операция встретилась двумя отдельными сериями (повторный вызов, перемежение с другой операцией, два файла) или внутри серии пауза длиннее 5 секунд, скрипт отвергает повтор с кодом 2 и объяснением. Паузу короче порога и два вызова одного контекста подряд без пауз он не отличит от одного вызова: такие вызовы нужно развести сбором, по одному процессу на повтор.

1

python tj_baseline.py compare "sample/before-r*" "sample/after-r*" --only "Справка(Документ)" --only ПроверитьДоступность --only ЦеныСервер

Рисунок 1. Команда compare на журналах опыта: 7 повторов до и 7 после, в скобках разброс между повторами.

Обращением к данным здесь считается событие SDBL. У проверки доступности до правки их 300 на 150 строк, по два на строку, а после правки два на весь список; это и объясняет разницу во времени. На семи повторах p95 совпадает с максимумом, поэтому его стоит читать как «худший повтор». Разброс в этом прогоне велик: справка «до» от 561,9 до 1172,0 мс, проверка доступности «до» от 203,0 до 781,0 мс; в четвёртом повторе секундомер с журналом показал для проверки доступности 819,7 мс при 204-262 мс в остальных. Из-за такого разброса в акт кладут и среднее, и осторожную оценку.

Время контрольной операции (8,7 и 0,0 мс) лежит в пределах шума журнала: метки времени событий идут шагами 15-16 мс. Это видно в самом журнале: 1526 событий SDBL дали 88 различных значений времени; из 87 промежутков между соседними значениями 82 равны 15 или 16 мс, остальные пять (31-78 мс) приходятся на паузы между событиями (evidence/tj-clock-step.txt). Поэтому 0,0 мс у быстрого вызова означает «короче шага часов», и результат 2,2 мс у проверки доступности после правки проверен вместе с секундомером.

Сверка с секундомером

Те же вызовы я засекла секундомером вокруг COM-вызова, один раз с включённым журналом и один раз без него. Скрипт сводки stand/wall_summary.py лежит в архиве инструмента.

Рисунок 2. Секундомер вокруг вызова: 7 повторов, 150 строк; сверху журнал выключен, ниже включён.

Таблица даёт следующее.

Журнал замедляет оба варианта, в абсолютных миллисекундах сильнее вариант «до». Справка с журналом идёт 862,3 мс против 492,5 без него, то есть в 1,75 раза дольше (плюс 369,8 мс); после правки 192,7 против 106,7, в 1,81 раза (плюс 86,0 мс). Абсолютный рост соответствует числу записанных событий: у варианта «до» их 755, у варианта «после» 159. Накануне то же сравнение дало 1,34 и 1,15 раза: на кратность накладных расходов журнала рассчитывать нельзя, её нужно мерить на своей базе.

Время по журналу (817,0 мс) близко к секундомеру с журналом (862,3 мс); секундомер без журнала показывает 492,5 мс. Пользователь с выключенным журналом экономит на справке 385,8 мс, журнал даёт 672,0 мс.

Секундомер включает запуск вызова через COM: после правки проверка доступности по журналу занимает 2,2 мс, а секундомер показывает 16,4 мс. Для коротких вызовов секундомер даёт нижнюю границу того, что видит вызывающий код.

От миллисекунд к рублям

Формула в tj_baseline.py benefit записана в самом инструменте и в приложении к договору:

1
2
3
4
5

сэкономлено_за_вызов (с) = среднее_до - среднее_после   (при ухудшении меньше нуля)
часов_в_год = сэкономлено_за_вызов * раз_в_день * рабочих_дней / 3600
рублей_в_год = часов_в_год * ставка
чистый_эффект = сумма рублей_в_год по всем операциям, ухудшения идут со знаком минус
вознаграждение = max(чистый_эффект, 0) * доля / 100

Ухудшение одной операции вычитается из выгоды другой, а отрицательный чистый эффект вознаграждения не даёт. Пример для проверки: одна операция экономит 1 с, другая теряет 2 с, по одному вызову в день, один день, ставка 3600 руб. за час: чистый эффект минус 1 руб., вознаграждение 0. Этот случай закреплён тестами обоих архивов. В примере статьи обе операции стали быстрее, поэтому на его числа правило не влияет.

Параметры примера я задала сама: 120 справок и 300 проверок доступности в рабочий день на всех сотрудников, 247 рабочих дней, 800 руб. за час сотрудника с налогами, доля исполнителя 20 %. В договоре их подтверждает заказчик, журнал их не содержит.

1
2
3

python tj_baseline.py benefit "sample/before-r*" "sample/after-r*" ^
    --freq "Справка(Документ)=120" --freq "ПроверитьДоступность=300" ^
    --rate 800 --workdays 247 --fee 20 --act act.md --csv table.csv

В PowerShell команду записывают одной строкой, без символов ^; в окне консоли на рисунке 3 она выполнена так, без ключей --act и --csv.

Рисунок 3. Команда benefit: часы и рубли по каждой операции, итог и вознаграждение 20 %; в скобках осторожная оценка.

Осторожная оценка берёт самый быстрый повтор «до» и самый медленный повтор «после». Команда с ключами и описание источника времени записываются в сам акт. Строки секундомера получены калькулятором calc_csv.py из компаньона на тех же формулах (evidence/calc-stopwatch.txt). Калькулятор принимает средние, округлённые до десятых миллисекунды, поэтому на журнальных числах он даёт 9351 руб. вместо 9353: разница в два рубля идёт от округления входа (evidence/calc-filled.txt).

Расхождение между 9353 и 4939 руб. вызвано разными часами: журнал и секундомер без журнала измеряют разные вещи, и договор должен назвать одни из них. Для приложения я бы записала журнал как способ фиксации периодов «до» и «после», а основанием выплаты назвала осторожную оценку по журналу. В этом опыте 4841 руб. лежат рядом с 4939 руб. секундомера без журнала и ниже них; это наблюдение одного опыта; что осторожная оценка по журналу окажется ниже секундомера на других данных, оно не гарантирует.

Суммы в примере малы: операций две, данных 300 товаров, стенд учебный. Они показывают порядок расчёта. На базе заказчика числа выйдут из его частот и его журналов.

Что записать в приложении к договору

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

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

Границы замера

• Журнал должен содержать по одному вызову каждой операции на повтор. Определить по журналу, сколько раз и когда вызывалась операция, скрипт не может; повторные вызовы и перемежение отвергаются, а паузу меньше 5 секунд и два вызова подряд без паузы он считает одним вызовом.
• Скрипт не включает журнал и не запускает 1С: он читает готовые файлы *.log. Сбор повторов для вашей команды делает collect_runs.py из компаньона: если в каком-то повторе нет журнала с событиями или команда завершилась ошибкой, сбор останавливается с ненулевым кодом, существующий замер не удаляется без ключа --replace.
• Файловая база пишет события SDBL и DBV8DBEng; события CALL и DBMSSQL там не появляются. Разбор клиент-серверных журналов скрипт умеет, но на них он не запускался.
• Часы журнала на этой машине идут шагами 15-16 мс, поэтому вызовы короче 50 мс сверяются секундомером.
• Время до первого и после последнего обращения к данным в журнале не видно: разница с секундомером при включённом журнале составила 45,3 мс у справки «до» и 47,7 мс у справки «после». Полный путь пользователя через клиента замеряется отдельно.
• Скрипт считает время; рубли получаются из частоты и ставки, которые приходят из договора.
• Со временем база растёт, и сегодняшний «после» перестаёт быть сегодняшним. Для этого в приложении есть гарантийный период и пункт о повторных замерах на тех же данных.

Файлы к статье

К статье приложены два архива.

Инструмент perf-fee-24-4-tool.zip содержит tj_baseline.py, 26 тестов, журналы опыта (sample/before-r1..r7 и sample/after-r1..r7) и стенд: make_stand.py собирает варианты before и after из выгрузки «Нано-УТ 2.0», run_experiment.py повторяет опыт, wall_summary.py сводит секундомер. Запуск из корня распакованного архива:

1
2

python tj_baseline.py compare "sample/before-r*" "sample/after-r*"
python -m unittest discover -s tests -v

Компаньон perf-fee-24-4-companion.zip содержит заполненный образец приложения к договору, акт замеров этого опыта, калькулятор calc_csv.py с пустым и заполненным CSV, collect_runs.py (сбор повторов для вашей команды), шаблон logcfg.xml, чек-лист аудита из пяти разделов и журналы опыта. Тесты обоих архивов работают без платформы; из чистой распаковки проходят 26 тестов инструмента и 24 теста компаньона (журнал прогона лежит в evidence/unittest-tool.txt и evidence/unittest-companion.txt). В обоих архивах есть SHA256SUMS.txt с хешами всех файлов.

Рисунок 4. Тесты обоих архивов из чистой распаковки: 26 у инструмента и 24 у компаньона, все проходят.

Итог

Технологический журнал и скрипт на 14 повторах дали таблицу для акта: справка быстрее в 5,6 раза по журналу (817,0 против 145,0 мс) и в 4,6 раза по секундомеру без журнала, у проверки доступности 301,3 против 2,2 мс по журналу и 162,0 против 16,4 мс по секундомеру. При условных 120 и 300 вызовах в день и ставке 800 руб. за час это 11,69 часа и 9353 руб. в год по журналу, 4939 руб. по секундомеру без журнала, 4841 руб. по осторожной оценке. Тот же опыт накануне дал 660,7 и 95,9 мс по справке и 6991 руб. по журналу (evidence/previous-run-20261025.txt): числа от прогона к прогону отличаются, поэтому в договор вносят журналы конкретных прогонов; числа из статьи годятся только как образец.

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

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

 

Нинель Адольевна Щербакова (Ninel_S)

Архитектор • SRE & DevOps инженер • HighLoad 1С

Автор технических публикаций на Infostart. Разработчик NOPik, SRE-Suite-for-1C и мультиагентных ассистентов для экосистемы 1С:Предприятие.

Каталог статей и открытых репозиториев Ninel_S