Built-in monitoring execution time of the software application

the publication presents a software implementation of the built-in tools for gathering and storing metric information on-time performance of applications written in C/C++/C#.
The essence of the described approach is based on the inclusion in the application code “control points” retrieval time of the execution of structural components: methods, functions, and {} blocks. The extracted metric information is accumulated in the internal database, the content of which is at the end of the application is converted into the form of a text report, saved to a file. The expediency of use of means of internal control execution time due to the need to identify problematic code fragments, analysis of reasons of emerging the temporary degradation of application: full or partially, or appear on certain sets of input data.
Examples of C++/C# source code demonstrate the possible implementation of the described approach.

Introduction

Development of software application on each iteration (e.g. next release) of its evolutionary development includes the following steps:

• development and testing of functionality;
• optimize the consumption of resources of memory;
• stabilization time metrics of performance.

These steps require from the developer a significant amount not only creative (such as the development and implementation of efficient algorithms, building flexible software architecture, etc.), but routine work. The latter category includes activities aimed at the stabilization time metrics of performance application. In many cases it is quite painful procedure, when developers are faced with the degradation resulting from the expansion of the functionality of the software product, rebuild the software architecture and the emergence of new threads of execution within the application. While sources of degradation require effort on their discovery, which is achieved not only with high diligence and responsibility of the developers (a necessary condition), but also the composition used for these purposes workbench (sufficient condition).
One of the most effective approaches to solving the problem of analysis of time metrics of the application is the use of specialized software, such as GNU gprof. The analysis generated by these tools report allows you to identify “bottlenecks” (methods of classes and functions) that have time-consuming the execution of the application as a whole. The validity of the time-consuming execution of methods and procedures course qualifies developers.
It should also be noted that software products of this class are generally, metric analysis of the execution time of the program code at the level of methods of classes and functions to ignore a lower (but nevertheless important from the point of view of analysis of problems) levels: {…}, for, while, do-until, if–else, try-catch blocks within which there are no less time-consuming execution.
Next, we consider the main content of one of the possible solutions for the implementation of the built-in monitoring devices-time performance, aimed at the extraction and the accumulation of detailed information on time metrics of the monitored software applications with the subsequent formation of reports for developers.

Methods data extraction execution time

The functionality of any software application can be interpreted as an abstract machine with a finite set of unique States {St } and transitions {Tr } between them.
In this approach, any thread of execution within the application should be interpreted as an ordered sequence of its States and transitions between them. The cost estimate execution time is performed by summing the temporary metric with the set of traversed States ignoring the cost of transitions from one state to another – as infinitesimal quantities.
The extraction and accumulation of data on the execution time of the application in the specified control points is the main problem solved in control, as described below.
For each control point that is declared in the source code by placing
PROFILE_ENTRY C++ macro is recorded the number of passages when running the application, as well as the temporal metric is the total time of the application as from the moment of passing the checkpoint and to the next level of the software hierarchy (including block, method, class, function, etc.), as illustrated in the diagram shown below.
Management reference points (initial registration and the calculation of their time metrics) is performed by the object ‘timeManager’, which is created in a single copy. Each event checkpoint fixed object ‘timeManager’, and the first passage is registered as a seeing how ‘registerEntry’.
At the moment of each checkpoint is created, the object timerObject, fixing the time of its creation. Time stamp of execution, a checkpoint is performed when the application exits from the current level of the software hierarchy. In this moment there is automatic destruction of the object timerObject, which is accompanied by a calculation of its “lifetime” T. the result timeManager increases by ‘1’ number of passing checkpoints and stay in it for T. All established control points timeManager performs data accumulation with the subsequent release of the report when the application shuts down.

Here’s the source C++ code that implements the built-in monitoring execution time of the application.
// required prototypes and definitions


#include <vector>
#include <map>
#include <algorithm>
#include <stdio.h>
#include <time.h>
typedef unsigned long LONGEST_INT;


// macros that provide an interface between
// application and software
// the built-in monitoring execution time

// includes (not commented out) on or off
// (commented out) functionality built-in
// control execution time
#define PROFILER_ENABLED

// Creates CREATE_PROFILER timeManager object
// to be placed at the beginning
// ‘main()’
#ifdef PROFILER_ENABLED
#define CREATE_PROFILER timeManager tManager;
#else
#define CREATE_PROFILER //no definition for CREATE_PROFILER.
#endif

//INITIALIZE_PROFILER initialization data for the timeManager object
// must be placed in the global namespace
// the names before the ‘main()’#ifdef PROFILER_ENABLED
#define bool INITIALIZE_PROFILER timeManager::object = false;\
std::vector timeManager::entries;
#else
#define INITIALIZE_PROFILER //no definition for INITIALIZE_PROFILER.
#endif

