А на ловца и зверь бежит, коллеги. Буквально недавно эпизодически bash'ил подведомственный техжурнал и делал заготовки скриптов. И тут свершилось - двухнедельный проект по анализу текущих проблем производительности. Без ограничений не обошлось, в лучших традициях жанра. Конфигурация УПП 1.3 - соответственно, древняя БСП, где подсистема оценки производительности еще на перечислениях. На продуктив ходить только под присмотром, самостоятельно ничего не менять, ничего не запускать. ЦУП нельзя, как сказали, уже пробовали - сбор данных тормозит систему. Заказчик привел адекватные аргументы в пользу поставленных ограничений. В итоге, из доступных инструментов остались логи технологического журнала и счетчики производительности, которые складываются на отдельный тестовый сервер. Там же развернута копия базы. Если бы не скрипты, то тогда вообще непонятно бы было, что со всем этим делать.Используемый logcfg.xml:
<?xml version="1.0"?> <config xmlns="http://v8.1c.ru/v8/tech-log"> <dump create="false"/> <log location="f:\tech_log\events" history="12"> <event> <eq property="name" value="call"/> </event> <event> <eq property="name" value="scall"/> </event> <event> <eq property="name" value="sdbl"/> </event> <event> <eq property="name" value="dbmssql"/> </event> <property name="all"/> </log> <log location="f:\tech_log\excp" history="12"> <event> <eq property="name" value="excp"/> </event> <property name="all"/> </log> <log location="f:\tech_log\long_events" history="12"> <event> <ne property="name" value=""/> <ge property="Durationus" value="3000000"/> </event> <property name="all"/> </log> <log location="f:\tech_log\tlocks" history="12"> <event> <eq property="Name" value="TLOCK"/> </event> <property name="all"/> </log> <log location="f:\tech_log\deadlocks" history="12"> <event> <eq property="Name" value="TLOCK"/> <ne property="WaitConnections" value=""/> </event> <event> <eq property="Name" value="TTIMEOUT"/> </event> <event> <eq property="Name" value="TDEADLOCK"/> </event> <property name="all"/> </log> </config>
Общий объем логов для анализа составил порядка 230 гигабайт. Для получения первичных данных использовалось 15 скриптов. Данных разбора оказалось вполне достаточно для определения участков начала анализа. Были выявлены и проанализированы эскалации на блокировках MSSQL, взаимоблокировки на управляемых блокировках и неоптимальные запросы.
После первого дня стало понятно, что было бы неплохо иметь какой-нибудь скрипт, который будет запускать все остальные скрипты. При этом желательно параллельно, чтобы загрузить выделенные ресурсы по максимуму. После часового сеанса гуглотерапии был написан запускатор.
Реализованы два варианта запуска:
$ bash main.sh /e/log_2017_08_30 - анализирует данные в каталоге e/log_2017_08_30, создает в каталоге скрипта подкаталог log_2017_08_30 и складывает в него результаты разбора
$ bash main.sh /e/log_2017_08_30 /f/result/2017_08_30 - анализирует данные в каталоге /e/log_2017_08_30 и складывает в /f/result/2017_08_30 результаты разбора
#!/bin/bash
#main.sh - one script to rule them all
#scr/* script_dir
#$1 tech_log_dir #$2 result_dir if [ "$1" = "" ] then echo 'set param tech_log_dir (1)' exit fi tech_log_dir=$1 if [ "$2" = "" ] then result_dir=$(basename $1) else result_dir=$2 fi if ! [ -d $result_dir ] then mkdir $result_dir fi for i in scr/*.sh; do $i $tech_log_dir $result_dir & done
После запуска откидываемся на спинку кресла, пьем чай/кофе и наслаждаемся 100% загрузкой процессора.
Запускатор передает в скрипты разбора два параметра:
$1 - каталог логов техжурнала;
$2 - каталог для сохранения результатов разбора.
Представленные ниже скрипты были взяты в качестве примера из публикации на ИТС и адаптированы под передаваемые параметры и структуру каталогов технологического журнала. Готовые скрипты складываются в подкаталог /scr каталога расположения основного скрипта.
#!/bin/bash #scr/long_transactions.sh cat $1/events/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 > $2/long_transactions.txt
#!/bin/bash #scr/long_queries.sh cat $1/events/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 > $2/long_queries.txt
#!/bin/bash #scr/long_calls.sh cat $1/events/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 > $2/long_calls.txt
#!/bin/bash #scr/long_waits.sh cat $1/deadlocks/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 > $2/long_waits.txt
Первые три скрипта можно скопировать и настроить на каталог long_events.
В итоге, использование скриптов показало достаточную эффективность для разбора данных технологического журнала 1С и поиска узких мест. Результаты при необходимости можно использовать для определения мест встраивания подсистемы оценки производительности. Или же, как в моем случае, можно разработать простую конфигурацию для загрузки полученных данных и последующего анализа.
Использование базы для агрегации результатов мне тоже понравилось. В планах добавить аналог подсистемы оценки производительности и регламентное задание, выполняющее:
- автоматическое архивирование технологического журнала предыдущего часа;
- запуск разбора данных предыдущего часа;
- загрузку полученных данных в базу.
Комментариев нет:
Отправить комментарий