В публикации представлена программная реализация встроенных средств сбора и накопления метрической информации по времени исполнения приложений, написанных на 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 <vector>
#include <map>
#include <algorithm>
#include <stdio.h>
#include <time.h>
typedef unsigned long LONGEST_INT;
// макросы, обеспечивающие интерфейс между
// приложением и программными средствами
// встроенного контроля времени исполнения
// включает (не закомментированный) или выключает
// (закомментированный) функциональность встроенного
// контроля времени исполнения
#define PROFILER_ENABLED
// CREATE_PROFILER создает timeManager объект,
// подлежит размещению в начале
// ‘main()’
#ifdef PROFILER_ENABLED
#define CREATE_PROFILER timeManager tManager;
#else
#define CREATE_PROFILER //нет определения для CREATE_PROFILER.
#endif
//INITIALIZE_PROFILER инициализация данных для timeManager объекта
// должен быть размещен в глобальном пространстве
// имен перед ‘main()’
#ifdef PROFILER_ENABLED
#define INITIALIZE_PROFILER bool timeManager::object = false;\
std::vector<registerEntry> timeManager::entries;
#else
#define INITIALIZE_PROFILER //нет определения для INITIALIZE_PROFILER.
#endif
//DELAY(_SECONDS) задерживает исполнение на‘_SECONDS’ секунд.
// Используется исключительно для отладки, когда
// требуется принудительно задержать исполнение
// приложения
#ifdef PROFILER_ENABLED
#define DELAY(_SECONDS) {clock_t clk_wait=clock()+((double)_ARG)*CLOCKS_PER_SEC;\
while(clock()<clk_wait) {}}
#else
#define DELAY(_SECONDS) // нет определения для DELAY.
#endif
// макросы для объединения строковых данных,
// имеются некоторые различия для UNIX и WINDOWS
// используются исключительно для внутренних целей
#ifdef PROFILER_ENABLED
#define MERGE2(x,y) x##y
#define MERGE1(_X,_Y) MERGE2(_X,_Y)
#if WIN32
#define UNIQUENAME prefix,postfix) MERGE1(prefix,postfix)
#else
#define UNIQUENAME(prefix,postfix) MERGE2(prefix,postfix)
#endif
#define GEN_SRC(_ARG1,_ARG2) static int UNIQUENAME(ind,_ARG2)=-1;\
if(UNIQUENAME(ind,_ARG2)<0)\
UNIQUENAME(ind,_ARG2)=timeManager::add_entry(_ARG1);\
timeManager::incr_counter(UNIQUENAME(ind,_ARG2));\
timerObject UNIQUENAME(tm,_ARG2)(UNIQUENAME(ind,_ARG2));
//PROFILE_ENTRY макро для объявления контрольной точки
#ifdef PROFILER_ENABLED
#if WIN32
#define PROFILE_ENTRY(_TITLE) GEN_SRC(_TITLE,__COUNTER__)
#else
#define PROFILE_ENTRY(_TITLE) GEN_SRC(_TITLE,__LINE__)
#endif
#else
#define PROFILE_ENTRY(_TITLE) // нет определения для PROFILE_ENTRY.
#endif
// структуры данных и методы встроенных средств контроля
// времени исполнения приложения
// структура данных контрольной точки, зарегистрированной в timeManager
struct registerEntry
{
// внешнее имя контрольной точки (назначается при объявлении)
std::string entry_name;
// количество прохождений контрольной точки
// в процессе исполнении приложения
LONGEST_INT covers_counter;
// время пребывания приложения в контексте
// контрольной точки в тиках (ticks)
LONGEST_INT elapsed_time;
//конструктор
registerEntry(const char * title):entry_name(title),
covers_counter(0),
elapsed_time(0) {}
};
//класс для измерения временнОго интервала
class timerObject
{
// уникальный целочисленный идентификатор, связанный с контрольной точкой
int index;
// время создания объекта
clock_t start_time;
public:
// конструктор с регистрацией времени создания объекта
timerObject(int ind):index(ind),start_time(clock()) {}
// деструктор с добавлением “времени жизни” объекта
// ко времени исполнения приложения в контексте
// контрольной точки
~timerObject(void)
{
timeManager::incr_timer(index,(LONGEST_INT)(clock()-start_time));
}
};
// класс управления контрольными точками
class timeManager
{
private:
// множество зарегистрированных контрольных точек
static std::vector<registerEntry> entries;
// флаг, гарантирующий создание только одного
// объекта данного класса
static bool object;
public:
// выполняет регистрацию новой поименованной
// контрольной точки, назначает и возвращает
// ее уникальный целочисленный иденификатор
static int add_entry(const char * title)
{
entries.push_back(registerEntry(title));
return (((int)entries.size())-1);
}
// увеличивает на единицу количество прохождений приложение
// контрольной точки с указанным идентификатором
static void incr_counter(int profile_entry_id)
{
entries[profile_entry_id].covers_counter++;
}
// добавляет величину‘value’ ко времени исполнения приложения
// в контексте указанной контрольной точки
static void incr_timer(int profile_entry_id, LONGEST_INT value)
{
entries[profile_entry_id].elapsed_time += val;
}
// выполняет формирование отчета по метрикам зарегистрированных
// контрольных точек
static void report(void);
// конструктор
timeManager(void)
{
if(!object)
object = true;
else
{
printf("\n<<ОШИБКА>>: попытка создания второго 'timeManager' объекта.\n");
throw;
}
}
// деструктор с выпуском отчета по метрикам зарегистрированных
// контрольных точек
virtual ~timeManager(void) {report();}
};
// предикат сравнения двух контрольных точек
bool cmp_entries(registerEntry & first,
registerEntry & second)
{
if(first.entry_name.compare(second.entry_name)>0)
return false;
return true;
}
// генератор отчета по временнЫм метрикам
// зарегистрированных контрольных точек
void timeManager::report(void)
{
const std::string bar(72,'*');
// расположение файла с отчетом в файловой иерархии
const char * REPORT_FILE = "C:\\tmProfile.txt";
FILE * fp = fopen(REPORT_FILE,"w");
if(!fp)
{
printf("\n<<ОШИБКА>>: указано неправильное имя файла с отчетом (%s)",REPORT_FILE);
return;
}
fprintf(fp,"\n#%s",bar.c_str());
fprintf(fp,"\n#\n# Метрические данные по зарегистрированным контрольным точкам");
fprintf(fp,"\n#\n#%s",bar.c_str());
fprintf(fp,"\n#\n# %-35s %-15s %-20s",
"Наименование точки","Прохождений","Время (с)");
fprintf(fp,"\n# %-35s %-15s %-20s",
"------------------","-------------","---------------\n#");
// сортировка контрольных точек в алфавитном порядке их наименований
std::sort(entries.begin(),entries.end(),cmp_entries);
for(unsigned jj = 0; jj< entries.size(); jj++)
{
fprintf(fp,"\n# %-35s %-16d", entries[jj].entry_name.c_str(),
entries[jj].covers_counter);
if(entries[jj].covers_counter == 0)
fprintf(fp,"%-20d",0);
else
fprintf(fp,"%-20.0f", static_cast<double>(entries[jj].elapsed_time)/
static_cast<double>(CLOCKS_PER_SEC));
}
if(entries.size() == 0)
fprintf(fp,"\n# No covered profile entries found\n");
fprintf(fp,"\n#\n#%s\n",bar.c_str());
fclose(fp);
}Ниже представлена структура демонстрационного приложения, иллюстрирующего на примерах использование средств встроенного контроля времени исполнения, а также таблица полученных результатов (см. подробности в разделе Дополнение 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# приложения
/// <summary>
/// Класс по управлению контрольными точками и регистрации времени исполнения приложения в них
/// </summary>
public class TimeWatcher
{
/// <summary>
/// Внутренний класс управления контрольной точкой и регистрации времени исполнения в ней
/// </summary>
internal class TimeEntry
{
// объект регистрации времени исполнения
public Stopwatch timeWatch;
// суммарное время исполнения в данной точке
public long elapsedTime;
// конструктор
public TimeEntry()
{
timeWatch = new Stopwatch();
elapsedTime = 0;
}
}
// установка активности средств регистрации времени исполнения
// в контрольных точках
private static bool enableTimeWatcher = false;
// словарь внешних имен контрольных точек и зарегистрированного времени исполнения в них
private static Dictionary<string, TimeEntry> entryDictionary = new Dictionary<string,
TimeEntry>();
// запуск процедуры регистрации времени исполнения в указанной точке
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;
}
}