Анализ технологического журнала 1С с помощью PowerShell

04.05.2022

Универсальная методика анализа технологического журнала 1C без применения алгоритмов программирования.

Внимание! Детали изложенных проблем и их решения потеряют свою актуальность после выхода в релиз платформы версии 8.3.25(26), где будет реализована возможность выгрузки технологического журнала в формате JSON.

Мысль написать это руководство возникло после прослушивания курса "Эксперт по технологическим вопросам 1С". Как многим уже наверно известно - лекторами, экзаменаторами и различными профильными публикациями пропагандируется использование bash-скриптов. При этом достичь понимания, как именно работают эти скрипты, могут совсем немногие: неоднократно слышал совет от коллег зазубривать их наизусть для сдачи экзамена. А так как на каждый случай разбора ТЖ нужен свой скрипт, то заучивать придется много! Если же говорить вне контекста экзамена, то все пользуются готовой коллекцией скриптов, что уже совсем не прибавляет желания никому в них разбираться и совершенствовать.

В данной статье я предлагаю альтернативный способ сделать всё то же самое с помощью инструмента PowerShell.

Плюсы данного подхода: вместо зоопарка из разных утилит, имеющих свои уникальные форматы аргументов, выдающих неожиданные результаты в зависимости от их версий, а в случае с awk и perl ещё и необходимости изучения сразу двух совершенно разных языков программирования каждый с собственным синтаксисом для написания мини-программ (!!!! а оно вам действительно надо для выполнения узкой задачи?) - вместо всего этого вы будете использовать только один инструмент, система команд которого и интерфейс параметров реализованы по единому стандарту. Дополнительные возможности даёт и объектная модель данных. Сам текст скриптов более читабелен, доступно поэтапное выполнение задач с сохранением результата тяжелых вычислений в памяти, что позволяет не повторять всё с самого начала много раз при отладке.

Примечание: ошибочно считать PowerShell инструментом Microsoft Windows, он уже давно является проектом с открытым исходным кодом и прекрасно работает на GNU/Linux. PowerShell входит в репозитарии многих популярных дистрибутивов, поэтому приведенный в статье анализ универсален для обоих ОС и любого типа сервера СУБД.

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

1. Сбор данных ТЖ

<config xmlns="http://v8.1c.ru/v8/tech-log">
<log history="3" location="c:\Logs\1C">
    <event>
        <ne property="name" value=""/>
        <eq property="p:processName" value="testdb"/>
    </event>
    <property name="all"/>
</log>
</config>

2. Чтение ТЖ и приведение его в более структурированный вид

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

> select-string "^" */*.log

rphost_8508/21080409.log:1:45:50.169000-15999,SCALL,3,process=rphost,p:processName=...
rphost_8508/21080409.log:2:45:50.169002-1,SCALL,3,process=rphost,p:processName=...
rphost_8508/21080409.log:68:45:50.216005-1,HASP,3,process=rphost,p:processName=testdb,OSThread=1828...

Для начала поработаем с метками времени в заголовках строк. Так как в ТЖ пишутся только минуты:секунды.микросекунды, а для решения задач могут потребоваться ещё и часы, то озаботимся извлечением номера часа из наименования файла. Для чтения всех строк без фильтрации используем регулярное выражение "^", но при необходимости всегда можно на этом шаге отфильтровать лишнее, но мы сразу этого делать не будем:

> $log = Select-String "^" */*.log | foreach { $_ -replace "^.*(\d\d)\.log:\d+","`$1" -replace "^\d\d:(?!\d\d:)","" }

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