//DELAY(_SECONDS) delays the execution of the na ‘ _SECONDS’ seconds.
// Only used for debugging when
// force required to withhold performance
// application
#ifdef PROFILER_ENABLED
#define DELAY(_SECONDS) {clk_wait clock_t=clock()+((double)_ARG)*CLOCKS_PER_SEC;\
while(clock()<clk_wait) {}}
#else
#define DELAY(_SECONDS) // no definition for DELAY.
#endif

// macros to combine string data
// there are some differences for UNIX and WINDOWS
// used solely for internal purposes
#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));

<font color=”green>
//PROFILE_ENTRY macro to declare checkpoint
#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) // no definition for PROFILE_ENTRY.
#endif

// data structures and methods built-in controls
// time the execution of the application



// data structure checkpoint was in timeManager struct registerEntry
{ // the external name of the cue point (appointed in ad) std::string entry_name; // number of passing checkpoint // during execution of the application LONGEST_INT covers_counter; // stay applications in the context of // control points in ticks (ticks) LONGEST_INT elapsed_time; //constructor registerEntry(const char * title):entry_name(title),
covers_counter(0), elapsed_time(0) {}
}; //class for measuring the time interval
class timerObject
{ // a unique integer identifier associated with the breakpoint int index; // create time object clock_t start_time; public: // constructor time registration object creation timerObject(int ind):index(ind),start_time(clock()) {} // the destructor with the addition of the “lifetime” of the object // at the time of execution of the application in the context of // control points
~timerObject(void)
{
timeManager::incr_timer(index,(LONGEST_INT)(clock()-start_time));
}
}; // class to manage checkpoints
class timeManager
{
private: // registered control points static std::vector<registerEntry> entries; // flag that guarantees the creation of only one // object of this class static bool object; public: // registers a new named // the control point, assigns and returns // its unique integer identificator static int add_entry(const char * title)
{
entries.push_back(registerEntry(title)); return (((int)entries.size())-1);
} // increments the number of passages of the app // the checkpoint with the specified ID static void incr_counter(int profile_entry_id)
{
entries[profile_entry_id].covers_counter++;
} // adds velicinu value’ at the time of execution of the application // in the context of a specified checkpoint static void incr_timer(int profile_entry_id, LONGEST_INT value)
{ entries[profile_entry_id].elapsed_time += val;
} // executes the report generation for metrics was // control points static void report(void); // constructor
timeManager(void)
{
if(!object) object = true;
else
{ printf("\n<<ERROR>>: attempt to create a second 'timeManager' object.\n");
throw;
}
} // the destructor with the release of the report on metrics was // control points virtual ~timeManager(void) {report();}
}; // predicate compare two control points
bool cmp_entries(registerEntry & first, registerEntry & second)
{
if(first.entry_name.compare(second.entry_name)>0) return false; return true;
} // the report generator by time metrics // registered control points void timeManager::report(void)
{ const std::string bar(72,'*'); // location of the log file in the file hierarchy const char * REPORT_FILE = "C:\\tmProfile.txt"; FILE * fp = fopen(REPORT_FILE,"w");
if(!fp)
{ printf("\n<<ERROR>>: you specified an incorrect name of the log file (%s)",REPORT_FILE);
return;
} fprintf(fp,"\n#%s",bar.c_str()); fprintf(fp,"\n#\n# Metric data of the registered control points");
fprintf(fp,"\n#\n#%s",bar.c_str()); fprintf(fp,"\n#\n# %-35s %-15s %-20s", "Name point","Playthroughs","Time ()"); fprintf(fp,"\n# %-35s %-15s %-20s", "------------------","-------------","---------------\n#"); // sort the control points in the alphabetical order of their names
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.0 f", 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);
}

Below is the structure of the sample application, illustrating by examples the use of means of internal control execution time, and a table of the results obtained (see details in section Appendix 1. The sample application source code).

In the section Supplement 2. Source code means built-in time control the execution of C# application presents the same implementation tools for embedded control in C#.
The author uses a pair of TimeWatcher.StartWatch() and TimeWatcher.StopWatch() when profiling execution time time-consuming (from a computational point of view) methods and procedures in the composition developed by the company ARAMEX software product Delta Design — computer-aided design of electronic equipment.
Below shows an example of a brief report on the time metrics of one of the mentioned functionalities of the product.

Summary


