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

26.07.22

База данных - HighLoad оптимизация

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

Вступление

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

 
 Даешь bash-скрипт анализа взаимоблокировок !


Пропустим установку 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"

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

 

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

tlock tdeadlock взаимоблокировок технологический bash context регулярные Богачев grep egrep awk gawk cat sed print printf echo sort logcfg

См. также

Анализируем SQL сервер глазами 1С-ника

HighLoad оптимизация Инструменты администратора БД Платформа 1С v8.3 Конфигурации 1cv8 Абонемент ($m)

Обработка для простого и удобного анализа настроек, нагрузки и проблем с SQL сервером с упором на использование оного для 1С. Анализ текущих зааросов на sql, ожиданий, конвертация запроса в 1с и рекомендации где может тормозить

1 стартмани

15.02.2024    7350    149    ZAOSTG    66    

95

Удаление строк из таблицы значений различными способами с замером производительности

HighLoad оптимизация Платформа 1С v8.3 Конфигурации 1cv8 Абонемент ($m)

Встал вопрос: как быстро удалить строки из ТЗ? Рассмотрел пять вариантов реализации этой задачи. Сравнил их друг с другом на разных объёмах данных с разным процентом удаляемых строк. Также сравнил с выгрузкой с отбором по структуре.

09.01.2024    5760    doom2good    48    

63

Опыт оптимизации 1С на PostgreSQL

HighLoad оптимизация Бесплатно (free)

При переводе типовой конфигурации 1C ERP/УТ/КА на PostgreSQL придется вложить ресурсы в доработку и оптимизацию запросов. Расскажем, на что обратить внимание при потерях производительности и какие инструменты/подходы помогут расследовать проблемы после перехода.

20.11.2023    8577    ivanov660    6    

75

ТОП проблем/задач у владельцев КОРП лицензий 1С на основе опыта РКЛ

HighLoad оптимизация Бесплатно (free)

Казалось бы, КОРП-системы должны быть устойчивы, быстры и надёжны. Но, работая в рамках РКЛ, мы видим немного другую картину. Об основных болевых точках КОРП-систем и подходах к их решению пойдет речь в статье.

15.11.2023    4999    a.doroshkevich    20    

72

Магия преобразований: ЖР, ТЖ, RAS/RAC, логи - универсальное решение Vector

Мониторинг Журнал регистрации Технологический журнал Абонемент ($m)

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

1 стартмани

13.11.2023    2880    4    AlexSTAL    0    

42

Начните уже использовать хранилище запросов

HighLoad оптимизация Запросы

Очень немногие из тех, кто занимается поддержкой MS SQL, работают с хранилищем запросов. А ведь хранилище запросов – это очень удобный, мощный и, главное, бесплатный инструмент, позволяющий быстро найти и локализовать проблему производительности и потребления ресурсов запросами. В статье расскажем о том, как использовать хранилище запросов в MS SQL и какие плюсы и минусы у него есть.

11.10.2023    15956    skovpin_sa    14    

97

«Монитор» – простой анализ производительности

Администрирование СУБД Технологический журнал Бесплатно (free)

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

21.09.2023    5661    Andreynikus    14    

79
Вознаграждение за ответ
Показать полностью
Комментарии
В избранное Подписаться на ответы Сортировка: Древо развёрнутое
Свернуть все
1. VKislitsin 958 20.03.20 16:41 Сейчас в теме
Николай, еще один плюс!
Было бы здорово, если после каждого скрипта был бы приведен образец вывода его результата.
Иначе приходится либо выполнять этот вывод мысленно, либо повторять у себя. А данные для повторения есть не всегда..
2. vasilev2015 2677 20.03.20 16:49 Сейчас в теме
(1) Здравствуйте !

Мне выгодно, чтобы Вы повторили у себя и если будут ошибки присылали. Буду признателен за любые замечания и предложения.
cleaner_it; +1 Ответить
3. VKislitsin 958 20.03.20 17:30 Сейчас в теме +0.1 $m
(2) Николай, я отвечу длинно :)
Не знаю, как другие, но я практически никогда не использую чужие скрипты в том виде, как они опубликованы. При этом всегда их изучаю, чтобы что-то подсмотренное перенять и применить в своей работе.

