10 сент. 2017 г.

bash, еще bash, еще много-много bash

А на ловца и зверь бежит, коллеги. Буквально недавно эпизодически 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С и поиска узких мест. Результаты при необходимости можно использовать для определения мест встраивания подсистемы оценки производительности. Или же, как в моем случае, можно разработать простую конфигурацию для загрузки полученных данных и последующего анализа.


Использование базы для агрегации результатов мне тоже понравилось. В планах добавить аналог подсистемы оценки производительности и регламентное задание, выполняющее:
- автоматическое архивирование технологического журнала предыдущего часа;
- запуск разбора данных предыдущего часа;
- загрузку полученных данных в базу.

Комментариев нет:

Отправить комментарий