Любые переменные, они же указатели объектов в PowerShell начинаются с символа доллара: $log. Значение присвоенное переменным живет в памяти пока вы не закроете консоль, поэтому скрипт можно писать постепенно, отлаживая каждый шаг.
select-string - команда PowerShell, как и все другие команды имеет сокращенные варианты, например для этой команды это sls, но я бы не рекомендовал злоупотреблять сокращениями. Регистр букв значения не имеет и в Linux и в Windows. Список всех команд можно посмотреть командой get-command, а помощь по каждой команде получить через get-help <команда> - это поможет писать скрипты когда подсказки недоступны. Чтобы вывести значение переменной на экран просто введите его наименование в консоли.
В PowerShell пайпы устроены аналогично bash, передача данных в следующую команду идёт с помощью вертикальной черточки |
foreach {} - обработка поступившего через пайп массива строк в цикле. Причем это сокращенный вариант команды Foreach-Object. Встречаются и экстремальное сокращение в виде % {}. Каждый элемент массива ловится внутри цикла при помощи предопределенной переменной $_. Причем в данном случае мы просто его пишем в начале цикла и оно выводится для дальнейшей обработки. Для усвоения попробуйте сами проверить вывод команд select-string "^" "*.log" и select-string "^" "*.log" | foreach { $_ }.
Опция -replace производит поиск и замену подстрок с помощью регулярного выражения, аналог линуксовой утилиты sed. При группировках в регулярных выражениях группы ловятся при помощи предопределённых переменных $1, $2 и т.д. Замену можно проводить много раз подряд: первая замена убирает вставленные наименования файлов в начале строк, оставляя только 2 цифры (значение часа) : -replace "^.*(\d\d)\.log:\d+","`$1"
Вторая замена связана с тем, что, к сожалению, в 1С не особо парились с форматом технологического журнала и при обработке данных в нём возникает много ловушек, поэтому с ними придётся бороться, шаг за шагом. Код для выгрузки ТЖ писали Дядя Фёдор, Матроскин и Шарик, поэтому содержание некоторых полей (например Sql) в одном и том же файле могут быть в двойных кавычках, либо в одинарных кавычках либо вообще без кавычек. Также в содержание длинных полей могут произвольно писаться символы LF, которые при обработке командой grep или select-string интерпретируются как полноценное сочетание CRLF. Либо случается вообще невообразимое и пишется полноценный CRLF прямо в содержание поля (передаю привет тому кто писал выгрузку Context из rphost). В результате тексты полей Sql, Context, Sdbl. Txt, Descr и др. разбиваются на несколько строк, что сильно мешает дальнейшему анализу. Во втором replace мы убираем вставленные командой select-string час и номер строки, если дальше не стоит метка времени: -replace "^\d\d:(?!\d\d:)","".

Проверьте результат выполнения команды, набрав $log в следующей строке. Вы должны увидеть номер часа в начале каждой метки времени.

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

$log = $log -join " " -replace " (\d\d:\d\d:\d\d\.\d+-)","`n`$1" -split "`n"

Пояснения:

Опция -join " " превращает массив строк в одну строку с разделителем пробелом. Т.е. весь журнал теперь находится в одной строке;
Далее мы вставляем разделитель строк перед всеми метками времени, с помощью опции -replace и регулярного выражения;
Опция -split "`n" снова делит окончательную строку на массив строк.

Снова проверьте результат, набрав $log в консоли. Теперь все события журнала нормализованы и находятся каждый только в одной строке.

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

$log = $log  | foreach { $_ -replace "#tt\d+","#tt" }

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

3. Импорт ТЖ в таблицу

$table = $log | 
foreach { $t = $_ -match "\.\d+-(?<Duration>\d+),(?<Name>\w+),.*(?<Sql>Sql='.*'|Sql="".*""),Context='(?<Context>.*)'" ;
new-object object | add-member -NotePropertyMembers $matches -PassThru  }

Пояснения:

Разбил на три строки чтобы было удобнее смотреть на сайте;
Опция -match "..." снова производит поиск по регулярному выражению, но результатом у неё будут не найденные строки, а булевый (True или False), и чтобы подавить этот ненужный вывод мы просто присваиваем значение переменной $t.
Ещё одним результатом опции -match является предопределённый массив $matches, который заполняется найденными группами из регулярного выражения после выполнения этой команды и доступен для дальнейшего анализа. Конструкция (?<Sql>...) в регулярном выражении присваивает имена группам, через которые их можно достать из массива $matches;
Регулярное выражение выглядит громоздким, но зато с его помощью мы извлекаем поля Duration, Name, Sql и Context из строки технологического журнала. Эти поля помещаются в одноименные значения в массиве $matches.
Важно понимать, что в случае использования bash-скриптов все использованные в статье регулярные выражения будут практически точно такими же, не менее пугающими. Можно отпарсить любые другие поля в зависимости от поставленной задачи. Кроме того, в $matches ещё помещается целиком вся строка, которую можно использовать дальше для парсинга других полей при необходимости;
Обратите внимание, что значения поля Sql (а также Context) может оказаться окружённым как одинарными кавычками, так и двойными, в зависимости от употребления кавычек внутри текста запроса. Это ещё одна структурная ловушка ТЖ. На самом деле кавычек может вообще никаких может не быть, но мы этот случай не рассматриваем (так обычно бывает на очень коротких запросах).
Команда New-Object создает новый пустой объект для каждой строки ТЖ Команда Add-Member с указанными опциями добавляет свойства и значения вновь созданного объекта из массива находок $matches

Проверяем результат набрав в консоли $table. Теперь у нас в памяти есть таблица с ТЖ в структурированном виде, который можно начать анализировать.

4. Анализ таблицы ТЖ

Как вы понимаете, все данные ТЖ у нас сидят в оперативной памяти и если объёмы журнала в гигабайтах то могут возникнуть проблемы с производительностью. Поэтому фильтровать по идее нужно с самого начала. Но 16 ГБ есть сегодня практически у всех и мы анализируем короткий промежуток во время прогона Тест-центра поэтому пока все прекрасно помещается в оперативной памяти. Если всё же есть риск уйти в своп то в ходе работы нужно освобождать память от ненужных данных командой Remove-Variable.

Пример простейшего запроса: вывести все события DBMSSQL:

$table | where-object -property Name -eq DBMSSQL

Вывести события, в которых поминается форма документа СчетФактураВыданный:

$table | where-object {$_.context -like "*Документ.СчетФактураВыданный.ФормаОбъекта*"}

Сгруппируем все события DBMSSQL по тексту запроса и контексту:

$table | where-object -property name -eq DBMSSQL | group-object -property sql,context

То же самое что выше, но выведем только топ 3 запроса по количеству вызовов и развернем формат чтобы тексты читались на экране:

$table | where-object -property name -eq DBMSSQL |
group-object -property sql,context |
sort-object -property count -desc | select-object -first 3 | format-list

Наконец, напишем топ запросов по времени выполнения (Duration). В bash-скриптах для этого приходится освоить инструмент программирования awk с крайне своеобразным С-подобным синтаксисом, который на обучении даётся труднее всего. Писать будем с постепенным продвижением для отладки и лучшего усвоения:

$table | where-object -property name -eq DBMSSQL |
group-object -property sql,context | 
foreach { select-object -inputobject $_ -Expandproperty Group |
measure-object -property Duration -allstats }

Пояснения:

Разбито на четыре строки для облегчения прочтения на сайте. В консоли PowerShell это одна строка;
В начале так же как и в предыдущем примере группируем данные из $table по тексту запроса и контексту. Результат команды Group-Object не является объектом данных из строки журнала, а новым объектом со своими свойствами. Рекомендую прочитать документацию на эту команду. Этот объект содержит только единственную агрегатную функцию - количество вхождений в группу (свойство Count), которое в данном случае не требуется.
Следующая команда foreach {...} проходит в цикле каждый элемент группировки
Команда Select-Object вновь разворачивает каждую группировку обратно в таблицу с исходными данными, но зато теперь внутри большого блока из фигурных скобок мы работаем с каждым элементом группировки отдельно, получая возможность использовать агрегатные функции.
Команда Measure-Object является агрегатной функцией, с опцией -AllStats мы запрашиваем всю возможную статистику: минимальное, среднее, максимальное и прочие вычисления по указанному полю, в данном случае нас интересует свойство Duration.