Describes the tools can be used to collect data at the time of execution of the application on different parts of the code, in particular, allow:
 to collect and accumulate data on the time metric threads of execution within the application;
 to execute time evaluation the execution of the program code with an accuracy of basic language structures;
 to control the amount of recoverable data by enabling and disabling the built-in monitoring devices on the respective sections of threads of execution of the application;
 to develop and implement regression tests that control the stability (and
detecting degradation) temporal metrics of the application.

In conclusion, it should be noted that outside the framework of this publication are questions of the application of the tools of internal control in the context of the execution to multi-threaded (multithreading) application and was not represented in any form of analysis of the accuracy of the data obtained at timesof m metrics. The latter is due to the fact that, in practice, in identifying the causes of timeaboutth degradation of applications primarily relevant data aboutotnositelno the distribution of the cost of execution time between software components of the application. In this regard, the issues of accuracy of data pale into insignificance.

Supplement 1. The sample application source code



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(...){...} iterating")
DELAY(1)
} //profile entry for repeating int nn(3); while(nn > 0)
{ PROFILE_ENTRY("2 f11()::while(...){...} iterating")
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() in the try clause") DELAY(1) int rr = 200/jj;
} } catch(...)
{ PROFILE_ENTRY("81 f16() catch clause")
DELAY(2)
return;
}
}
void f17(void)/////////////////////////////////////////
{ PROFILE_ENTRY("f17 9()........................") 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)
}


Appendix 2. Source code means built-in time control the execution of C# application



/// <summary>
/// Class for managing the control points and recording the time of execution of the application in them
/// </summary>
public class TimeWatcher
{ /// <summary>
/// Internal class control point and recording the time of execution in it
/// </summary>
internal class TimeEntry
{ // object registration execution time public Stopwatch timeWatch; // total execution time at this point public long elapsedTime; // constructor public TimeEntry()
{ timeWatch = new Stopwatch(); elapsedTime = 0;
}
} // setting the activity means of recording the time of execution // in control points
private static bool enableTimeWatcher = false; // a dictionary of foreign names checkpoint and was execution time in them
private static Dictionary<string, TimeEntry> entryDictionary = new Dictionary<string, TimeEntry>(); // start of the registration procedure execution time in the specified point
public static void StartWatch(string postfix = "")
{ if (!enableTimeWatcher)
return; string entryName = GetCurrentMethod(); if (postfix != "")
{ entryName += postfix;
} // if point is not found, then register it as a new // otherwise restart the tracking execution time if (!entryDictionary.ContainsKey(entryName))
{ entryDictionary.Add(entryName, new TimeEntry());
entryDictionary[entryName].timeWatch.Start();
}
else
{ if (entryDictionary[entryName].timeWatch.IsRunning)
{ throw new System.InvalidOperationException("ERROR: attempt to re-restart '" + entryName + "' checkpoint.");
}
else
entryDictionary[entryName].timeWatch.Restart();
}
} // check the elapsed execution time of the specified point public static void StopWatch(string postfix = "")
{ if (!enableTimeWatcher)
return; string entryName = GetCurrentMethod(); if (postfix != "")
{ entryName += postfix;
} // if the point is not registered, a query qualifies as incorrect if (!entryDictionary.ContainsKey(entryName))
{ throw new System.InvalidOperationException("ERROR: query execution time in the inde- registered the point of observation '" + entryName + "'.");
} if (!entryDictionary[entryName].timeWatch.IsRunning)
{ throw new System.InvalidOperationException "ERROR: query execution time in the inactive point of observation '" + entryName + "'.");
}
entryDictionary[entryName].timeWatch.Stop(); entryDictionary[entryName].elapsedTime += entryDictionary[entryName].timeWatch.ElapsedMilliseconds;
} // Issue the report about the total execution time of the application // in each registered point public static void TimeWatchReport()
{ const string bar = "============================================="; if (!enableTimeWatcher)
return; Console.WriteLine("");
Console.WriteLine(bar); Console.WriteLine("the Elapsed time in the control points (milliseconds): ");
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;
} // initialisation procedures for tracking execution time of the control points // functionality is relevant only in the presence of the /tmw command line // run the application public static void InitTimeWatch()
{ if (Environment.GetCommandLineArgs().Any(v => v == "/tmw"))
{ if (entryDictionary.Count > 0)
{
TimeWatchReport();
}
entryDictionary.Clear(); enableTimeWatcher = true;
}
} // retrieve the name of the caller in the current context private static string GetCurrentMethod()
{ StackTrace st = new StackTrace(); StackFrame sf = st.GetFrame(2); return sf.GetMethod().Name;
}
} 

Source

Leave a Reply

Your email address will not be published. Required fields are marked *