Встроенные средства контроля времени исполнения программного приложения

в 14:45, , рубрики: C#, c++, CAD/CAM, время в программах, измерение времени, Программирование

Встроенные средства контроля времени исполнения программного приложения - 1В публикации представлена программная реализация встроенных средств сбора и накопления метрической информации по времени исполнения приложений, написанных на 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 выполняет накопление данных с последующим выпуском отчета при завершении работы приложения.

Встроенные средства контроля времени исполнения программного приложения - 2

Ниже представлен исходный 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 foundn");

   fprintf(fp,"n#n#%sn",bar.c_str());
   fclose(fp);
}

Ниже представлена структура демонстрационного приложения, иллюстрирующего на примерах использование средств встроенного контроля времени исполнения, а также таблица полученных результатов (см. подробности в разделе Дополнение 1. Исходный код демонстрационного приложения).

Встроенные средства контроля времени исполнения программного приложения - 3

Встроенные средства контроля времени исполнения программного приложения - 4

В разделе Дополнение 2. Исходный код средств встроенного контроля времени исполнения C# приложения представлена аналогичная реализация средств встроенного контроля на C#.

Автор использует пары TimeWatcher.StartWatch() и TimeWatcher.StopWatch() при профилировании времени исполнения трудоемких (с вычислительной точки зрения) методов и процедур в составе разрабатываемого компанией ЭРЕМЕКС программного продукта Delta Design — системы автоматизированного проектирования радиоэлектронной аппаратуры.

Ниже показан пример краткого отчета по временным метрикам одной из функциональностей упомянутого продукта.

Встроенные средства контроля времени исполнения программного приложения - 5

Краткие выводы

Описанные средства могут быть использованы для сбора данных по времени исполнения приложения на различных участках его программного кода, в частности позволяют:

  • осуществлять сбор и накопление данных по временным метрикам потоков исполнения в приложении;
  • выполнять оценки времени исполнения программного кода с точностью до элементарных языковых конструкций;
  • управлять объемом извлекаемых данных путем включения и отключения средств встроенного контроля на соответствующих участках потоков исполнения приложения;
  • разрабатывать и применять регрессионные тесты, контролирующие стабильность (и выявляющие деградацию) временных метрик приложения.

В завершение следует отметить, что вне рамок данной публикации остались вопросы применения описанных средств встроенного контроля в контексте исполнения многопоточных (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;
    }
  }

Автор: Alexander Abramov

Источник


* - обязательные к заполнению поля


https://ajax.googleapis.com/ajax/libs/jquery/3.4.1/jquery.min.js