Анализ взаимоблокировок

Вступление

Анализ взаимоблокировок описан на ИТС, там же пошаговая инструкция. Предлагают анализировать файл технологического журнала в блокноте. Ниже Bash-скрипт для получения информации из технологического журнала по событиям TTIMEOUT, TDEADLOCK, TLOCK.

Пропустим установку Bash и сбор технологического журнала.

Упрощенная (первая) версия.

egrep '^[0-9][0-9].{10,24},TLOCK.*WaitConnections=[0-9]' -h -R \
| awk -F'(:.{8,21},TLOCK.*t:connectID=)|(,SessionID=.*,Regions=)|(,Locks=.*WaitConnections=)|(,connectionID=)' \
'BEGIN {print "#!/bin/bash" > "2step.sh"} \
{cow[$3,$2,$1]="egrep '\''^"$1"\.{10,25},TLOCK.*t:connectID="$2".*,Regions="$3".*WaitConnections="$4"'\'' -h -R"; \
tiger[$3,$2,$1]="egrep '\''^"$1"\.{10,25},TLOCK.*t:connectID="$4".*,Regions="$3".*WaitConnections=,'\'' -h -R"; \
timeout[$3,$2,$1]="egrep '\''^"$1"\.{10,25},TTIMEOUT.*t:connectID="$2".*WaitConnections="$4"'\'' -h -R";} \
END {for (item in cow) {print cow[item]"\n"timeout[item]"\n"tiger[item]"\n"tiger1[item] >> "2step.sh"; }}' \
; ./2step.sh

Комментарии к коду:
1.    выбираем возможные жертвы с непустым временем ожидания. Предполагаем, что порядок тегов событий TLOCK не изменяется.
2.    разделители подобраны таким образом, что $1 минута события, $2 ID соединения жертвы, $3 область блокировки, $4 ID соединения виновника
3.    очищаем файл шаблона запроса 2step. Первая строка командного скрипта bash должна быть стандартной #!/bin/bash.
4.    заполняем текстовые переменные cow (жертва), tiger (виновник), timeout для шаблона запроса egrep.
5.    эти шаблоны предполагают, что минута времени виновника и жертвы совпадают. Конечно, можно проверять предыдущую минуту, например "egrep '\''^"$1-1"\.{10,25},TLOCK.*t:connectID="$4".*, Regions="$3".*WaitConnections=,'\'' -h -R"; и более ранние события. Но мы не будем распространятся в эту сторону: такие ситуации могут возникать только при очень длительных блокировках, которые являются совершенным злом, их необходимо анализировать отдельно. Очень трудно было напечатать одинарную кавычку в шаблон из кода awk. Наконец нашел конструкцию: внутри двойных кавычек открывается одинарная кавычка, слэш одинарная кавычка, одинарная кавычка. На выходе имеем одинарную кавычку.
6.    после обработки событий TLOCK всех возможных жертв, выводим в файл 2step запрос по шаблону
7.    выполняем файл 2step.sh. Выходят события жертвы блокировки, виновника блокировки, запись TTIMEOUT.

Первая версия прекрасно работает, но есть возможности ее улучшить: дополнительно группировать события по области блокировки (Regions), добавить события DEADLOCK.

Основная версия скрипта:

#!/bin/bash
egrep '^[0-9][0-9].{10,24},TLOCK,.*WaitConnections=[0-9]' -H -R --include "200311*.log" \
| awk -F'(^.{1,20}\/)|(.log:)|(:.{8,21},TLOCK,.*t:connectID=)|(,SessionID=.*,Regions=)|(,Locks=.*,WaitConnections=)|((,connectionID=)|(,Context=))' \
'BEGIN {print "#!/bin/bash" > "2step.sh"} \
{gsub("'\''",".",$5) \
; ord[$3,$5,$4]="Time"$3"Regions"$5"Tiger"$6"EndOrder" \
; cow[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TLOCK.*t:connectID="$4".*,Regions="$5".*WaitConnections="$6"'\'' -h -R --include "$2".log" \
; tiger[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TLOCK.*t:connectID="$6".*,Regions="$5".*WaitConnections=,'\'' -h -R --include "$2".log" \
; deadlock[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TDEADLOCK.*t:connectID="$4".*DeadlockConnectionIntersections=."$4"."$6"'\'' -h -R --include "$2".log" \
; timeout[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TTIMEOUT.*t:connectID="$4".*WaitConnections="$6"'\'' -h -R --include "$2".log";} \
END {for (K in ord) \
{print ord[K]cow[K]"\n"ord[K]timeout[K]"\n"ord[K]deadlock[K]"\n"ord[K]tiger[K]"\n"ord[K]"echo "; }}' \
| sort -rnb \
| awk -F'^.*EndOrder' '{print $2;}' >> "2step.sh" \
; ./2step.sh >> "result.txt"

Комментарии к коду: скрипт запускать из среды Bash в каталоге, где собраны подкаталоги rphost за день. В моем случае объем за день 3 Гб, 4 каталога rphost, 66 файлов. Время работы скрипта на моем компьютере – 10 Минут. Скрипт находит события не только по которым зафиксировано TTIMEOUT или TDEADLOCK, но и ожидания на блокировках.
1.    Выбираем файлы по маске, например 200311*.log с событиями TLOCK, которые имели ожидание. Выборка включает имя файла.
2.    Разделители awk подобраны так, что: $2 краткое имя файла, $3 Минута события, $4 ConnectID жертвы, $5 Область блокировки, $6 ConnectID виновника. Оказывается, после ConnectID виновника может быть тег connectionID ИЛИ Context. Порядок тегов очень важен.
3.    Очищаем файл шаблона запроса 2step. Первая строка командного скрипта bash должна быть стандартной #!/bin/bash.
4.    Область блокировки может содержать одинарные кавычки, от этого страдает построение шаблона запроса. Заменяем одинарные кавычки на точку.
5.    Заполняем выражение упорядочивания: область, виновник, жертва.
6.    Заполняем текстовые переменные cow (жертва), tiger (виновник), timeout, deadlock для шаблона запроса egrep. Используем допущение, что час и минута всех файлов всех событий одной взаимоблокировки совпадают.
7.    Формируем шаблон запроса, между группами строк выводим echo
8.    Сортируем по области блокировки
9.    Убираем область сортировки, помещаем шаблон запроса в файл.
10.    Выполняем шаблон запроса.

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

Скрипт для поиска длительных транзакций

#!/bin/bash
printf "%15s\t\t%s", "Duration(sec.)", "Event string" \
; echo \
; egrep '^.{12,25},SDBL,.*Func=(Commit|Rollback)Transaction' -h -R --include "$@" \
| awk -F'(-|,)' '{printf "\n%4d\t%s", $2/1000000, $0}' \
| sort -rnb \
| head

Комментарии к коду:

1. Обязательная первая строка bash-скрипта
2. Заголовок таблицы
3. Отделяем заголовок от таблицы
4. Выбираем события SDBL, маску файла берем из параметра командной строки.
5. Печатаем длительность в секундах, строку события.
6. Сортируем
7. Выводим первые 10 строк.

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

#!/bin/bash
egrep '^[0-9][0-9].{10,24},TLOCK,.*WaitConnections=[0-9]' -H -R --include "$@" \
| awk -F'(^.{1,20}\/)|(.log:)|(:.{8,21},TLOCK,.*t:connectID=)|(,SessionID=.*,Regions=)|(,Locks=.*,WaitConnections=)|((,connectionID=)|(,Context=))' \
'BEGIN {print "#!/bin/bash" > "2step.sh"} \
{gsub("'\''",".",$5) \
;ord[$5]=$5 \
;cow[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TLOCK.*t:connectID="$4".*,Regions="$5".*WaitConnections="$6"'\'' -h -R --include "$2".log" \
;region[cow[$3,$5,$4]]=$5 \
;tiger[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TLOCK.*t:connectID="$6".*,Regions="$5".*WaitConnections=,'\'' -h -R --include "$2".log" \
;deadlock[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TDEADLOCK.*t:connectID="$4".*DeadlockConnectionIntersections=."$4"."$6"'\'' -h -R --include "$2".log" \
;timeout[$3,$5,$4]="egrep '\''^"$3"\.{10,25},TTIMEOUT.*t:connectID="$4".*WaitConnections="$6"'\'' -h -R --include "$2".log";} \
END {for (L in ord) { print "echo " >> "2step.sh"; \
for (K in cow) { if (region[cow[K]]==ord[L]) \
{print cow[K]"\n"timeout[K]"\n"deadlock[K]"\n"tiger[K] >> "2step.sh";} \
}}}' \
; ./2step.sh  >> "result.txt"

Обновление от 26/07/2022
Всем привет ! Решил упростить обработку, переделал колонки в AWK. Обратите внимание на один нюанс: обработка ищет проблемы не по ключевым словам TDEADLOCK, TTIMEOUT а анализирует все ненулевые ожидания.
 

#!/bin/bash
egrep '^.{20,30},TLOCK,.*WaitConnections=[0-9]' -H -R --include "*.log" \
| awk -F'(:)|(.connectID=)|(,SessionID.*,Regions=)|(,Locks=.*,WaitConnections=)|(,Context=)|(,connectionID=)' \
'BEGIN {print "#!/bin/bash" > "2step.sh"} \
{gsub("'\''",".",$9) \
;ord[$9]=$9 \
;cow[$2,$9,$8]="egrep '\''^"$2"\.{10,25},TLOCK.*t:connectID="$8".*,Regions="$9".*WaitConnections="$10"'\'' -h -R --include "$1 \
;region[cow[$2,$9,$8]]=$9 \
;tiger[$2,$9,$8]="egrep '\''^"$2"\.{10,25},TLOCK.*t:connectID="$10".*,Regions="$9".*WaitConnections=,'\'' -h -R --include "$1 \
;deadlock[$2,$9,$8]="egrep '\''^"$2"\.{10,25},TDEADLOCK.*t:connectID="$8".*DeadlockConnectionIntersections=."$8"."$10"'\'' -h -R --include "$1 \
;timeout[$2,$9,$8]="egrep '\''^"$2"\.{10,25},TTIMEOUT.*t:connectID="$8".*WaitConnections="$10"'\'' -h -R --include "$1;} \
END {for (L in ord) { print "echo " >> "2step.sh"; \
for (K in cow) { if (region[cow[K]]==ord[L]) \
{print cow[K]"\n"timeout[K]"\n"deadlock[K]"\n"tiger[K] >> "2step.sh";} \
}}}' \
; ./2step.sh  >> "result.txt"

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

 

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