Многострочный контекст событий

Постановка задачи.

Иногда для событий (например) DBMSQL контекст вызова содержит несколько строк. Пример  можно найти в ИТС, по ключевым словам awk –vORS=. Рассмотрим этот случай подробнее.

Bash-cкрипты тестировал на технологическом журнале, платформа 8.3.12, управляемые формы. Пропустим установку bash и сбор технологического журнала, желающие - смотрите //infostart.ru/public/825405/

Основная версия скрипта анализа дополнительного контекста событий.

#!/bin/bash
printf "%20s%20s%20s%20s", "Duration/Count", "Duration", "Count", "Context" \
; echo \
; time cat $@ \
| awk -vORS= '{ \
if ($0~"^[0-9][0-9].{10,30}DBMSSQL") { print "\n"$0;} \
else if ($0~"^[0-9][0-9]:[0-9][0-9]") { print "\n"; } \
else { gsub("\t","",$0); print "-"$0; } \
}' \
| egrep '^[0-9][0-9].{10,30}DBMSSQL.*,Context=' \
| awk -F'-|(,DBMSSQL.*?,Context=)' '{ \
LastContext=substr($NF,1,90); \
FirstContext=substr($2,1,90); \
if (length(FirstContext)<9) {FirstContext=substr($3,1,90);} \
Duration[LastContext]+=$2; Count[LastContext]+=1; \
} \
END { for (i in Count) \
{printf "%20d%20d%20d%5s%-90s\n", \
Duration[i]/(Count[i]*1000000),Duration[i]/1000000,Count[i],"\t",i \
}}' \
| sort -rnb \
| head -n20

Файл *.sh запускать в каталоге с подкаталогами rphost, параметры командной строки например ./script.sh "rphost*/200330*.log". Вызов команды начинается точка-слэш, иначе будет "command not found".

Построчный комментарий:
1.    Печать заголовка: частное "Duration/Count", колонки "Duration", "Count", "Context"
2.    Отделить заголовок от таблицы
3.    Начинаем замер времени, считываем файлы по маске - параметр командной строки
4.    Начинаем awk, обрабатываем каждую полученную строку. Опция –vORS= означает, что внутренней переменной ORS присвоено пустое значение. При выводе записей awk символ начала строки «\n», не будет добавляться автоматически, необходимо добавлять явно.
5.    Если событие DBMSSQL, то выводим исходную строку «с новой строки»
6.    Если строка начинается с минуты-секунды, то это какое-то событие, но не контекст и не DBMSSQL. Выводим символ перехода строки.
7.    Иначе выводим строку, из которой функция gsub убирает символы табуляции.  Выводим тире как разделитель.
8.    Закончена обработка awk (4).
9.    Фильтруем строки, содержащие DBMSSQL и контекст.
10.    Разделители подобраны так, что $2 = длительность, $2 = первая строка контекста, $3 = вторая строка контекста, $NF = последняя строка контекста.
11.    Вырезаем первые 90 символов для последней строки контекста. Это лучше для сортировки и вывода на экран.
12.    Вырезаем первые 90 символов для первой строки контекста. Это лучше для сортировки и вывода на экран.
13.    Если первая строка неинформативная, то используем вторую строку контекста.
14.    Суммируем длительность и количество событий для последней строки. Если нужна первая строка – здесь заменяем LastContext на FirstContext.
15.    после окончания обработки строк awk(10) начинаем цикл
16.    формат колонок "%20d%20d%20d%5s%-60s\n"
17.    печатаем накопленные переменные  в виде таблицы.
18.    Заканчиваем обработку итогов awk (10).
19.    Сортируем таблицу по убыванию
20.    Выводим первые 20 строк

Дополнительные бонусы.

Похожим скриптом можно искать объектное чтение. Для этого нужно добавить фильтр со словом "Version" в текст запроса. При объектном чтении платформа считывает версию объекта

| awk -vORS= '{ \
if ($0~"^[0-9][0-9].{10,30}DBMSSQL.{180,220}SELECT.{4,6}Version") { print "\n"$0;} \
else if ($0~"^[0-9][0-9]:[0-9][0-9]") { print "\n"; } \
else { gsub("\t","",$0); print "-"$0; } \
}' \

Группы строк, которые начинаются ^.{12,25},Context, появляются в технологическом журнале при запуске из толстого клиента внешних обработок. Поэтому в этой статье их не рассматриваем.

Модификация первого скрипта с группировкой по событиям. Можно найти события SDBL, длительность которых существенно отличается от соответствующих событий DBMSSQL. Это отличие (highly likely) говорит об большом объеме передаваемых данных от СУБД серверу приложений.

#!/bin/bash
printf "%10s%10s%10s%20s", "Duration", "Count", "Event", "Context" \
; echo \
; time cat */*.log \
| awk -vORS= '{ \
if ($0~"^[0-9][0-9].{10,30},(DBMSSQL|SDBL|EDS)") { print "\n"$0;} \
else if ($0~"^[0-9][0-9]:[0-9][0-9]") { print "\n"; } \
else { gsub("\t","",$0); print "-"$0; } \
}' \
| egrep '^[0-9][0-9].{10,30},(DBMSSQL|SDBL|EDS).*,Context=' \
| awk -F'-|(,(DBMSSQL|SDBL|EDS).*?,Context=)' '{ \
Event=$0; \
sub("^.{12}-[0-9]{0,9},","",Event); \
sub(",.*$","",Event); \
LastContext=substr($NF,1,120); \
FirstContext=substr($2,1,120); \
if (length(FirstContext)<9) {FirstContext=substr($3,1,120);} \
Duration[LastContext,Event]+=$2; Count[LastContext,Event]+=1; \
Context[LastContext,Event]=LastContext; Events[LastContext,Event]=Event; \
} \
END { for (i in Count) \
{printf "%10d%10d%10s%5s%-120s\n", \
Duration[i]/1000000,Count[i],Events[i],"\t",Context[i] \
}}' \
| sort -rnb \
| head -n90

Благодарю Виктора Богачева за предоставленные методические материалы и поддержку.

#!/bin/bash
printf "%20s%20s%20s%20s", "Duration", "Duration/Count", "Count", "Context" \
; echo \
; time cat $@ \
| awk -vORS= '{ \
if ($0~"^[0-9][0-9].{8,30}(DBMSSQL|SDBL)") { print "\n"$0;} \
else if ($0~"^[0-9][0-9]:[0-9][0-9].{8,30}Context") { print ",Context="; } \
else if ($0~"^[0-9][0-9]:[0-9][0-9]") { print "\n"; } \
else { gsub("\t","",$0); print "-"$0; } \
}' \
| egrep '^[0-9][0-9].{8,30}(DBMSSQL|SDBL).*,Context=' \
| awk -F'-|(,(DBMSSQL|SDBL).*?,Context=)' '{ \
LastContext=substr($NF,1,90); \
FirstContext=substr($2,1,90); \
if (length(FirstContext)<9) {FirstContext=substr($3,1,90);} \
Duration[LastContext]+=$2; Count[LastContext]+=1; \
} \
END { for (i in Count) \
{printf "%20d%20d%20d%5s%-90s\n", \
Duration[i]/1000,Duration[i]/(Count[i]*1000),Count[i],"\t",i \
}}' \
| sort -rnb \
| head -n20