Выведем промежуточный результат, он нас не устроит, т.к. мы не видим самого текста запроса. Он содержится в предопределенном свойстве Name результата команды группировки. Поэтому добавим его через пайп:

$table | where-object -property name -eq DBMSSQL |
group-object -property sql,context |
foreach { select-object -inputobject $_ -Expandproperty Group |
measure-object -property Duration -allstats | 
add-member -name "sql" -value $_.Name  -membertype noteproperty -passthru }

Команда Add-Member и добавит нам новое свойство Sql к объекту результата агрегатной функции Measure-Object.

Напоминаю, если в процессе написания скрипта вы не можете сходу вспоминать все параметры команды, надо использовать Get-Help, например Get-Help Add-Member:

PS /home/almaz> get-help add-member

NAME
    Add-Member
    
SYNTAX
    Add-Member -InputObject <psobject> -TypeName <string> [-PassThru] [<CommonParameters>]
    
    Add-Member [-MemberType] {AliasProperty | CodeProperty | Property | NoteProperty | ScriptProperty | PropertySet
    | Method | CodeMethod | ScriptMethod | Methods | ParameterizedProperty | MemberSet | Event | Dynamic 
    | InferredProperty | Properties | All} [-Name ] <string> [[-Value] <Object>] [[-SecondValue] <Object>]
    -InputObject <psobject> [-TypeName <string>] [-Force] [-PassThru] [<CommonParameters>]
    
    Add-Member [-NotePropertyName] <string> [-NotePropertyValue] <Object> -InputObject <psobject> 
    [-TypeName <string>] [-Force] [-PassThru] [<CommonParameters>]
    
    Add-Member [-NotePropertyMembers] <IDictionary> -InputObject <psobject> [-TypeName <string>] 
    [-Force] [-PassThru] [<CommonParameters>]

Ну и напоследок, нам нужны только первые 3 строчки результата в читабельном виде, поэтому добавим ещё команд и получим финальный результат:

$table | where-object -property name -eq DBMSSQL |
group-object -property sql,context |
foreach { select-object -inputobject $_ -Expandproperty Group |
measure-object -property Duration -allstats | 
add-member -name "sql" -value $_.Name  -membertype noteproperty -passthru } | 
sort-object -property sum -desc | select-object -first 3

Вывод:

$table | where-object -property name -eq DBMSSQL | group-object -property sql,context | foreach { select-object -inputobject $_ -Expandproperty Group | measure-object -property Duration -allstats | add-member -name "sql" -value $_.Name  -membertype noteproperty -passthru } | sort-object -property sum -desc | select-object -first 3