Вот здесь, например, мне интересно было каким образом Вы получили имя файла в строке для awk. Я вижу что его подставляет в начало каждой строки egrep. Но, в таком случае, контексты теперь уж точно обрезаются только до первой строки. По крайней мере, так мне сообщает мой "мысленный вывод результата". Уж у TLOCK-ов то контекст точно не однострочный. Или я не прав?

Кроме того, как я уже писал, для запуска скрипта в том виде, как он опубликован, нужны подходяще собранные логи. У меня, например, сейчас нет подходящих. Рыться в архивах? Ждать когда же вылезет какая-нибудь взаимоблокировка? Так они устранены давно уже. Моделировать специально для проверки скрипта? Всё это слишком трудозатратно, по крайней мере, пока нет реальной потребности решить проблему.

Насчет ошибок и отзывов: вот я почему-то думаю, что прямо сейчас, по прочтению статьи, вряд ли кто-то бросится запускать это у себя. Может быть отметят в избранное, чтобы вернуться когда понадобится. Поэтому фидбэка тут особо полезного не получить. А статья могла бы быть информативнее с примерами вывода. Но это конечно, лишь мое скромное мнение.
TerveRus; jaroslav.h; user843241; berezdetsky; o.nikolaev; Xershi; MVK80; +7 Ответить
4. vasilev2015 2677 20.03.20 18:35 Сейчас в теме
(3) Добавил символическое вознаграждение за длинный ответ ))
В моем ТЖ контекст только в TTimeout, TDeadlock одной строкой.
Файл настройки ТЖ обычный.

Скрипт кому-то пригодится. Буду ждать.
5. VKislitsin 958 20.03.20 18:40 Сейчас в теме
(4) Спасибо :)
А вообще, интересно Вы с awk-ом работаете. Мне раньше не встречалось, чтобы разделители через "или" набирались.
И корова с тигром - забавно :)
15. Sloth 379 21.03.20 21:53 Сейчас в теме
(5)
А вообще, интересно Вы с awk-ом работаете. Мне раньше не встречалось, чтобы разделители через "или" набирались.

Тоже оценил такую конструкцию, однако интересно сколько вычислительного времени расходуется на такой разбор ...
16. vasilev2015 2677 21.03.20 23:30 Сейчас в теме
(15) указал, что скрипт обрабатывает 3Гб за 10 минут. Для любого регулярного выражения awk, egrep условия проверяются последовательно. Как известно, конструкция '^.{12,25},CALL,.*' работает на порядок быстрее, чем ',CALL,.*'
17. Sloth 379 21.03.20 23:33 Сейчас в теме +0.1 $m
(16) дык я к тому и озадачился, что возможно без использования подобной конструкции скрипт бы работал, скажем, 3 минуты, но стал бы при этом менее читаемым ...
18. vasilev2015 2677 21.03.20 23:35 Сейчас в теме
(17) да, интересно. Буду признателен, если замеряете скорость для другого способа и сравните.
25. TerveRus 12.11.20 13:26 Сейчас в теме
(4) а обычный файл настройки ТЖ - это какой?
Можно где-нибудь забрать его себе? Очень хочется пустить скрипт в работу)
26. vasilev2015 2677 12.11.20 15:35 Сейчас в теме
(25) Здравствуйте ! настройки смотрите тут infostart.ru/public/825405/
6. Vladimir Litvinenko 2865 21.03.20 00:56 Сейчас в теме
Спасибо! Полезно как для практического применения, так и для популяризации bash/Linux инструментов.

Не сочтите за придирку, но хотелось бы видеть немного комментариев в самом коде, хотя бы ссылающихся на пункты пояснений, которые приводятся до этого в статье. Вы используете \ для много строчных выражений. А это позволяет использовать комментарии прямо в скрипте:
printf '3e2' | \
# comment
egrep --only-matching '3'

