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

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

Цель

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

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

Для тех, кто не знаком, статья по сути приводит готовые примеры, которые можно начать использоваться "как есть".

У этой статьи нет цели дать полное описание всех свойств инструментов. 

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

Существует много способов анализа технологических журналов, нет цели рассказать о них всех. 

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

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

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

Как мне настроить технологические журналы и проделать то, что написано в статье

Технологические журналы настраиваются в файле logcfg.xml

Также на ИТС можно найти методику по настройке технологического журнала с целью мониторинга

Для отработки материала в данной статье вам понадобится

- клиент-серверный вариант технологической Платформы 1С:Предприятие (примеры готовились на примере 8.3.10)

- СУБД (примеры готовились для MS SQL Server)

- информационная база, как вариант, СНТ, входящий в Корпоративный Инструментальный Пакет

На рабочем сервере настраиваем технологический журнал в файле (logcfg.xml)

<?xml version="1.0" encoding="UTF-8"?>

<config xmlns="http://v8.1c.ru/v8/tech-log">

<log location="C:\LOGS\FULL" history=“72">

<event>

<ne property="Name" value=""/>

</event>

<property name="all"/>

</log>

</config>

Это полный журнал, который будет собираться в директорию "C:\LOGS\FULL".

Если вы это делаете на рабочих серверах, то следите за местом. (Лучше, конечно, не настраивать полный журнал,  а указывать только те события, которые нужны для анализа вам сейчас.)

Для целей этой статьи нам нужен полный журнал.

Подробнее об инструментах

Речь пойдет сначала об "утилитах" bash/sh.

Для пользователей linux не нужно практически ничего, они уже имеют "утилиты".

Для пользователей windows существуют варианты:

- c windows 10 есть встроенный bash (пока в beta-версии) (https://msdn.microsoft.com/en-us/commandline/wsl/about)

- есть инструмент cygwin (https://www.cygwin.com/)

- есть git bash (который в своей поставки содержит всё нужное) (https://git-scm.com/)

Авторы в os windows предпочитают использовать git bash, т.к. по сути его запуск и подготовка к использованию сводятся к клику правой кнопкой мыши в директории с журналами и выбором кнопки git bash here.

Все примеры в этой статье приводятся из расчета, что автор

- либо выполнил cd C:\LOGS\FULL (или аналогичный путь у вас)

- либо запустил в windows git bash here в директории "C:\LOGS\FULL"

Т.е., если выполните pwd, вы увидите директорию "C:\LOGS\FULL"

Для знакомства также рекомендуется книга Скотт Граннеман «Linux Необходимый код и команды Карманный справочник»

Также рекомендуем книгу Джеффри Фридл «Регулярные выражения»

Первые шаги

Хочется очень коротко озвучить приемы, которые применяются периодически для решения простейших микро-задач (посмотреть какие файлы в директории и т.п.).

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

(В целом, последнее замечание касается всей статьи).

Команды и утилиты

Копирование файла

сp <что_копировать> <куда_копировать>

Копирование с удаленной машины server

scp server:/var/dir/<что_копировать> /home/alex/<куда_копировать>

Переместить файл

mv <что_переместить> <куда_переместить>

Переименовать файл

mv <что_переместить> <куда_переместить>

Удалить файл

rm <что_удалить>

Удалить всё, включая поддиректории, без подтверждения

rm -rf <что_удалить>

Список файлов

ls

Список файлов в порядке «последние использованные - снизу» с информацией о правах и времени их модификации

ls -lhatr

Только список в одну колонку

ls -1

Только список в строку 

ls -1 | xargs

История команд

history

Найти файлы по имени в текущей директории

find . -name “16091011.log”

Найти файлы по размеру больше 10 Мб от корня файловой системы

find / -depth -size +10M

Найти файлы, старше 21:40 04.05.2017 (текущего года)

touch -t 05042140 ~/datastamp ; find . -newer ~/datastamp -exec ls -l {} \; rm ~/datastamp ;

Просто вывести file

cat file

Вывести и пролистать file

less file

Вывести первые 10 строк файла file

head file

Вывести первые N

head file -n 20

Вывести последние 10

tail

Вывести последние N

tail file -n 5

Следить за изменениями в файлах и выводить каждую секунду обновления:

tail -f <файл>

tail -f <множество_файлов*> (кроме «новых»)

Например:

tail -f rphost*/*.log

Конвеер pipe

|

cmd1 | cmd2

grep

Вывод строк, включающих соответствия выражению, из входного потока

grep  <выражение>

Поиск во всех подкаталогах

grep -r <выражение> 

Поиск в файлах

grep <выражение> <файлы>

Вывод только совпадающего фрагмента

grep -o <выражение>

Вывод только совпадающего фрагмента с использованием perl конструкций

grep -oP <выражение>

Вывести 5 строк до и после найденного выражения

grep <выражение> -C 5

Вывести совпадения, но не выводить имена файлов и пути

grep -h <выражение> <файлы>

grep -rh <выражение>

Вывести только определенное поле, например, ClientID=<номер> от строк, совпадающих с <выражением> (не выводя всю строку).

Например, выражение - ",EXCP,"

grep -oPh ',EXCP,\K(ClientID=\d+)' <файлы>

Поиск по журналам rphost за определенный час (12 часов)

grep <выражение> rphost*/*12.log

sed и perl

Поиск и замена

sed 's/найти/заменить/'

Вывести содержимое файла и заменить GUID-ы, адреса и номера портов на короткие имена:

cat file | sed -r 's/.{8}-.{4}-.{4}-.{4}-.{12}/{GUID}/g' | sed -r 's/\:[0-9]{4,5}/{PORT}/g' | sed -r 's/[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+/{ADDR}/g' 

Убрать всё с начала строки до выражения:

sed 's/^.*<выражение>//'

Убрать всё с выражения до конца строки:

sed 's/<выражение>.*$//'

Автор считает более удобным применять конструкцию

perl -pe 's/найти/заменить/'

в качестве альтернативы sed. Это вопрос предпочтений и незначительного выигрыша в производительности и удобстве.

Применить более одного раза (для всех вхождений):

perl -pe 's/найти/заменить/g'

awk

Программы awk

awk -F<delimiter> 'BEGIN { программа анализа} END {программа}'

Например, получить сумму по 2-ой колонке, если разделитель ;

awk -F';' '{sum+=$2;} END {print "Sum=" sum}'

Разделителем может быть даже слово

awk -F'Memory=' '{sum+=$2;} END {print "Sum=" sum}'

Группировка по входным данным (группируемое поле - $1, суммируется - $2)

awk '{count[$1]+=$2;} END {for (i in count) {print i " " count[i]}}'

Простые реальные примеры

Вывести top 10 совпадений с именами файлов, содержащий текст «Lock request timeout»

grep -r 'Lock request timeout' | awk -F: '{print $1}' | sort | uniq -c | sort -r | head

Выводить все события "исключения", возникающие сейчас в работающих процессах rphost

tail -f rphost*/*.log | grep ',EXCP,'

Вывести последние 10 событий фиксации или отката транзакции в журналах всех процессов rphost, длительностью более 20 секунд

cat rphost*/*.log | sed 's/-/,/' | awk -F',' '{if($2 > 20000000) {print}}' | grep ',SDBL,.*Transaction' | tail

Для удобства чтения

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

В bash перенос строки обозначается символом \

Т.е. по сути однострочная программа

cat rphost*/*.log | sed 's/-/,/' | awk -F',' '{if($2 > 20000000) {print}}' | grep ',SDBL,.*Transaction' | tail

может выглядеть и выполняться в таком виде

cat rphost*/*.log | \

sed 's/-/,/' | \

awk -F',' '{if($2 > 20000000) {print}}' | \

grep ',SDBL,.*Transaction' | \

tail

Для "сложных" одностроных программ такой подход в этой статье будет удобен, чтобы "программы менее походили на страшные заклинания", 

однако вряд ли вы его будете применять на практике (автор не применяет).

Оптимизация

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

Для того, чтобы программы выполнялись быстро, следует пользоваться правилами:

- Постараться как можно ближе к началу отобрать необходимый объем строк;

- Не оперировать миллионами строк;

- Помнить, что сортировки на сотнях тысяч строк могут быть дорогими.

Вы можете воспользоваться утилитой time для получения реального времени выполнения программы.

Например:

time cat rphost*/*.log | sed 's/-/,/' | awk -F',' '{if($2 > 20000000) {print}}' | grep ',SDBL,.*Transaction' | tail

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

Поэтому в этом случае можно сразу после первого pipe | добавить head, тем самым отобрав только 10 строк.

Если программа на 10 строках работает ожидаемо, то возможно, ожидаемое вами поведение сохранится и на большем числе строк (все зависит от вас).

Например:

cat rphost*/*.log | head | sed 's/-/,/' | awk -F',' '{if($2 > 20000000) {print}}' | grep ',SDBL,.*Transaction' | tail

Фильтрация событий технологического журнала Платформы

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

Например, события DBMSSQL содержат текст запроса и могут содержать контекст.

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

Попробуем получить все события DBMSSQL по определенному сеансу SessionID=2049

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"};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep "DBMSSQL.*SessionID=2049" | \

sed 's/<line>/\n/g' | \

less

Таким образом, ключевыми стали:

- преобразование события к одной строке

perl -n -e 'if (/^\d\d:\d\d\.\d+/) {$event =~ s/\n/<line>/g; print $event."\n"; $event = "";} $event .= $_; END{print $event."\n"};'

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

perl -pe 's/\xef\xbb\xbf//g' | \

- фильрация "утилитами" в привычном построчном режиме 

grep "DBMSSQL.*SessionID=2049"

- преобразование "обратно" к многострочному варианту после необходимых фильтраций

sed 's/<line>/\n/g'

Обратное преобразование не всегда необходимо, поэтому можно, например, заменять <line> на пробелы.

sed 's/<line>/ /g'

Альтернативным способом преобразования события к однострочному и обратно к многострочному выводу является способ с помощью awk

cat rphost*/*.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep 'DBMSSQL.*SessionID=2049' | sed -e "s/\xef\xbb\xbf/ /g" | head

Естественно, есть и другие способы.

Применение теории

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

Найдем 5 наиболее длительных транзакций.

Шаг 1. Получим только фиксации и откаты транзакций

grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" rphost*/*.log | head

Шаг 2. Получим все свойства события полностью

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | sed 's/<line>/\n/g' | head

Шаг 3. Оставляем события в одну строку (убираем "обратное" преобразование к многострочному варианту)

cat rphost*/*.log | perl -n -e 'if (/^\d\d:\d\d\.\d+/) {$event =~ s/\n/ /g; print $event."\n"; $event = "";} $event .= $_; END{print $event."\n"};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "SDBL.*Func=(Commit|Rollback)Transaction" | head

Шаг 4. Оставим только нужные поля.

- Например, длительность и первую строку контекста.

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | grep -oP "^\d+:\d+.\d+-\K(\d+),SDBL,.*(,Context=[\'\"]<line>[^(<line>)]*)" | sed 's/<line>//g' | sed 's/,SDBL,.*Context/,Context/g' | head

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | \

grep -oP "^\d+:\d+.\d+-\K(\d+),SDBL,.*(,Context=[\'\"]<line>[^(<line>)]*)" | \

sed 's/<line>//g' | sed 's/,SDBL,.*Context/,Context/g' | \

head

- Например, длительность и последнюю строку контекста.

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | perl -pe 's/^\d+:\d+.\d+-//g' | perl -pe 's/,SDBL,.*Context.*<line>[ \t]+/,Context=/g' | perl -pe 's/,SDBL,.*Context=/,Context=/g' | sed 's/<line>//g' | head

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,SDBL,.*Context.*<line>[ \t]+/,Context=/g' | \

perl -pe 's/,SDBL,.*Context=/,Context=/g' | \

sed 's/<line>//g' | \

head

В конструкции 's/^\d+:\d+.\d+-//g' мы избавились от полей до длительности события, чтобы в дальшейшем можно было удобно группировать.

Шаг 5. Пробуем применить группировку с помощью awk

awk -F, '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print s[i] " " sum[i]/count[i] " " count[i] " " i}}'

Результат:

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | perl -pe 's/^\d+:\d+.\d+-//g' | perl -pe 's/,SDBL,.*Context.*<line>[ \t]+/,Context=/g' | perl -pe 's/,SDBL,.*Context=/,Context=/g' | sed 's/<line>//g' | awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | sort -rnb | head -n 5

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "SDBL.*Func=(Commit|Rollback)Transaction.*Context" | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,SDBL,.*Context.*<line>[ \t]+/,Context=/g' | \

perl -pe 's/,SDBL,.*Context=/,Context=/g' | \

sed 's/<line>//g' | \

awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | \

sort -rnb | \

head -n 5

Найдем 5 наиболее длительных запросов к СУБД MS SQL Server.

На первый взгляд кажется, можно применить уже известный прием

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "DBMSSQL.*Context" | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,DBMSSQL,.*Context.*<line>[ \t]+/,Context=/g' | \

perl -pe 's/,DBMSSQL,.*Context=/,Context=/g' | \

sed 's/<line>//g' | \

awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | \

sort -rnb | \

head -n 5

Но проблема в том, что не все события DBMSSQL имеют контексты.

Поэтому группировка по первой или последней строке контекста не подойдет. 

Нужно научиться группировать тексты запросов.

Однако в них могут быть числовые параметры, различные имена временных таблиц (#tt17, #tt56), когда структура таких таблиц по сути одинаковая.

Таким образом, нам нужно научиться сворачивать тексты запросов так, чтобы "уникальные" имена пропали.

Для тренировки явно добавим опцию

grep -v 'Context'

исключения Context в нашу программу, хотя, понятно, что самые длительные запросы будут только среди запросов без контекста из-за использования grep -v 'Context'.

Но так проще для тренировки.

Шаг 1. Получаем запросы без контекстов.

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "DBMSSQL.*Sql" | \

grep -v 'Context' | \

perl -pe 's/<line>//' | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,DBMSSQL,.*Sql=/,Sql=/g' | \

head

Шаг 2. Можно убрать GUID и имена временных таблиц, номера строк и цифры.

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "DBMSSQL.*Sql" | \

grep -v 'Context' | \

perl -pe 's/<line>//' | perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,DBMSSQL,.*Sql=/,Sql=/g' | \

perl -pe 's/\w+-\w+-\w+-\w+-\w+/{GUID}/g' | \

perl -pe 's/\(\d+\)/({NUM})/g' | \

perl -pe 's/tt\d+/{TempTable}/g' | \

head

Результат:

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P "DBMSSQL.*Sql" | grep -v 'Context' | perl -pe 's/<line>//' | perl -pe 's/^\d+:\d+.\d+-//g' | perl -pe 's/,DBMSSQL,.*Sql=/,Sql=/g' | perl -pe 's/\w+-\w+-\w+-\w+-\w+/{GUID}/g' | perl -pe 's/\(\d+\)/({NUM})/g' | perl -pe 's/tt\d+/{TempTable}/g' | awk -F',Sql=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | sort -rnb | head -n 5

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P "DBMSSQL.*Sql" | \

grep -v 'Context' | \

perl -pe 's/<line>//' | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,DBMSSQL,.*Sql=/,Sql=/g' | \

perl -pe 's/\w+-\w+-\w+-\w+-\w+/{GUID}/g' | \

perl -pe 's/\(\d+\)/({NUM})/g' | \

perl -pe 's/tt\d+/{TempTable}/g' | \

awk -F',Sql=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {print sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | \

sort -rnb | \

head -n 5

Найдем 5 наиболее длительных вызовов.

В целом задача не отличается от предыдущих.

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

На самом деле он немного мешает. Решим задачу и изменим немного вывод awk:

awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {printf "%d %d %d %s\n",sum[i],sum[i]/count[i], count[i],i}}'

Результат:

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P ",CALL,.*,Context=" | perl -pe 's/<line>//' | perl -pe 's/^\d+:\d+.\d+-//g' | perl -pe 's/,CALL,.*Context/,Context/g' | perl -pe 's/,Interface=.*OutBytes=\d+//g' | awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {printf "%d %d %d %s\n",sum[i],sum[i]/count[i], count[i],i}}' | sort -rnb | head -n 5

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P ",CALL,.*,Context=" | \

perl -pe 's/<line>//' | \

perl -pe 's/^\d+:\d+.\d+-//g' | \

perl -pe 's/,CALL,.*Context/,Context/g' | \

perl -pe 's/,Interface=.*OutBytes=\d+//g' | \

awk -F',Context=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {printf "%d %d %d %s\n",sum[i],sum[i]/count[i], count[i],i}}' | \

sort -rnb | \

head -n 5

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

Используем тот же прием.

Однако, теперь нас интересует поле Regions.

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

Помним, что в этом случае поле WaitConnections= не пустое.

Результат:

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};' | perl -pe 's/\xef\xbb\xbf//g' | grep -P ",TLOCK,.*WaitConnections=\d+,Context" | perl -pe 's/^\d+:\d+.\d+-//g' | grep -P 'WaitConnections=\d+' | perl -pe 's/,Locks=.*$//g' | perl -pe 's/,TLOCK,.*Regions=/,Regions=/g' | sed 's/<line>//g' | awk -F',Regions=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {printf "%d %d %d %s\n", sum[i], sum[i]/count[i],count[i],i}}' | sort -rnb | head -n 5

или

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};' | \

perl -pe 's/\xef\xbb\xbf//g' | \

grep -P ",TLOCK,.*WaitConnections=\d+,Context" | \

perl -pe 's/^\d+:\d+.\d+-//g' | grep -P 'WaitConnections=\d+' | \

perl -pe 's/,Locks=.*$//g' | \

perl -pe 's/,TLOCK,.*Regions=/,Regions=/g' | \

sed 's/<line>//g' | \

awk -F',Regions=' '{sum[$2]+=$1; count[$2]+=1;} END {for(i in sum) {printf "%d %d %d %s\n", sum[i], sum[i]/count[i],count[i],i}}' | \

sort -rnb | \

head -n 5

Аналогичным способом разобранную конструкцию можно самостоятельно применять и для других задачи поиска top 5 <чего-то>.

Поиск по другим журналам

Если посмотреть, например, на access логи nginx, то мы видим пригодные для разбора журналы.

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

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

grep -P '24/Mar/2017:12'  /var/log/nginx/access.log | awk -F'|' '{if($6>40) {sum[$8]+=$6; count[$8]+=1; countall+=1;}} END {for (i in sum) {print count[i]*100/countall "% " sum[i] " " sum[i]/count[i] " " count[i] " " i}}' | sort -nb | head -n 50

Когда серверов много

Допустим, вы знаете, что в вашей сети серверы имеют имена вида server1, server2, ... server100.

Тогда мы можем вывести имена всех серверов примерно так:

for i in `seq 1 100`; do echo server$i; done

Но тогда, например, поиск EXCP по множеству серверов будет выглядеть примерно так:

for i in `seq 1 100`; do ssh server$i 'grep ,EXCP, /var/log/srv1cv8/logs/FULL/rphost*/*.log'; done

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

По этой причине лучше искать более точечно. Например, среди последних 1000 строк.

for i in `seq 1 100`; do ssh server$i 'tail -n 1000 /var/log/srv1cv8/logs/FULL/rphost*/*.log' | grep ",EXCP,"; done

Естественно через pipe | вы можете применять уже знакомые вам конструкции.

zip архивы

Технологические журналы рекомендуется складывать в zip архивы и не удалять какое-то время, т.к. они могут понадобиться для расследования проблем, которые были.

Естественно хранить такие архивы лучше не рабочих серверах, а в отведенных для этого хранилищах.

Но разархивировать журналы долго, хочется сразу начать искать по архивам.

Можно воспользоваться конструкцией вида

find * -name '*.zip' -print0 | xargs -0 -i -n 1 unzip -p {} '*.log' 2>/dev/null | grep ',EXCP,'

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

find //server/disk/2017-05-04/logs -name '*.zip' -print0 | xargs -0 -i -n 1 unzip -p {} '*/FULL/rphost*/*.log' '*/FULL/rmngr*/*.log' 2>/dev/null | grep ",EXCP," | head