sql               : Sql='CREATE TABLE #tt (_Q_001_F_000RRef BINARY(16), _Q_001_F_001_TYPE BINARY(1), _Q_001_F_001_RTRef BINARY(4), _Q
                    _001_F_001_RRRef BINARY(16), _Q_001_F_002RRef BINARY(16), _Q_001_F_003RRef BINARY(16), _Q_001_F_004RRef BINARY(16
                    ), _Q_001_F_005RRef BINARY(16), _Q_001_F_006 DATETIME, _Q_001_F_007RRef BINARY(16), _Q_001_F_008_TYPE BINARY(1), 
                    _Q_001_F_008_RTRef BINARY(4), _Q_001_F_008_RRRef BINARY(16), _Q_001_F_009 NUMERIC(21, 2), _Q_001_F_010 NUMERIC(21
                    , 2))', Форма.Записать : Документ.ПоступлениеТоваровУслуг.Форма.ФормаДокументаТовары Документ.ПоступлениеТоваровУ
                    слуг.МодульОбъекта : 557 : ПроведениеСервер.ГрупповоеПерепроведение(ЭтотОбъект));   ОбщийМодуль.УчетНДСПереопредел
                    яемый.Модуль : 1654 : СчетФактураОбъект.Записать(РежимЗаписиДокумента.Проведение);          Документ.СчетФактураПолученн
                    ый.МодульОбъекта : 362 : ТаблицаПредъявленногоНДС = УчетНДСБП.ПодготовитьТаблицуПредъявленногоНДС(               ОбщийМодуль
                    .УчетНДСБП.Модуль : 2358 : Результат = Запрос.Выполнить();
Count             : 214
Average           : 15988
Sum               : 3421432
Maximum           : 15988
Minimum           : 15988
StandardDeviation : 0
Property          : Duration

sql               : Sql='CREATE TABLE #tt (_Q_000_F_000 NUMERIC(22, 2), _Q_000_F_001 NUMERIC(22, 2))', Форма.Записать : Документ.Пост
                    уплениеТоваровУслуг.Форма.ФормаДокументаУслуги Документ.ПоступлениеТоваровУслуг.МодульОбъекта : 400 : ПараметрыПр
                    оведения = Документы.ПоступлениеТоваровУслуг.ПодготовитьПараметрыПроведения(Ссылка, Отказ);         Документ.Поступление
                    ТоваровУслуг.МодульМенеджера : 1109 : Результат = Запрос.ВыполнитьПакет();
Count             : 226
Average           : 14971
Sum               : 3383446
Maximum           : 14971
Minimum           : 14971
StandardDeviation : 0
Property          : Duration

sql               : Sql='CREATE TABLE #tt (_Q_000_F_000RRef BINARY(16), _Q_000_F_001 DATETIME, _Q_000_F_002RRef BINARY(16), _Q_000_F_
                    003 BINARY(1), _Q_000_F_004 BINARY(1), _Q_000_F_005RRef BINARY(16), _Q_000_F_006TRef BINARY(4), _Q_000_F_006RRef 
                    BINARY(16), _Q_000_F_007 NVARCHAR(9) COLLATE DATABASE_DEFAULT, _Q_000_F_008_TYPE BINARY(1), _Q_000_F_008_RRRef BI
                    NARY(16), _Q_000_F_009RRef BINARY(16), _Q_000_F_010RRef BINARY(16), _Q_000_F_011 DATETIME, _Q_000_F_012 NUMERIC(1
                    , 0), _Q_000_F_013 NVARCHAR(10) COLLATE DATABASE_DEFAULT, _Q_000_F_014 NVARCHAR(3) COLLATE DATABASE_DEFAULT, _Q_0
                    00_F_015 DATETIME, _Q_000_F_016 NVARCHAR(15) COLLATE DATABASE_DEFAULT, _Q_000_F_017 DATETIME, _Q_000_F_018 NVARCH
                    AR(15) COLLATE DATABASE_DEFAULT, _Q_000_F_019 DATETIME, _Q_000_F_020 NUMERIC(10, 0), _Q_000_F_021 DATETIME, _Q_00
                    0_F_022 BINARY(1), _Q_000_F_023RRef BINARY(16), _Q_000_F_024 NUMERIC(15, 2), _Q_000_F_025 NUMERIC(14, 2), _Q_000_
                    F_026 NUMERIC(14, 2), _Q_000_F_027 NUMERIC(14, 2), _Q_000_F_028 NUMERIC(14, 2), _Q_000_F_029 NUMERIC(14, 2), _Q_0
                    00_F_030 BINARY(1), _Q_000_F_031 BINARY(1), _Q_000_F_032_TYPE BINARY(1), _Q_000_F_032_RTRef BINARY(4), _Q_000_F_0
                    32_RRRef BINARY(16), _Q_000_F_033_TYPE BINARY(1), _Q_000_F_033_N NUMERIC(10, 0), _Q_000_F_034_TYPE BINARY(1), _Q_
                    000_F_034_T DATETIME, _Q_000_F_035 NUMERIC(6, 0), _Q_000_F_036RRef BINARY(16), _Q_000_F_037 NVARCHAR(50) COLLATE 
                    DATABASE_DEFAULT, _Q_000_F_038 NUMERIC(15, 2), _Q_000_F_039 NUMERIC(15, 2), _Q_000_F_040 NUMERIC(14, 2), _Q_000_F
                    _041 NUMERIC(14, 2), _Q_000_F_042 NUMERIC(14, 2), _Q_000_F_043 NUMERIC(14, 2))', Форма.Записать : Документ.Реализ
                    ацияТоваровУслуг.Форма.ФормаДокументаТовары Документ.РеализацияТоваровУслуг.МодульОбъекта : 902 : ПроведениеСерве
                    р.ГрупповоеПерепроведение(ЭтотОбъект));     ОбщийМодуль.УчетНДСПереопределяемый.Модуль : 1654 : СчетФактураОбъект.За
                    писать(РежимЗаписиДокумента.Проведение);            Документ.СчетФактураВыданный.МодульОбъекта : 353 : ПараметрыПроведения
                     = Документы.СчетФактураВыданный.ПодготовитьПараметрыПроведения(Ссылка, Отказ);                     Документ.СчетФактураВыданный.М
                    одульМенеджера : 2764 : Результат = Запрос.ВыполнитьПакет();