Таким образом код можно разделять на более читаемые логические блоки.

Иногда кстати можно услышать, что записанный в баше RegExp - это write only code. Потому что никому кроме автора редактировать не удаётся. Но такой ситуации можно избежать, если снабжать отдельные строки комментариями прямо в коде. Ведь передавать такой код например коллеге удобнее без дополнительных ссылок на статьи ))

Планируете ли Вы ещё писать на эту тему? Очень интересные приёмы демонстрируете.
YPermitin; +1 Ответить
8. vasilev2015 2677 21.03.20 10:37 Сейчас в теме
(6) Здравствуйте !

Про комментарии в коде думал, но есть нюансы:

1. Хотелось однообразия, а после каждой строки не получилось.
Например, awk разбит на несколько строк - внутри не поставить #
2. На stackoverflow нет комментариев после каждой строки
3. Если скрипт потеряет связь со статьей - для меня скорее недостаток

Поэтому я сделал коммернтарии для каждой строки, но поместил их после
7. Xershi 1473 21.03.20 09:54 Сейчас в теме
У Гилева как то видел обработку, которая в режиме онлайн показывает, что происходит в базе. У вас нет аналога?
Это решение уже постфактум даёт анализ для исправления.
9. vasilev2015 2677 21.03.20 10:38 Сейчас в теме
(7) Здравствуйте !

Нет, пока нет аналога. ))
10. Xershi 1473 21.03.20 10:41 Сейчас в теме
(9) недавно провел обновление УТ 11.4.1 на 11.4.7.
И выполнил проверку кода конфигурации.
Нашёл множество ошибок.
И хотел этот массив обработать быстро и наглядно.
Не писали парсер, который так сделает?
Обновление я уже поставил на рабочую базу. И ошибки исправлены.
Но хотелось бы иметь такой инструмент.
11. vasilev2015 2677 21.03.20 10:46 Сейчас в теме
(10) да, у меня была похожая ситуация.
в статье https://infostart.ru/public/1095079/
парсер для файла ОтчетОСравнении.txt сравнения конфигураций.
12. Xershi 1473 21.03.20 11:45 Сейчас в теме
(11) эту я видел. Тут же речь немного о другом.
13. пользователь 21.03.20 14:06
(0) статьи очень интересные.
Обязательно продолжайте!
14. vasilev2015 2677 21.03.20 15:35 Сейчас в теме
(13) спасибо, буду стараться.
YPermitin; +1 Ответить
19. buganov 200 22.03.20 13:18 Сейчас в теме
20. Serg O. 224 27.03.20 12:30 Сейчас в теме
Про анализ каких логов идёт речь? логи SQL или логи 1С сервера?
если логи 1С - технологический журнал...
то его сначала включить надо... аккуратно иначе логи не 3 Гб будут а 300 Гб

если логи - это лог тех.журнала 1С сервера... то про какую версию это всё?
8.3.XX разные тем более 8.2 и 8.3 вообще

и ещё увидел во 2-ом скрипте ссылку на логи 2003 года?! это вы так "пошутили"?
--include "200311*.log"

я лично (да думаю и многие 1С-программисты) не очень то любят лезть в тех.журнал,
тем более анализировать его через BASH-команды... т.е. практически руками...

есть прекрасные инструменты и в 1С... и всякие внешние обработки и публикации
зачем ещё один "велосипед"... Вы конечно молодец, и так можно (если умеючи)

Ещё "комментарий"! - не все блокировки (взаимоблокировки DeadLock) отражаются в тех.журнале как прямо "блокировки"...
есть "ошибки" ERROR ... которые показываются пользователям как ошибка блокировки объекта...
или ошибка совместного доступа и т.д.
это те ошибка, которые можно "увидеть" в Журнале регистрации в 1С...
а некоторые блокировки вообще не поймать... без SQL-логов

