Встроенные средства контроля времени исполнения программного приложения
В публикации представлена программная реализация встроенных средств сбора и накопления метрической информации по времени исполнения приложений, написанных на C/C++/C#.
Существо описываемого подхода базируется на включении в программный код приложения «контрольных точек» извлечения данных по времени исполнения структурных составляющих: методов, функций и {} блоков. Извлекаемые метрическая информация накапливаются во внутренней базе данных, содержание которой по завершении приложения конвертируется в форму текстового отчета, сохраняемого в файле. Целесообразность использования средств встроенного контроля времени исполнения обусловлена необходимостью выявления проблемных участков кода, анализа причин возникающей временной деградации приложения: полной или частичной, либо проявляющейся на определенных наборах исходных данных.
Приведенные примеры C++/C# исходных кодов демонстрируют возможные реализации описанного подхода.
Введение
Разработка программного приложения на каждой итерации (например, выпуск очередного релиза) его эволюционного развития включает выполнение следующих основных шагов:
- разработка и тестирование функциональности;
- оптимизация потребляемых ресурсов оперативной памяти;
- стабилизация метрик времени исполнения.
Перечисленные шаги требуют от разработчиков значительного объема не только творческой (как-то разработка и реализация эффективных алгоритмов, построение гибкой архитектуры программного обеспечения и т. п.), но и рутинной работы. К последней категории относится деятельность, направленная на стабилизацию временных метрик исполнения приложения. Во многих случаях это достаточно болезненная процедура, когда разработчики сталкиваются с деградацией, являющейся следствием расширения функциональности программного продукта, перестроения архитектуры программного обеспечения и появления новых потоков исполнения в приложении. При этом источники деградации требуют определенных усилий по их обнаружению, что достигается не только высоким трудолюбием и ответственностью разработчиков (необходимое условие), но и составом применяемых для этих целей инструментальных средств (достаточное условие).
Одним из эффективных подходов к решению проблемы анализа временных метрик приложения является использования специализированных программных продуктов, например GNU gprof. Анализ генерируемых такими инструментальными средствами отчетов позволяет выявлять «узкие места» (методы классов и функции), на которые приходятся значительные затраты времени исполнения приложения в целом. При этом обоснованность затрат времени исполнения методов и процедур безусловно квалифицируется разработчиками.
Следует также отметить, что программные продукты этого класса выполняют, как правило, метрический анализ времени исполнения программного кода на уровнях методов классов и функций, игнорирую более низкие (но тем не менее существенные с точки зрения анализа проблемы) уровни: {…}, for, while, do-until, if–else, try-catch блоков, внутри которых происходят не менее значительные затраты времени исполнения.
Далее рассматривается основное содержание одного из возможных решений по реализации средств встроенного контроля времени исполнения, нацеленных на извлечение и накоплении детальной информации о временных метриках контролируемых блоков программного обеспечения с последующим формированием отчетов для разработчиков.
Методы извлечения данных времени исполнения
Функциональность любого программного приложения может интерпретироваться как абстрактная машина с конечным набором уникальных состояний {St } и переходов {Tr } между ними.
В рамках такого подхода любой поток исполнения в приложении следует интерпретировать как упорядоченную последовательность его состояний и переходов между ними. При этом оценка затрат времени исполнения выполняется суммированием временных метрик по всему набору пройденных состояний с игнорированием затрат на переходы от одного состояния к другому — как ничтожно малых величин.
Извлечение и накопление данных по времени исполнения приложения в заданных контрольных точках является основной задачей, решаемой встроенными средствами контроля, описываемыми ниже.
Для каждой контрольной точки, объявленной в исходном коде путем размещения
PROFILE_ENTRY C++ макроса, регистрируется количество ее прохождений при выполнении приложения, а также временная метрика — суммарное время пребывания приложения в состоянии от момента прохождения контрольной точки и до выхода на следующий уровень программной иерархии (включающий блок, метод класса, функция и т.п.), как это иллюстрируется на диаграмме, показанной ниже.
Управление контрольными точками (первичная регистрация и вычисление их временных метрик) выполняется объектом «timeManager», который создается в единственном экземпляре. Каждое событие прохождения контрольной точки фиксируется объектом «timeManager», , а при первом прохождении регистрируется им в качестве наблюдаемых как «registerEntry».
В момент каждого прохождения контрольной точки создается объект timerObject, фиксирующий время своего создания. Фиксация времени исполнения в контрольной точке выполняется при выходе приложения с текущего уровня программной иерархии. В этот момент происходит автоматическое уничтожение timerObject объекта, которое сопровождается вычислением его «времени жизни» T. В результате timeManager увеличивает на »1» количество прохождений контрольной точки и время пребывания в ней на T. По всем установленным контрольным точкам timeManager выполняет накопление данных с последующим выпуском отчета при завершении работы приложения.
Ниже представлен исходный C++ код, реализующий встроенные средства контроля времени исполнения приложения.
// необходимые прототипы и определения
#include
#include
Ниже представлена структура демонстрационного приложения, иллюстрирующего на примерах использование средств встроенного контроля времени исполнения, а также таблица полученных результатов (см. подробности в разделе Дополнение 1. Исходный код демонстрационного приложения).
В разделе Дополнение 2. Исходный код средств встроенного контроля времени исполнения C# приложения представлена аналогичная реализация средств встроенного контроля на C#.
Автор использует пары TimeWatcher.StartWatch () и TimeWatcher.StopWatch () при профилировании времени исполнения трудоемких (с вычислительной точки зрения) методов и процедур в составе разрабатываемого компанией ЭРЕМЕКС программного продукта Delta Design — системы автоматизированного проектирования радиоэлектронной аппаратуры.
Ниже показан пример краткого отчета по временным метрикам одной из функциональностей упомянутого продукта.
Краткие выводы
Описанные средства могут быть использованы для сбора данных по времени исполнения приложения на различных участках его программного кода, в частности позволяют:
- осуществлять сбор и накопление данных по временным метрикам потоков исполнения в приложении;
- выполнять оценки времени исполнения программного кода с точностью до элементарных языковых конструкций;
- управлять объемом извлекаемых данных путем включения и отключения средств встроенного контроля на соответствующих участках потоков исполнения приложения;
- разрабатывать и применять регрессионные тесты, контролирующие стабильность (и выявляющие деградацию) временных метрик приложения.
В завершение следует отметить, что вне рамок данной публикации остались вопросы применения описанных средств встроенного контроля в контексте исполнения многопоточных (multithreading) приложений и не был представлен в какой-либо форме анализ точности получаемых данных по временным метрикам. Последнее связано с тем, что на практике, при выявлении причин временной деградации приложения в первую очередь актуальны данные об относительном распределении затрат времени исполнения между программными составляющими приложения. В связи с этим вопросы точности получаемых данных отходят на второй план.
Дополнение 1. Исходный код демонстрационного приложения
INITIALIZE_PROFILER
int main(int argc, char * argv[])
{
//create profile manager
CREATE_PROFILER
PROFILE_ENTRY("1 Main context")
f11();
for(unsigned jj = 0;jj<4;jj++)
f12();
f13 ();
f14 ();
f15 ();
f16 ();
f17();
return 0;
}
void f11(void)/////////////////////////////////////////
{
PROFILE_ENTRY ("2 f11()........................")
for (unsigned jj = 0; jj<5; jj++)
{
PROFILE_ENTRY ("2 f11()::for(...){...} iterat-ing")
DELAY(1)
}
//profile entry for repeating
int nn(3);
while(nn > 0)
{
PROFILE_ENTRY("2 f11()::while(...){...} iterat-ing")
DELAY(1)
nn--;
}
}
void f12(void)/////////////////////////////////////////
{
PROFILE_ENTRY("3 f12()........................")
goto ending;
{
PROFILE_ENTRY("3 f12()::ignored code part")
DELAY(1)
}
ending: PROFILE_ENTRY("3 f12()::ending code part")
DELAY(2)
}
void f13(void) /////////////////////////////////////////
{
PROFILE_ENTRY("4 f13()........................")
srand((unsigned) time(NULL)/2);
for(unsigned jj = 0; jj < 200; jj++)
{
if(rand()%2 == 0)
{
PROFILE_ENTRY("4 f13()::even branch")
DELAY(0.01)
}
else
{
PROFILE_ENTRY("4 f13()::od branch")
DELAY(0.02)
}
}
}
void f14(void)/////////////////////////////////////////
{
static int depth = 10;
{
PROFILE_ENTRY("5 f14() recursion")
depth--;
DELAY(0.5)
if(depth == 0) return;
}
f14();
}
void f15(void)/////////////////////////////////////////
{
PROFILE_ENTRY("7 f15()........................")
for(unsigned jj = 0; jj < 10; jj++)
{
demo_class obj;
obj.method1();
obj.method2();
obj.method3();
}
}
void f16(void)/////////////////////////////////////////
{
PROFILE_ENTRY("8 f16()........................")
try
{
for(int jj = 10; jj >= 0; jj--)
{
PROFILE_ENTRY("81 f16() try clause")
DELAY(1)
int rr = 200/jj;
}
}
catch(...)
{
PROFILE_ENTRY("81 f16() catch clause")
DELAY(2)
return;
}
}
void f17(void)/////////////////////////////////////////
{
PROFILE_ENTRY("9 f17()........................")
f21();
f22();
f23();
f24();
f25();
}
void f22(void)/////////////////////////////////////////
{
PROFILE_ENTRY("91 f22()........................")
DELAY(1)
f221();
f222();
f223();
}
void f23(void)
{PROFILE_ENTRY("91 f23()")
DELAY(1)
}
void f24(void)
{PROFILE_ENTRY("91 f24()")
DELAY(1)
}
void f25(void)
{PROFILE_ENTRY("91 f25()")
DELAY(1)
}
void f221(void)
{PROFILE_ENTRY("91 f221()")
DELAY(3)
}
void f222(void)
{PROFILE_ENTRY("91 f222()")
DELAY(4)
}
void f223(void)
{PROFILE_ENTRY("91 f223()")
DELAY(5)
}Дополнение 2. Исходный код средств встроенного контроля времени исполнения C# приложения
///
/// Класс по управлению контрольными точками и регистрации времени исполнения приложения в них
///
public class TimeWatcher
{
///
/// Внутренний класс управления контрольной точкой и регистрации времени исполнения в ней
///
internal class TimeEntry
{
// объект регистрации времени исполнения
public Stopwatch timeWatch;
// суммарное время исполнения в данной точке
public long elapsedTime;
// конструктор
public TimeEntry()
{
timeWatch = new Stopwatch();
elapsedTime = 0;
}
}
// установка активности средств регистрации времени исполнения
// в контрольных точках
private static bool enableTimeWatcher = false;
// словарь внешних имен контрольных точек и зарегистрированного времени исполнения в них
private static Dictionary entryDictionary = new Dictionary();
// запуск процедуры регистрации времени исполнения в указанной точке
public static void StartWatch(string postfix = "")
{
if (!enableTimeWatcher)
return;
string entryName = GetCurrentMethod();
if (postfix != "")
{
entryName += postfix;
}
// если точка не найдена, то регистрируем ее как новую
// в противном случае перезапускаем слежение за временем исполнения
if (!entryDictionary.ContainsKey(entryName))
{
entryDictionary.Add(entryName, new TimeEntry());
entryDictionary[entryName].timeWatch.Start();
}
else
{
if (entryDictionary[entryName].timeWatch.IsRunning)
{
throw new System.InvalidOperationException("ОШИБКА: попытка повторного рестарта '"
+ entryName
+ "' контрольной точки.");
}
else
entryDictionary[entryName].timeWatch.Restart();
}
}
// регистрация затраченного времени исполнения в указанной точке
public static void StopWatch(string postfix = "")
{
if (!enableTimeWatcher)
return;
string entryName = GetCurrentMethod();
if (postfix != "")
{
entryName += postfix;
}
// если точка не зарегистрирована, то запрос квалифицируется как ошибочный
if (!entryDictionary.ContainsKey(entryName))
{
throw new System.InvalidOperationException("ОШИБКА: запрос времени исполнения в неза-
регистрированной точке наблюдения '" + entryName + "'.");
}
if (!entryDictionary[entryName].timeWatch.IsRunning)
{
throw new System.InvalidOperationException
"ОШИБКА: запрос времени исполнения в неактивной точке наблюдения '" +
entryName + "'.");
}
entryDictionary[entryName].timeWatch.Stop();
entryDictionary[entryName].elapsedTime +=
entryDictionary[entryName].timeWatch.ElapsedMilliseconds;
}
// Выпуск отчета о суммарном времени исполнения приложения
// в каждой зарегистрированной точке
public static void TimeWatchReport()
{
const string bar = "=============================================";
if (!enableTimeWatcher)
return;
Console.WriteLine("");
Console.WriteLine(bar);
Console.WriteLine("Затраченное время в контрольных точках (миллисекунды): ");
Console.WriteLine("");
int maxLen = 0;
foreach (var timeEntry in entryDictionary)
{
if(timeEntry.Key.Length > maxLen)
maxLen = timeEntry.Key.Length;
}
maxLen++;
string strFormat = "{0," + maxLen + "} ... {1,-10}";
foreach (var timeEntry in entryDictionary)
{
Console.WriteLine(strFormat, timeEntry.Key, timeEntry.Value.elapsedTime);
}
Console.WriteLine(bar);
Console.WriteLine("");
entryDictionary.Clear();
enableTimeWatcher = false;
}
// инициализация процедуры слежения за временем исполнения в контрольных точках
// функциональность актуальна только при наличии /tmw в командной строке
// запуска приложения
public static void InitTimeWatch()
{
if (Environment.GetCommandLineArgs().Any(v => v == "/tmw"))
{
if (entryDictionary.Count > 0)
{
TimeWatchReport();
}
entryDictionary.Clear();
enableTimeWatcher = true;
}
}
// извлечение имени вызывающего метода в текущем контексте
private static string GetCurrentMethod()
{
StackTrace st = new StackTrace();
StackFrame sf = st.GetFrame(2);
return sf.GetMethod().Name;
}
} 