Count             : 146
Average           : 15974
Sum               : 2332204
Maximum           : 15974
Minimum           : 15974
StandardDeviation : 0
Property          : Duration

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

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

5. Бенчмарк Powershell vs Perl

Касательно производительности утилит, линуксовые утилиты на данный момент работают быстрее чем команды PowerShell. Но начиная с 7 версии в PowerShell Core (не путайте с Powershell версии 5.1 который встроен в Windows 10) появилась возможность выполнять команды многопоточно. На многоядерных процессорах имеются реальные шансы догнать однопоточную методику анализа в bash, описанную в статье ИТС, которой конкретно и обучают на курсах. Но нужно понимать, что план выполнения задачи должен быть продуман так, чтобы получить все профиты от многопоточности, например не сливать сразу все обработанные логи в один файл. Конечно и в bash есть способы многопоточного выполнения команд, но эту специфику оставим в запасе для тех кто собирает ТЖ терабайтами.

Ниже два сравнительных бенчмарка, выполненных на чистом линуксе c 6-ядерным ноутбучным процессором Core i5 8-го поколения. Задача: переписать все события логов ТЖ из папки объемом 10 ГБайт в надежный однострочный формат, убрав символ LF из текстов полей.

А. Классический способ с однострочной программой Perl, изложенный в профильных статьях (попробуйте его понять или зазубрить):

time (cat rphost_*/*.log | perl -n -e 'if (/^\d\d:\d\d\.\d+/) {$event =~ s/\n/<line>/g; print $event."\n"; $event = "";} $event .= $_; END{print $event."\n"};' >res.txt)
( cat rphost_*/*.log | perl -n -e  > res.txt; )  
36,44s user 23,54s system 77% cpu 1:17,15 total

Результат: 1 мин 17 секунд.

Б. Многопоточный способ в PowerShell:

measure-command { dir "rphost_*/*.log" | % -parallel { (gc $_ -raw)
 -replace "`n(?!\d\d:\d\d\.\d+-)"," $1" -replace "`r(?!\d\d:\d\d\.\d+-)"," $1" | 
 out-file "$($_.FullName).txt" } }

Days              : 0
Hours             : 0
Minutes           : 1
Seconds           : 18
Milliseconds      : 307
Ticks             : 783071855
TotalDays         : 0,000906333165509259
TotalHours        : 0,0217519959722222
TotalMinutes      : 1,30511975833333
TotalSeconds      : 78,3071855
TotalMilliseconds : 78307,1855

Результат: 1 мин 18 секунд, проигрыш всего 1 секунда. Мне снова не пришлось писать программу в программе. А если бы процессор был 8-ядерный?

P.S.:Позже объяснение одинаковости результата было найдено: оба способа уперлись в пропускную способность дисковой системы SSD).