я лично считаю, что "лучший" инструмент анализа тех.журнала у группы Гилёва gilev.ru
и бесплатный и легко "включаемый" - само всё анализируется... автоматически
и блокировок http://www.gilev.ru/latch/
и взаимо-блокировки http://www.gilev.ru/deadlock/
и долгие запросы - http://www.gilev.ru/querytj/
и анализ Журнала регистрации http://www.gilev.ru/status/

есть прекрасные статьи и видео от Андрея Бурмистрова... выступления на ИнфоСтарт - 2014, 2015, 2016г.

статьи от Андрея Бурмистрова
"Ускорение в 100 раз. Решаем проблему блокировок https://infostart.ru/public/629017/
Опять упало https://infostart.ru/public/205264/
система автоматизации анализа ошибок, связанных со скоростью работы 1С https://infostart.ru/public/861201/
ещё статьи
Ловля блокировок на связке "Microsoft SQL server - 1С" https://infostart.ru/public/1081863/
Gilev.Vyacheslav; shaykhelov; TerveRus; +3 Ответить
21. vasilev2015 2677 27.03.20 13:58 Сейчас в теме
(20) Здравствуйте !

В статье указано, что анализируем технологический журнал.

Предполагается, что читатель умеет настраивать ТЖ.
Для начинающих есть более подробная статья https://infostart.ru/public/825405

Тестировал на платформе 8.3.12, должно работать на (почти)всех платформах.
200311 - значит, 20 год, месяц 03.

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

Но мы теперь знаем, что сервис (deadlock) можно заменить на десять строчек кода.

Открыто, для всех.
VKislitsin; Sloth; +2 Ответить
22. Rioneri 96 01.09.20 23:51 Сейчас в теме +1 $m
Здравствуйте! Очень трудно было напечатать одинарную кавычку в шаблон из кода awk? Можно так - \x027 - это экранированный апостроф. Получается читабельно.
23. vasilev2015 2677 02.09.20 08:29 Сейчас в теме
(22) Здравствуйте ! Попробую.
24. Rioneri 96 03.09.20 00:29 Сейчас в теме
(23)Ноль лишний... правильно, конечно \x27
27. buganov 200 09.12.20 22:06 Сейчас в теме
Я для себя в последнее время открыл python с его асинхронностью. По итогу, разбор тлоков на 8Гб в 8 процессов формирует таблицу Виновник-Жертва примерно за 1.5 минуты на ноутбуке с i5-1035G1. Проблема баша в том, что он упирается в параллельное чтение и я в свое время не смог найти решения утилизировать все предоставленные для разбора логов ядра(8) процессора.
28. kuza_87 28 14.10.21 14:56 Сейчас в теме
В скрипте, не учитывается, что контекст переносится на следующую строку. В итоге результат без контекста.
29. vasilev2015 2677 14.10.21 16:53 Сейчас в теме
(28) Присылайте в личку фрагмент журнала, чтобы я его сохранил в файл, запустил скрипт и увидел ошибку.
Это позволит исправить скрипт.
30. pedchenko32 29.10.21 11:31 Сейчас в теме
$ /d/lock/FindByname.sh
awk: warning: escape sequence `\/' treated as plain `/'
awk: cmd. line:4: warning: escape sequence `\.' treated as plain `.'

В чем может быть проблема при запуске этого:
#!/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"
31. vasilev2015 2677 29.10.21 15:16 Сейчас в теме
(30) Здравствуйте !

это не проблема, а предупреждение что последовательность символов рассматривается как косая и точка.
32. pedchenko32 29.10.21 17:16 Сейчас в теме
Здравствуйте! Спасибо большое. Я понимаю, что для начинающих по другой ссылке, где задаем переменные? Здесь ord[$3,$5,$4]="Time"$3"Regions"$5"Tiger"$6"EndOrder" \ ? Скрипт обрабатывает только один файл?
33. vasilev2015 2677 29.10.21 23:29 Сейчас в теме
(32) здесь используются возможности программирования внутри оператора AWK.
Внутри AWK "крутится" цикл.
переменные $1...$6 - это значения колонок для каждой строки.
ord[..] - это многомерный массив.
Скрипт обрабатывает содержимое файлов по маске 200311*.log

