Введение

• разработка и тестирование функциональности;
• оптимизация потребляемых ресурсов оперативной памяти;
• стабилизация метрик времени исполнения.

Методы извлечения данных времени исполнения

// необходимые прототипы и определения
#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);
}

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

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

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)
}

/// <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;
    }
  }