Получение top 25 вызовов в клиент-серверном режиме работы с наибольшей суммарной длительностью

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

1. Настроить технологический журнал
2. Проанализировать собранный технологический журнал

Перед применением инструкции рекомендуется ознакомиться с разделом методики "Методики / Мониторинг на продукционных серверах".

Настройка технологического журнала.

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

<?xml version="1.0" encoding="UTF-8"?> 
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="C:\LOGS\CALL" history="12">
<event> 
<eq property="Name" value="CALL"/>
</event> 
<property name="all"/>
</log>  
</config>

Анализ полученных данных.

Видим, что события CALL фиксируются в журнале в формате

59:59.589001-30966,CALL,1,process=rphost,p:processName=base1,t:clientID=107,t:applicationName=WebServerExtension,t:computerName=server1,t:connectID=103742,SessionID=290896,
Context=ОбщийМодуль.Вызов : ОбщийМодуль.СоединенияИБВызовСервера.Модуль.ПараметрыБлокировкиСеансов,Interface=bc15bd01-10bf-413c-a856-ddc907fcd123,Method=0,
CallID=1753280059,Memory=923,MemoryPeak=35266,InBytes=0,OutBytes=0

Выполняем в cygwin

$ cat rphost*/*.log | perl call.pl | awk -F'-' '{duration[$2]+=$1; count[$2]+=1;} END {for (i in duration) {print "SumDuration=" duration[i]/1000000 " sec;   
\tAvgDuration=" duration[i]/count[i]/1000000 " sec;   \tNumb=" count[i] ";   \t" i}}' | sort -rnb  | head -n 25 

Используем 1000000 для 8.3 и 10000 для 8.2

#!/usr/bin/perl
use strict;  
my $event;
my %actions = ( 
    'CALL' => [
{ 
   'action' => sub {
my ($event) =@_; 
my ($date, $garbage) = split /,CALL/, $event;
  
$date =~ s/\d\d:\d\d\.\d+-//g;
  
my ($garbage, $context) = split /Context=/, $event;
my ($context, $garbage) = split /,Interface=/, $context;  
if ($context =~ /\n/) {
   my @mlc = split /\n/, $context; 
   $context = $mlc[$#mlc];
}  
print "$date-$context\n" if $context;
   }, 
},
    ], 
);
  
print "\n";
while (<>) { 
    $event=process_event($event) if /^\d\d:\d\d\.\d+/;
    $event .= $_; 
}
  
sub process_event($) {
    my ($event) = @_; 
    return unless $event;
    foreach my $event_type ( keys %actions ) { 
next unless $event =~ /^[^,]+,$event_type,/;
foreach my $issue ( @{ $actions{$event_type} }) { 
   &{$issue->{action}}($event);
} 
    }
}

Получаем результат вида (всего 25 строк):

SumDuration=98.9029 sec;        AvgDuration=2.15006 sec;         Numb=46;         Система.ПолучитьФорму : Отчет.ОтчетПоПроводкам.Форма.ФормаОтчета
SumDuration=97.9661 sec;        AvgDuration=5.76271 sec;         Numb=17;         Форма.Вызов : Обработка.ЗакрытиеМесяца.Форма.Форма.Модуль.ПриИзмененииОрганизации 
SumDuration=96.9744 sec;        AvgDuration=0.718329 sec;       Numb=135;       Система.ПолучитьФорму : Документ.СчетНаОплатуПокупателю.ФормаСписка
SumDuration=94.1614 sec;        AvgDuration=0.350043 sec;       Numb=269;       Система.ПолучитьФорму : Документ.РасходныйКассовыйОрдер.ФормаОбъекта
...

SumDuration - суммарная длительность вызовов в секундах

Numb - число вызовов

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