к bash нужно привыкнуть, он необычный.
Почитайте описание скрипта, посмотрите как работает AWK.
34. pedchenko32 01.11.21 11:31 Сейчас в теме
35. cdiamond 233 02.06.22 09:43 Сейчас в теме
На настоящем линуксе не работают скрипты. Какая-то беда с кавычками в 2step.sh:
$ ./2step.sh
 -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
.*,Regions=a210b08c-a809-462a-8619-f61ed201d8ff.*WaitConnections=,: Слишком длинное имя файла
 -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
: Слишком длинное имя файла25,TDEADLOCK.*t:connectID=4546.*DeadlockConnectionIntersections=.4546.


начало файла выглядит так:
#!/bin/bash
egrep '^Reference84.REFLOCK\.{10,25},TTIMEOUT.*t:connectID=4546.*WaitConnections='
' -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
egrep '^Reference84.REFLOCK\.{10,25},TLOCK.*t:connectID='
.*,Regions=a210b08c-a809-462a-8619-f61ed201d8ff.*WaitConnections=,' -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
egrep '^Reference84.REFLOCK\.{10,25},TLOCK.*t:connectID=4546.*,Regions=a210b08c-a809-462a-8619-f61ed201d8ff.*WaitConnections='
' -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
egrep '^Reference84.REFLOCK\.{10,25},TDEADLOCK.*t:connectID=4546.*DeadlockConnectionIntersections=.4546.'
' -h -R --include 00:01.302128-74,TLOCK,4,process=rphost,p:processName=kb_erp,OSThread=11012,t:clientID=4997,t:applicationName=BackgroundJob,t:computerName=NBCS0009,t:connectID=4547.log
echo 
Показать
36. cdiamond 233 02.06.22 14:43 Сейчас в теме
(35) Разобрался, невидимые символы перевода строк с веб-страницы криво вставились в редактор )
37. vasilev2015 2677 02.06.22 14:54 Сейчас в теме
(36) Круто ! Удалось найти взаимоблокировки ? Или просто убедились, что их нет ?
38. cdiamond 233 02.06.22 17:27 Сейчас в теме
(37) Нашёл, проблема имеет место. Вручную ещё перепроверил в блокноте - всё верно показало!
Но просто как учил Богачев истинную причину таймаута трудно найти - TLOCK ставится платформой в обработке проведения при записи движений документа, сразу по 10 измерениям, то есть гранулярность отличная. Но запись конкретно в этот блокируемый регистр занимает миллисекунды, и записано очень мало строк. Похоже это всё обернуто дополнительной транзакцией длительных фоновых операций и задержку дает другой регистр. Получается надо шерстить по событиям всех регистров движений
39. Froloid 66 29.07.22 03:20 Сейчас в теме
(38) Что-то тут в тексте малость каша. То, что в сложных ситуациях причину таймаута сложновато найти - это Виктор верно сказал. Но вот предположения о причинах тут требуют уточнения:
Но запись конкретно в этот блокируемый регистр занимает миллисекунды, и записано очень мало строк
- сама запись вероятно и быстро, но вот у наборов записей бывают подписки и там всё бывает не быстро. Но на самом деле это не важно, так как блокировка удерживается до конца транзакции;
Похоже это всё обернуто дополнительной транзакцией длительных фоновых операций и задержку дает другой регистр
- тут 2 момента. 1 - каждое фоновое задание, это отдельный сеанс, он не может быть обёрнут в одну транзакцию ни с каким другим сеансом (как другим фоновым, так и в частности пользовательским из которого запустилось фоновое). 2
и задержку дает другой регистр
в основном, задержку даёт не регистр, а исполняемый код, запросы и ожидания на блокировках;
Получается надо шерстить по событиям всех регистров движений
- не знаю о каких событиях тут идёт речь, но если о TLOCK, то ни чего там по другим регистрам шерстить не надо.

