Анализ времени выполнения скриптов и поиск "узкого" места в функционале
Для определения "узких" мест в функционале разработал набор методов (функций), которые позволяют измерять суммарное время на выполнение каждой функции и процентное отношение суммарного времени вызова этой функции к суммарному времени выполнения общего функционала. В моей ситуации каждая функция вызывалась по много раз, поэтому нужно было реализовать накопление времени выполнения по каждой функции или участку кода.
Функционал в моем случае: импорт прайс-листа из Excel по производителю с большим количеством строк.
В результате оптимизации, удалось ускорить импорт прайс-листа приблизительно раза в четыре (был 1 час, стало 15 минут).
Вот набор этих методов
(прикрепил ниже в архиве scr_ScriptExecutionAnalysis.zip).
// scr_ScriptExecutionAnalysis
//-----------------------------------------------------------------------------
var ScriptExecutionAnalysis = {};
function _StartTiming(Caller, IsMain) {
if (!Caller) {
return;
}
var Name;
if (typeof(Caller) == 'function') {
Name = "[fn]" + Caller.toString().split('(')[0].substring(9);
} else {
Name = Caller;
}
if (!ScriptExecutionAnalysis[Name]) {
ScriptExecutionAnalysis[Name] = {};
ScriptExecutionAnalysis[Name].TotalDuration = 0;
ScriptExecutionAnalysis[Name].NumberOfCalls = 0;
ScriptExecutionAnalysis[Name].MinDuration = 0;
ScriptExecutionAnalysis[Name].MaxDuration = 0;
ScriptExecutionAnalysis[Name].WasZeroDuration = false;
}
if (IsMain) {
ScriptExecutionAnalysis.IsMainName = Name;
}
ScriptExecutionAnalysis[Name].Start = (new Date()).getTime();
}
function _EndTiming(Caller) {
if (!Caller) {
return;
}
var Name;
if (typeof(Caller) == 'function') {
Name = "[fn]" + Caller.toString().split('(')[0].substring(9);
} else {
Name = Caller;
}
if (!ScriptExecutionAnalysis[Name]) {
return;
}
ScriptExecutionAnalysis[Name].End = (new Date()).getTime();
var Duration = ScriptExecutionAnalysis[Name].End - ScriptExecutionAnalysis[Name].Start;
if (Duration == 0) { ScriptExecutionAnalysis[Name].WasZeroDuration = true }
if ((ScriptExecutionAnalysis[Name].MinDuration == 0 &&
!ScriptExecutionAnalysis[Name].WasZeroDuration) ||
Duration ScriptExecutionAnalysis[Name].MinDuration) {
ScriptExecutionAnalysis[Name].MinDuration = Duration;
}
if (Duration > ScriptExecutionAnalysis[Name].MaxDuration) {
ScriptExecutionAnalysis[Name].MaxDuration = Duration;
}
ScriptExecutionAnalysis[Name].TotalDuration += Duration;
ScriptExecutionAnalysis[Name].NumberOfCalls++;
}
function _CreateScriptExecutionAnalysisReport() {
var Item;
var Name;
var Main;
if (ScriptExecutionAnalysis.IsMainName) {
Main = ScriptExecutionAnalysis[ScriptExecutionAnalysis.IsMainName];
}
var FString = "[%1] TotalDuration - %2 ms, NumberOfCalls - %3, MinDuration - %4 ms, MaxDuration - %5 ms, AverageDuration - %6 ms";
for (Name in ScriptExecutionAnalysis) {
if (Name == 'IsMainName') {
continue;
}
Item = ScriptExecutionAnalysis[Name];
Log.Write(1, FormatStr(FString,
Name, Item.TotalDuration, Item.NumberOfCalls, Item.MinDuration, Item.MaxDuration,
Math.round(Item.TotalDuration / Item.NumberOfCalls * 100) / 100) +
(Main ? ", Portion - " + Math.round(Item.TotalDuration / Main.TotalDuration * 1000) / 10 + " %": ""));
}
ScriptExecutionAnalysis = {};
}
function FormatStr(Str) {
var Ln = arguments.length;
for (var i = 1; i Ln; i++ ) {
Str = Str.replace(new RegExp('%' + i, 'g'), arguments[i]);
}
return Str;
}
Описание методов:
_StartTiming(Caller, IsMain) - используется для указания начала отсчета времени.
Аргумент Caller может быть либо объект функции, в которой вызывается этот метод, а может быть и просто текстовая строка (тэг) для унификации этого замера времени. Унификация используется при построении отчета.
Аргумент IsMain - признак того, что метод вызывается из основной функции и нужен для подсчета суммарного времени работы функционала, а суммарное время расчеты функционала в свою очередь используется для определения процентного отношения вызова функции к общему времени выполнении функционала (в отчете).
_EndTiming(Caller) - используется для указания окончания замера времени.
Аргумент Caller указывается по аналогии как в методе _StartTiming.
Каждому вызову метода _StartTiming(Caller) должен соответствовать вызов метода _EndTiming(Caller) с таким же аргументом Caller. Это нужно для построения отчета и вообще для корректного замера времени.
_CreateScriptExecutionAnalysisReport() - метод выводит в лог Террасофт отчет по выполнению функций.
Пример использования в коде:
_StartTiming(arguments.callee, true);
...
InnerFunction();
...
_EndTiming(arguments.callee);
_CreateScriptExecutionAnalysisReport();
}
function InnerFunction() {
_StartTiming(arguments.callee);
...
_StartTiming('ScriptBlock1');
...
_StartTiming('ScriptBlock2');
...
_EndTiming('ScriptBlock2');
...
_StartTiming('ScriptBlock3');
...
_EndTiming('ScriptBlock3');
...
_EndTiming('ScriptBlock1');
...
_EndTiming(arguments.callee);
}
Пример отчета из "реальной жизни"
прикрепил ниже (Report.txt).
Пару строк из отчета:
[[fn]InitUpdateQuery] TotalDuration - 652 ms, NumberOfCalls - 46, MinDuration - 0 ms, MaxDuration - 31 ms, AverageDuration - 14.17 ms, Portion - 6.6 %
[ProcessOneRecord] TotalDuration - 4219 ms, NumberOfCalls - 49, MinDuration - 31 ms, MaxDuration - 329 ms, AverageDuration - 86.1 ms, Portion - 42.6 %
Расшифровка отчета:
TotalDuration - суммарное время на вызов этой функции/участка кода;
NumberOfCalls - количество вызовов этой функции / прохождения участка кода;
MinDuration - минимальное время выполнения этой функции/участка кода;
MaxDuration - максимальное время выполнения этой функции/участка кода;
AverageDuration - среднее время выполнения этой функции/участка кода;
Portion - процентное отношение суммарного вызова этой функции/участка кода к суммарному времени вызова основной функции.
В отчете [fn] обозначает, что это функция. Отсутствие [fn] обозначает, что это участок кода, который характеризуется указанным тэгом.
PriceListImport - это в моем примере основная функция (видно даже по значению Portion = 100%)
[fn]InitUpdateQuery - это вызов функции InitUpdateQuery, Portion = 6.6 %. Возможно, стоит на эту функцию обратить внимание с таким процентным соотношением.
ProcessOneRecord - участок кода с тэгом 'ProcessOneRecord'. Portion = 42.6 % - большой вес в общем функционале, стоит хорошенько пересмотреть этот участок кода.
Также, стоит заметить, что определенное время (задержка) тратиться на выполнение самих методов замера времени выполнения функций.