В общем случае методика следующая:
1. Смотрим TTIMEOUT из него понимаем на какой таблице было ожидание, и какой connectID был виновником НАЧАЛА ожидания;
2. Смотрим по connectID виновника события SDBL фиксации или отмены транзакции, которая началось ранее или одновременно по отношению к нашему событию таймаута и закончилось позже начала нашего таймаута/тлока. И вот тут самое интересно что позже начала, а не позже окончания.

Тут-то и кроется основное расстройство для таких "анализаторов" как я. Я то ждал по молодости, что виновник удерживал блокировку все 20 секунд, но на практике часто тут получается цепочка ожиданий из которых в ТЖ виден только первый виновник. (Например, пытаемся заблокировать остатки по 2-м товарам и попадаем на ожидание от сеанса 1, который держит блокировку по первому товару 15 секунд. На 10-й секунде ещё сеанс 2 устанавливает блокировку по товару 2 тоже на 15 секунд.

В итоге мы видим таймаут в ТЖ, где виновник сеанс 1 и по sdbl понимаем, что он отпустил конфликтный ресурс ранее, чем мы словили таймаут). И чтобы найти других виновников необходимо вычислить по tlock'ам сеансы, которые блокировали конфликтный ресурс по пересекающемуся пространству не позже, чем завершилась транзакция сеанса 1. И в цепочке в общем случае может быть несколько таких виновников.

Чтобы это провернуть необходимо собирать в ТЖ как минимум все таймауты без ограничения по времени установки (так как виновник мог установить её мгновенно), а так же необходимо собирать поля блокировки для tlock'ов (эти 2 настройки могут приводить к очень большим файлам логов на нагруженных системах). Ну и ещё найти пересечение пространств у двух tlock'ов технически не так уж и просто (хотя если по этому пространству немного потенциальных виновников, то можно скинуть в один файл и найти глазами).
40. cdiamond 233 29.07.22 05:46 Сейчас в теме
(39) Я наверно сумбурно написал, но в моем частном случае оказалось можно поступить намного проще и не выстраивать цепочки событий в ТЖ. После того как скриптом находим обработку проведения и убеждаемся что там все чисто, гранулярность высокая и запись в регистр быстрая нужно составить список всех регистров, участвующих в движениях документа. Далее идем в менеджер каждого регистра и ищем ПриЗаписи. Подписка на это событие в менеджере регистра уже само пр себе редкость, так что виновник в виде неоптимального запроса находится невооруженным глазом. Чтоб убедиться замеряем длительность выполнения и дело раскрыто, Холмс.
То есть иными словами - иногда связь между проблемой и его источником проще и быстрее найти через конфигуратор, а не через события ТЖ.
41. user1935599 12.04.23 13:20 Сейчас в теме
Николай, добрый день.
Команда в bash egrep '^.{20,30},TLOCK,.*WaitConnections=[0-9]' -H -R --include "23041207.log" при считывании одного файла на 36Мб висит бесконечно долго, с загрузкой ЦП на 100% и ничего не выводит... При этом, есть файлы из этого же часа большего и меньшего размера, которые считываются нормально... Ситуация повторяется на 2х компьютерах... logcfg стандартный. Не сталкивались с таким?
Прикрепленные файлы:
23041207.log
42. angabanga5 30.01.24 16:09 Сейчас в теме
ну такое, у меня 8 гигов Тлоков Т деделоков и скрипт возвращает просто 0 в файл ткст, хотя обычный греп по моим дедлоком отрабатывает часа полтора)
43. vasilev2015 2677 31.01.24 13:29 Сейчас в теме
(42) Здравствуйте !

Надеюсь, у вас журнал событий полный (все поля событий).
При выполнении bash скрипта сделайте отладку - смотрите результат выполнения от простого к сложному, от строки к строке.
Не удается разобраться самостоятельно - присылайте (фрагмент) ТЖ, я проверю.

Или можете просто написать, что разбираться неохота, но скрипт плохой ))
Оставьте свое сообщение