Click here to Skip to main content
15,896,912 members
Articles / Mobile Apps / Windows Mobile

Basic Instrumentation and Profiling Framework for C++

Rate me:
Please Sign up or sign in to vote.
5.00/5 (15 votes)
9 Oct 2008CPOL27 min read 76.8K   985   50  
Macro based framework written for C++ applications that will allow basic instrumentation and profiling features
/* FnTrace.h ******************************************************************
Author:		Paul Watt
Date:		Friday, August 18, 2006
Purpose:	Declarations and Definitions to help facilitate program instrumentation
			at a function level.  The constructs in this header will allow
			the programmmer to report the entry and exit of all functions 
			instrumented with the macros in this file.  The parameters and
			return value of a function can also be reported.

Use:
			To activate instrumentation, add this define to all modules that
			would like to view the FnTrace mechanism:

			#define FN_INSTRUMENT

			Also, at the beginning scope of each thread that should be logged, 
			this define will also need to be made:

			FN_INSTRUMENT_THREAD;

			This will initialize the thread local storage required to properly 
			instrument the application for each of its distinct threads.

Log Level:
			The default trace level willAc be 5 for functions and parameters. 
			In order to override these values, you can define these two macros
			to change the default definition:

			#define FN_FUNC_LEVEL_DEF FN_X
			#define FN_PARAM_LEVEL_DEF FN_X

			where FN_X is one of these predefined values:
			FN_0: no logging
			FN_1: Minimal reporting
			FN_2: 
			FN_3: Medium reporting
			FN_4: 
			FN_5: Maximal reporting

			FUNC_LEVEL controls the level of function entry reporting.
			PARAM_LEVEL controls the level of parameter reporting for each function.
				PARAM_LEVEL must be <= the TRACE_LEVEL.

			To change the log level at runtime, this macro can be called:
			FN_INSTRUMENT_LEVEL(F, P);

			where F is the new function trace level, and P is the new param level.

Profiling:	
			A simple set of profiling features can be enabled by calling:

			FN_ENABLE_PROFILE(boolVal);

			Where boolVal is true to enable profiling and false to disable it.
			When Profiling is enabled, the FnTrace utilities will count the
			number of times each function is called, as well as a rudimentary
			effort to record the amount of actual time that is spent processing
			each function call.

			The basic profile will be reported at the end when the application
			successfully shutsdown.

Output:
			The reporting can be directed to two locations:
			OutputDebugStream (default), when your application is attached to a 
				debugger, or some other type of application that can read the 
				debug string can capture the output for your analysis.
			clog: Activate with #define FN_OUTPUT_CLOG, the clog data will be
				directed to the output stream.  This output stream can then 
				be directed to a file or any other mechanism desired by your app.

			
******************************************************************************/
#ifndef __FNTRACE_H
#define __FNTRACE_H

/* FnTrace will only work in C++ when Enabled ********************************/
#if defined(__cplusplus) && defined(FN_INSTRUMENT)
const unsigned short FN_0 = 0;
const unsigned short FN_1 = 1;
const unsigned short FN_2 = 2;
const unsigned short FN_3 = 3;
const unsigned short FN_4 = 4;
const unsigned short FN_5 = 5;

#include <iostream>

#if defined(WIN32) && !defined(FN_OUTPUT_CLOG)
#include <sstream>
#include <windows.h>
#else
#include <iostream>
#endif //#if defined(WIN32) && !defined(FN_OUTPUT_CLOG)

/* Timing Headers ************************************************************/
#if defined(WIN32)
#include <stack>
#include <utility>
#endif

/* Macros to Facilitate Function Instrumentation *****************************/
#include <boost/preprocessor/array/elem.hpp>
#include <boost/preprocessor/array/pop_front.hpp>
#include <boost/preprocessor/array/size.hpp>
#include <boost/preprocessor/control/if.hpp> 
#include <boost/preprocessor/comparison/not_equal.hpp>
#include <boost/preprocessor/repetition/for.hpp>
#include <boost/preprocessor/stringize.hpp>

/* Default Trace Definitions *************************************************/
#ifndef FN_FUNC_LEVEL_DEF
#define FN_FUNC_LEVEL_DEF FN_5 /* Default Function Trace Level */

#endif

#ifndef FN_PARAM_LEVEL_DEF
#define FN_PARAM_LEVEL_DEF FN_5 /* Default Function Trace Level */ 
#endif

#ifndef FN_PROLOG
#ifdef WIN32
#define FN_PROLOG ::GetCurrentThreadId()
#else
#define FN_PROLOG "-"
#endif
#endif

/* MACRO **********************************************************************
Purpose:	Dynamically Changes the profiling state of the system.
Parameters:	B: 0(default is off) indicates no profiling, 1 enables profiling.

Ex:
			// Enable profiling
			FN_SET_INSTRUMENT(1);
******************************************************************************/
#define FN_ENABLE_PROFILE(B) fn::fnIsEnableProfile = B


/* MACRO **********************************************************************
Purpose:	Dynamically Changes Trace Levels at Runtime
Parameters:	F: The new function trace level, FN_0 through FN_5
			P: The new parameter trace level, FN_0 through FN_5
Ex:
			// Sets the function level tracing to f(all), and parameter
			// level tracing to 2 (slightly more than minimal level)
			FN_SET_INSTRUMENT(FN_5, FN_2);
******************************************************************************/
#define FN_INSTRUMENT_LEVEL(F, P) fn::fnTraceLevel = F; fn::fnParamLevel = min(P,fn::fnTraceLevel)

/* MACRO **********************************************************************
Purpose:	Initiates Tracing for a Thread.  This MACRO needs to be defined
			at the scope for each thread where function tracing should occur.
			This MACRO should only be declared once per thread, otherwise
			a memory leak will occur.
Parameters:	NONE		
Ex:
			FN_INSTRUMENT_THREAD;
******************************************************************************/
#define FN_INSTRUMENT_THREAD fn::CFnInstrumentThread __fnInstThread

/* HELPER MACRO ***************************************************************
Purpose:	Enables Tracing for Function with Parameters.  This macro should
			not be called directly.  Other macros use this macro.
Parameters:	A: Boost array definition of the form (n, (e0, e1, ..., 2n-1))
			level: The tracing level of this function.
Ex:
			
******************************************************************************/
#define _PRED_SIZE(r, state) BOOST_PP_ARRAY_SIZE(state) 
#define _OP_POP(r, state) BOOST_PP_ARRAY_POP_FRONT(state)
#define _MACRO_PARAM(r, state) FN_PARAM(BOOST_PP_ARRAY_ELEM(0, state))
#define _FN_PRINT_PARAMS(A, level) \
			if (fn::fnParamLevel >= level) \
			{ \
				BOOST_PP_FOR(A, _PRED_SIZE, _OP_POP, _MACRO_PARAM) \
			}

/* MACRO **********************************************************************
Purpose:	Enables Tracing for a Function.
Parameters:	retType: The type of the return value.  For functions that have
				a void return type, use the FN_VOID define as the return type.
			level: The tracing level of this function.
Ex:
			FN_FUNC(bool, FN_1);
******************************************************************************/
#define FN_FUNC(retType, level) \
			static fn::CFnParams<##retType##> __fnParamObj(__FUNCSIG__);\
			fn::CFnTrace<##retType##> __fnTraceObj(&__fnParamObj, level); 

/* MACRO **********************************************************************
Purpose:	Logs entry to a function to prepare for possible later checkpoint
			reporting.
Parameters:	level: The tracing level of this function.
Ex:
			
******************************************************************************/
#define FN_ENTRY(level) \
			static fn::CFnParams<FN_VOID> __fnParamObj(__FUNCSIG__);\
			fn::CFnTrace<FN_VOID> __fnTraceObj(&__fnParamObj, level, true); 

/* MACRO **********************************************************************
Purpose:	OUTPUT macro for general comments to instrumentation log.
Parameters:	output: ostream output, using operator << as well as basic_io
				formatters to generate any output for the display.  
				User-defined types such as classes can provide their own implementation
				for the operator << in order to output their values to the log.
Ex:
			int x = 4;
			int y = 5;
			FN_OUTPUT("The sum of x + y = " << (x+y));			

			//result: 
			//The sum of x + y = 9

Notes:		There are two versions of this macro, one that will write to clog, 
			and the other will write to the OutputDebugString function.
			OutputDebugString is the default.  To change to clog, define:
				#define FN_OUTPUT_CLOG
******************************************************************************/
#if defined(WIN32) && !defined(FN_OUTPUT_CLOG)
#define _FN_CLEAR_OUTPUT() \
			if (_FN_IS_INST) \
			{ \
				_FN_GET_LOG->rdbuf()->pubseekpos(0); \
			}
#define FN_OUTPUT(output) \
			if (_FN_IS_INST) \
			{ \
				std::wostringstream *pLog = _FN_GET_LOG; \
				*pLog << FN_PROLOG << ": "; \
				fn::__IndentTrace(); \
				*pLog << ##output## << "\n" << std::ends; \
				::OutputDebugString(pLog->str().c_str()); \
				pLog->rdbuf()->pubseekpos(0); \
			}
#else
#define _FN_CLEAR_OUTPUT()  
#define FN_OUTPUT(output) \
			if (_FN_IS_INST) \
			{ \
				std::clog << FN_PROLOG << ": "; \
				fn::__IndentTrace(); \
				std::clog << ##output## << std::endl; \
			}
#endif

/* MACRO **********************************************************************
Purpose:	Enables Return Value Tracing.  Set the value to be returned by the
			function into retVal before calling return.
Parameters:	retVal: The name of variable that will be returned when the function
			exits.
Ex:
			bool retVal;
			FN_RETVAL(retVal);
******************************************************************************/
#define FN_RETVAL(retVal) __fnTraceObj.SetRetVal(&retVal)

/* MACRO **********************************************************************
Purpose:	Enables Function Trace with Return Value.  Set the value to be 
			returned by the function into retVal before calling return.
Parameters:	retType: The type of the return value.  For functions that have
				a void return type, use the FN_VOID define as the return type.
			retVal: is the same type as the return value for the function.
			level: The tracing level of this function.
Ex:			
			bool retVal;
			FN_FUNC_RETVAL(bool, retVal, FN_1);
******************************************************************************/
#define FN_FUNC_RETVAL(retType, retVar, level)\
			FN_FUNC(retType, level);\
			FN_RETVAL(retVar)	

/* MACRO **********************************************************************
Purpose:	Outputs the value for a specified parameter.  This macro is automatically
			called as part of the FN_FUNC_PARAMS macro.  This macro can be 
			used to report the value of any datatype that supports an operator<<
			for the wostream.
Parameters:	param: The variable to display the output for.
Ex:
			int x = 100;
			FN_PARAM(x);

			//result: 
			//x = 100
******************************************************************************/
#define FN_PARAM(param)   FN_OUTPUT(BOOST_PP_STRINGIZE(param) << " = " << ##param##)

//C: This feature requires support for variadic macros, which appeared in 
//   Microsoft Visual Studio 2005.  Add other defintions as new compilers are discovered.
#if _MSC_VER >= 1400
/* MACRO **********************************************************************
Purpose:	Enables Function Trace with Return Value and parameter reporting.  
			Set the value to be returned by the function into retVal before calling return.
			Indicate the number of parameters to be reported, followed by
			the comma delimited list of all of the parameters.
Parameters:	retType: The type of the return value.  For functions that have
				a void return type, use the FN_VOID define as the return type.
			retVal: is the same type as the return value for the function.
			level: The tracing level of this function.
			n: The number of parameters to be reported when this function enters scope.
			...: A comma delimited list of all of the parameters to report values.
Ex:			
			bool function(int x, char* y, double z)
			{
				bool retVal;
				FN_FUNC_RETVAL(bool, retVal, FN_1, 3, x, y, z);
				// ... 
			}

			//function(10, "hello", 3.14); 
			//result: 
			//x = 10
			//y = hello
			//z = 3.14

******************************************************************************/
#define FN_FUNC_PARAMS(retType, retVar, level, n, ...)\
			FN_FUNC(retType, level);\
			_FN_PRINT_PARAMS((n, (__VA_ARGS__)), level);\
			FN_RETVAL(retVar);

/* MACRO **********************************************************************
Purpose:	Reports data at a checkpoint with a label and parameters.  
			Indicate the number of parameters to be reported, followed by
			the comma delimited list of all of the parameters.
Parameters:	label: A label to be reported for this checkpoint.
			level: The tracing level of this function.
			n: The number of parameters to be reported when this function enters scope.
			...: A comma delimited list of all of the parameters to report values.
Ex:			
			FN_ENTRY(FN_3);

			case WM_COMMAND:
			{
				FN_CHECKPOINT("WM_COMMAND", FN_1, 3, x, y, z);
				// ... 
			}

******************************************************************************/
#define FN_CHECKPOINT(label, level, n, ...)\
			__fnTraceObj.FlushCache(); \
			FN_OUTPUT(label); \
			_FN_INC_INDENT; \
			_FN_PRINT_PARAMS((n, (__VA_ARGS__)), level); \
			_FN_DEC_INDENT; 

#endif //#if _MSC_VER >= 1400

/* MACRO **********************************************************************
Purpose:	Enables Function Trace with Return Value and parameter reporting.  
			Set the value to be returned by the function into retVal before calling return.
			Indicate the number of parameters to be reported, followed by
			the comma delimited list of all of the parameters.
Notes:		Same as FN_FUNC_PARAMS, except these do not require the variadic
			macro feature, and therefore should be more portable across 
			different compiler platforms.
******************************************************************************/
#define FN_FUNC_PARAMS_1(retType, retVar, level, p0)\
			FN_FUNC(retType, level);\
			FN_RETVAL(retVar);\
			FN_PARAM(p0);

#define FN_FUNC_PARAMS_2(retType, retVar, level, p0, p1)\
			FN_FUNC_PARAMS_1(retType, retVar, level, p0)\
			FN_PARAM(p1);

#define FN_FUNC_PARAMS_3(retType, retVar, level, p0, p1, p2)\
			FN_FUNC_PARAMS_2(retType, retVar, level, p0, p1)\
			FN_PARAM(p2);

#define FN_FUNC_PARAMS_4(retType, retVar, level, p0, p1, p2, p3)\
			FN_FUNC_PARAMS_3(retType, retVar, level, p0, p1, p2)\
			FN_PARAM(p3);

#define FN_FUNC_PARAMS_5(retType, retVar, level, p0, p1, p2, p3, p4)\
			FN_FUNC_PARAMS_4(retType, retVar, level, p0, p1, p2, p3)\
			FN_PARAM(p4);

#define FN_FUNC_PARAMS_6(retType, retVar, level, p0, p1, p2, p3, p4, p5)\
			FN_FUNC_PARAMS_5(retType, retVar, level, p0, p1, p2, p3, p4)\
			FN_PARAM(p5);

#define FN_FUNC_PARAMS_7(retType, retVar, level, p0, p1, p2, p3, p4, p5, p6)\
			FN_FUNC_PARAMS_6(retType, retVar, level, p0, p1, p2, p3, p4, p5)\
			FN_PARAM(p6);

/* MACRO **********************************************************************
Purpose:	Reports a scope label and parameters.  
			Indicate the number of parameters to be reported, followed by
			the comma delimited list of all of the parameters.
Notes:		Same as FN_CHECKPOINT, except these do not require the variadic
			macro feature, and therefore should be more portable across 
			different compiler platforms.
******************************************************************************/
#define FN_CHECKPOINT_1(label, level, p0)\
			FN_OUTPUT(label);\
			FN_PARAM(p0);

#define FN_CHECKPOINT_2(label, level, p0, p1)\
			FN_CHECKPOINT_1(label, level, p0)\
			FN_PARAM(p1);

#define FN_CHECKPOINT_3(label, level, p0, p1, p2)\
			FN_CHECKPOINT_2(label, level, p0, p1)\
			FN_PARAM(p2);

#define FN_CHECKPOINT_4(label, level, p0, p1, p2, p3)\
			FN_CHECKPOINT_3(label, level, p0, p1, p2)\
			FN_PARAM(p3);

#define FN_CHECKPOINT_5(label, level, p0, p1, p2, p3, p4)\
			FN_CHECKPOINT_4(label, level, p0, p1, p2, p3)\
			FN_PARAM(p4);

#define FN_CHECKPOINT_6(label, level, p0, p1, p2, p3, p4, p5)\
			FN_CHECKPOINT_5(label, level, p0, p1, p2, p3, p4)\
			FN_PARAM(p5);

#define FN_CHECKPOINT_7(label, level, p0, p1, p2, p3, p4, p5, p6)\
			FN_CHECKPOINT_6(label, level, p0, p1, p2, p3, p4, p5)\
			FN_PARAM(p6);

/* MACRO **********************************************************************
Purpose:	Pauses the timer that records the amount of time spent inside of 
			a single function scope.
Notes:		One of the FN_FUNC_X macros must have been defined in the function
			scope before this macro, otherwise a compiler error will occur.
			Function profiling must be active for this MACRO to have any effect.
******************************************************************************/
#define FN_PAUSE() __fnParamObj.Pause()

/* MACRO **********************************************************************
Purpose:	Resumes the timer that records the amount of time spent inside of 
			a single function scope.
Notes:		One of the FN_FUNC_X macros must have been defined in the function
			scope before this macro, otherwise a compiler error will occur.
			Function profiling must be active for this MACRO to have any effect.
******************************************************************************/
#define FN_RESUME() __fnParamObj.Resume()

/* Portability Macros ********************************************************/
//C: Macro definition for thread-local storage compiler specifiers.
#ifdef _MSC_VER
	#ifdef UNDER_CE
		#define _FN_TLS
		#define _FN_IS_INST	(fn::CE_ISInst())
		#define _FN_GET_INDENT (fn::CE_GetIndent(0))
		#define _FN_DEC_INDENT (fn::CE_GetIndent(1))
		#define _FN_INC_INDENT (fn::CE_GetIndent(2))
		#define _FN_GET_LOG (reinterpret_cast<std::wostringstream*>(::TlsGetValue(fn::logIndex)))
		#define _FN_GET_TIME_STACK (reinterpret_cast<std::stack<fn::timeEdge>*>(::TlsGetValue(fn::stackIndex)))
	#else
		#define _FN_TLS _declspec(thread)
		#define _FN_IS_INST fn::isInstrumentThread
		#define _FN_GET_INDENT (fn::indentLevel)
		#define _FN_DEC_INDENT (--fn::indentLevel)
		#define _FN_INC_INDENT (++fn::indentLevel)
		#define _FN_GET_LOG (fn::pInstLog)
		#define _FN_GET_TIME_STACK (fn::pTimeStack)
	#endif
#else
	#define _FN_TLS __thread
	#define _FN_IS_INST isInstrumentThread
	#define _FN_GET_INDENT (indentLevel)
	#define _FN_DEC_INDENT (--indentLevel)
	#define _FN_INC_INDENT (++indentLevel)
	#define _FN_GET_LOG 0
	#define _FN_GET_TIME_STACK 0
#endif

/* Nothing to see here, ignore the man behind the curtains *******************/
/* fn Namespace **************************************************************/
namespace fn
{
/* Data Members **************************************************************/
//C: Trace level values for the FnTrace system.
static unsigned short fnTraceLevel = FN_FUNC_LEVEL_DEF; 
static unsigned short fnParamLevel = FN_PARAM_LEVEL_DEF; 
//C: Sets the enable state for profiling.
static int			  fnIsEnableProfile	= 0;

//C: TLS value that indicates if the current thread should instrument.
static _FN_TLS bool			isInstrumentThread = false;
static unsigned long		instrumentIndex = 0xFFFFFFFF;
//C: TLS value that indicates the tab depth for the curretn thread.
static _FN_TLS unsigned int	indentLevel = 0;
static unsigned long		indentIndex = 0xFFFFFFFF;

#ifndef FN_OUTPUT_CLOG
//C: TLS stream object to assist transfer data to the OutputDebugString.
static _FN_TLS std::wostringstream	*pInstLog = NULL;
static unsigned long				logIndex = 0xFFFFFFFF;
#endif

#ifdef WIN32
//C: timeEdge: Structure to help profile function time.
//		e1: Start time, 
//		e2: Pause period
typedef std::pair<DWORD, DWORD>	timeEdge;
static _FN_TLS std::stack<timeEdge> *pTimeStack = NULL;
static unsigned long				stackIndex = 0xFFFFFFFF;
#endif

//C: Count for the total number of thread objects that are instrumenting.
static unsigned int threadCount = 0;

/* Helper functions **********************************************************/
#ifdef _MSC_VER
#ifdef UNDER_CE

/* Global *********************************************************************
Author:		Paul Watt
Date:		Saturday, October 04, 2008
Purpose:	Helper to properly determine if the current CE thread is instrumenting.
Parameters: NONE
Return:		If instrumentation is active for this thread, then true will be
			returned otherwise false.
******************************************************************************/
inline bool CE_ISInst()
{
	LPVOID pVal = ::TlsGetValue(fn::instrumentIndex);
	return (pVal && *(bool*)pVal);
}

/* Global *********************************************************************
Author:		Paul Watt
Date:		Saturday, October 04, 2008
Purpose:	Helper to properly retrieve the TLS indent level for the thread.
Parameters:	command[in]: The type of command related to the indent level:
				0: get value
				1: decrement value
				2: increment value.
Return:		The indent level will be returned.
******************************************************************************/
inline unsigned int CE_GetIndent(int command)
{
	LPVOID pVal = ::TlsGetValue(fn::indentIndex);
	if (pVal)
	{
		switch (command)
		{
		case 0: // return value
			return *(unsigned int*)pVal;
		case 1: // decrement value
			return (--(*(unsigned int*)pVal));
		case 2: // increment value
			return (++(*(unsigned int*)pVal));
		}
	}

	//C: The TLS is not present.
	return 0;
}
#endif //#ifdef _MSC_VER
#endif //#ifdef UNDER_CE

/* Global *********************************************************************
Author:		Paul Watt
Date:		Friday, August 18, 2006
Purpose:	Indents the output by a system level depth.
Parameters:	NONE
Return:		-
******************************************************************************/
inline void __IndentTrace()
{
	unsigned int indent = _FN_GET_INDENT;
	for (unsigned int index = 0; index < indent; index++)
	{
		if (_FN_IS_INST)
		{
#ifdef FN_OUTPUT_CLOG
			std::clog << "  ";
#else
			*_FN_GET_LOG << "  ";
#endif
		}
	}
}

/* Class Definitions *********************************************************/
/* Class **********************************************************************
Author:		Paul Watt
Date:		9/27/2008
Purpose:	Stack object that will initialize the instrumentation for the 
			current thread.
******************************************************************************/
class CFnInstrumentThread
{
public:
	
	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Default Contructor, initializes current thread for function instrumentation.	
	******************************************************************************/
	CFnInstrumentThread ()
	{
#ifdef UNDER_CE
		//C: Test if TLS has already been allocated.
		if (0 == threadCount)
		{
			//C: Allocate TLS space for all of the variables.
			instrumentIndex = ::TlsAlloc();
			indentIndex = ::TlsAlloc();
			logIndex = ::TlsAlloc();
			stackIndex = ::TlsAlloc();
		}

		++threadCount;
		bool isTLSAllocated = false;
		if (0xFFFFFFFF != instrumentIndex &&
			0xFFFFFFFF != indentIndex &&
			0xFFFFFFFF != logIndex &&
			0xFFFFFFFF != stackIndex)
		{
			isTLSAllocated = true;

			LPVOID pVal;
			//C: Enable tracing for this thread.
			::TlsSetValue(instrumentIndex, (void*)new bool);
			pVal = ::TlsGetValue(instrumentIndex);
			if (pVal)
			{
				*(bool*)pVal = true;
			}
			else
			{
				isTLSAllocated = false;
			}

			//C: Allocate a buffer for the indent count.
			::TlsSetValue(indentIndex, (void*)new unsigned int);
			pVal = ::TlsGetValue(indentIndex);
			if (pVal)
			{
				*(unsigned int*)pVal = 0;
			}
			else
			{
				isTLSAllocated = false;
			}

#ifndef FN_OUTPUT_CLOG
			//C: Allocate the wostring buffer for output.
			::TlsSetValue(logIndex, (void*)new std::wostringstream);
			pVal = ::TlsGetValue(logIndex);
			if (!pVal)
			{
				FN_OUTPUT(L"ERROR: Could not allocate the output stream, instrumentation will be disabled.");
				isTLSAllocated = false;
			}
#endif

#ifdef WIN32
			//C: Allocate a stack object for function profiling.
			::TlsSetValue(stackIndex, (void*)new std::stack<timeEdge>);
			pVal = ::TlsGetValue(stackIndex);
			if (!pVal)
			{
				FN_OUTPUT(L"ERROR: Could not allocate time Stack, function profiling will not be available.");
				isTLSAllocated = false;
			}
#endif
		}
		
		if (!isTLSAllocated)
		{
			H_Destroy();
			return;
		}

#endif

#ifdef FN_OUTPUT_CLOG
		isInstrumentThread = true;
#else
		pInstLog = new std::wostringstream;
		if (pInstLog)
		{
			isInstrumentThread = true;
		}
#endif

#ifdef WIN32
		pTimeStack = new std::stack<timeEdge>;
		if (!pTimeStack)
		{
			//C: The time stack could not be created, uninitialize the logging.
			delete pInstLog;
			pInstLog = NULL;
			isInstrumentThread = false;
		}
#endif

	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Destructor
	******************************************************************************/
	~CFnInstrumentThread ()
	{
		H_Destroy();
	}

protected:
	void H_Destroy ()
	{
#ifdef UNDER_CE
		delete ::TlsGetValue(instrumentIndex);
		delete ::TlsGetValue(indentIndex);
#ifndef FN_OUTPUT_CLOG
		delete ::TlsGetValue(logIndex);
#endif
#ifdef WIN32
		delete ::TlsGetValue(stackIndex);
#endif
		--threadCount;
		if (0 == threadCount)
		{
			//C: Free the space for the TLS vars.  There are no more thread objects active.
			::TlsFree(instrumentIndex);
			::TlsFree(indentIndex);
#ifndef FN_OUTPUT_CLOG
			::TlsFree(logIndex);
#endif
#ifdef WIN32
			::TlsFree(stackIndex);
#endif
		}

#else
#ifndef FN_OUTPUT_CLOG
		delete pInstLog;
		pInstLog = NULL;
#endif

#ifdef WIN32
		delete pTimeStack;
		pTimeStack = NULL;
#endif
#endif //#ifdef UNDER_CE

		isInstrumentThread = false;
	}
};

/* Class **********************************************************************
Author:		Paul Watt
Date:		09/22/2008
Purpose:	Traces the parameter and return values of a called function.
******************************************************************************/
template <typename T>
class CFnParams
{
public:
	char*			m_pFunction;
	unsigned long	m_count;
	bool			m_isTimerActive;
	DWORD			m_totalUsage;

public:
	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Default Contructor, Initializes function count as well as the name
				of the function for reporting.
	******************************************************************************/
	CFnParams(char* function) :
		m_count(0),
		m_isTimerActive(false),
		m_totalUsage(0)
	{
		//C: Record the name of the function this object is tracing.
		if (function)
		{
			m_pFunction = function;
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Destructor, reports function statistics if enabled on exit.
	******************************************************************************/
	~CFnParams() 
	{
		//C: Only report if profiling is enabled.
		if (0 == fnIsEnableProfile)
		{
			//C: Report the number of times this function was called.
			FN_OUTPUT("Summary:\t" << m_pFunction);
			FN_OUTPUT("  Called:\t" << m_count);
			FN_OUTPUT("  Time:\t" << m_totalUsage << "ms");
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Records when this functions scope is entered for profiling.	
	Return:		The total delay recorded on the local stack will be returned.
	******************************************************************************/
	DWORD Enter()
	{
		//C: Do not continue if profiling is disabled.
		if (0 == fnIsEnableProfile)
		{
			return 0;
		}
		//C: Increment the call count for this function.
		++m_count;

		DWORD delay = 0;
		//C: Record the total delay up to this point.
		std::stack<timeEdge> *pStack = _FN_GET_TIME_STACK;
		if (pStack &&
			pStack->size())
		{
			timeEdge& top = pStack->top();
			delay = top.second;
		}

		//C: Start the clock.
		Resume();

		return delay;
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Records when this functions scope is exited for profiling.	
	Parameters:	stackDelay[in]: The amount of delay that has propagated further up
					the stack.  This delay will be reported down to the callers.
	******************************************************************************/
	void Leave(DWORD stackDelay, bool isDisplay)
	{
		//C: Do not continue if profiling is disabled.
		if (0 == fnIsEnableProfile)
		{
			return;
		}

		//C: Pause the clock.
		if (isDisplay)
		{
			//C: output elapesed time.
			FN_OUTPUT("elapsed:\t" << Pause() << "ms");
		}
		else
		{
			//C: Only Pause the clock, no output.
			Pause();
		}

		//C: If there are items already on the stack, carry the reported delay forward.
		std::stack<timeEdge> *pStack = _FN_GET_TIME_STACK;
		if (pStack &&
			pStack->size())
		{
			timeEdge& top = pStack->top();
			top.second += stackDelay;
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Pauses function time profiling for this function, and updates the 
				total usage time.
	Return:		The usage of the most recent execute section will be returned.
	******************************************************************************/
	DWORD Pause()
	{
		//C: Do not continue if profiling is disabled.
		if (0 == fnIsEnableProfile)
		{
			return 0;
		}

		std::stack<timeEdge> *pStack = _FN_GET_TIME_STACK;
		if (pStack &&
			m_isTimerActive)
		{
#ifdef WIN32

			//C: Remove the start time from the stack.
			timeEdge curEdge = pStack->top();
			pStack->pop();
			//C: Record the end time.
			DWORD curTime = ::GetTickCount();
			//C: Calculate the usage for this instance.
			DWORD usage;
			usage = curTime - curEdge.first;
			//C: Subtract pause delay.
			usage -= curEdge.second;
			//C: Add the diff to the total time spent in this function.
			m_totalUsage += usage;
			//C: If there are any other items on the time stack, 
			if (pStack->size())
			{
				//C: Add this functions current usage to the delay counter.
				timeEdge& callerEdge = pStack->top();
				callerEdge.second = curEdge.second + usage;
			}

			m_isTimerActive = false;
			return usage;
#endif
		}

		return 0;
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Resumes function time profiling for this function, and updates the 
				total usage time.
	******************************************************************************/
	void Resume()
	{
		//C: Do not continue if profiling is disabled.
		if (0 == fnIsEnableProfile)
		{
			return;
		}

		//C: Don't try to resume of the timer is already active.
		std::stack<timeEdge> *pStack = _FN_GET_TIME_STACK;
		if (pStack &&
			!m_isTimerActive)
		{
#ifdef WIN32
			//C: Record the start time.
			DWORD curTime = ::GetTickCount();
			//C: Place this time on the stack.
			timeEdge cur(curTime, 0);
			pStack->push(cur);
			m_isTimerActive = true;	
#endif
		}
	}

private:
	/* Hidden functions, do not implement ****************************************/
	CFnParams();
};


/* Class **********************************************************************
Author:		Paul Watt
Date:		Friday, August 18, 2006
Purpose:	Stack based object that will report when a function exits, and will
			report its return value if configured to do so.
******************************************************************************/
template <typename T>
class CFnTrace
{
public:
	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Default Contructor, Initializes base function stats, and records
				function entry.
	******************************************************************************/
	CFnTrace(CFnParams<T> *pParams, unsigned short level, bool isCache = false) :
	  m_pRetVal(NULL),
	  m_level(level),
	  m_pParams(pParams),
	  m_delay(0),
	  m_isCache(isCache),
	  m_isFlushCache(!m_isCache)
	{
		if (fnTraceLevel >= m_level)
		{
			m_delay = m_pParams->Enter();
			//C: Output function entry.
			if (!m_isCache)
			{
				FN_OUTPUT(m_pParams->m_pFunction);
			}
			//C: Increment the indent level.
			_FN_INC_INDENT;
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Destructor, reports the return value if specified as well as records
				function exit.
	******************************************************************************/
	~CFnTrace()
	{
		if (fnParamLevel >= m_level ||
			fnTraceLevel >= m_level)
		{
			m_pParams->Leave(m_delay, m_isFlushCache);
			//C: Decrement the indent level.
			_FN_DEC_INDENT;

			if (!m_isCache)
			{
				if (fnParamLevel >= m_level)
				{
					//C: Report the value of the return type if any.
					FN_OUTPUT("return (" << Return() << ");");
				}
				else
				{
					FN_OUTPUT("leave;");
				}
			}
			else if (m_isFlushCache)
			{
				FN_OUTPUT("leave;}");
			}
		}

		_FN_CLEAR_OUTPUT();
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Sets the address of the return buffer into this object so that it
				can report its value on exit of the function scope.	
	******************************************************************************/
	void SetRetVal(T *retVal)
	{
		if (retVal)
		{
			m_pRetVal = retVal;
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Saturday, September 27, 2008
	Purpose:	Returns the value for the specified return address.  If the address
				for the return buffer was never configured, then a message will
				indicate this state.
	******************************************************************************/
	T Return()
	{
		if (m_pRetVal)
		{
			return *m_pRetVal;
		}
		else
		{
			FN_OUTPUT("Return value unassigned");
			return T();
		}
	}

	/* Public *********************************************************************
	Author:		Paul Watt
	Date:		Sunday, October 05, 2008
	Purpose:	Flushes the cache for this instance of the function call.	
	******************************************************************************/
	void FlushCache()
	{
		if (!m_isFlushCache)
		{
			//C: Report the function name, and add an indent.
			_FN_DEC_INDENT;
			FN_OUTPUT(m_pParams->m_pFunction);
			//C: Increment the indent level.
			_FN_INC_INDENT;

			m_isFlushCache = true;
		}
	}

protected:
	unsigned short	m_level;
	CFnParams<T>	*m_pParams;
	T*				m_pRetVal;

	DWORD			m_delay;

	bool			m_isCache;
	bool			m_isFlushCache;
private:
	/* Hidden functions, do not implement ****************************************/
	CFnTrace();
};

} // namespace fn

/* Class **********************************************************************
Author:		Paul Watt
Date:		9/27/2008
Purpose:	Empty class definition to act as a place holder for void return types.
******************************************************************************/
struct FN_VOID{};
/* Public *********************************************************************
Author:		Paul Watt
Date:		Saturday, September 27, 2008
Purpose:	OStringStream implementation for the VOID Trace return placeholder.
******************************************************************************/
inline std::wostream& operator<<(std::wostream& os, const FN_VOID& _Val)
{
	os << L"void";
	return os;
}

#else
// Disable all of the macros in regular C, or if instrumentation is not active.
#define FN_ENABLE_PROFILE(b) ;
#define FN_INSTRUMENT_LEVEL(F, P) ;
#define FN_INSTRUMENT_THREAD ;
#define FN_ENTRY(level) ;
#define FN_FUNC(retType, level) ;
#define FN_FUNC_RETVAL(retType, retVar, level) ;

#if _MSC_VER >= 1400
#define FN_FUNC_PARAMS(retType, retVar, level, n, ...) ;
#define FN_CHECKPOINT(label, level, n, ...) ;
#endif //#if _MSC_VER >= 1400

#define FN_FUNC_PARAMS_1(retType, retVar, level, p0) ;
#define FN_FUNC_PARAMS_2(retType, retVar, level, p0, p1) ;
#define FN_FUNC_PARAMS_3(retType, retVar, level, p0, p1, p2) ;
#define FN_FUNC_PARAMS_4(retType, retVar, level, p0, p1, p2, p3) ;
#define FN_FUNC_PARAMS_5(retType, retVar, level, p0, p1, p2, p3, p4) ;
#define FN_FUNC_PARAMS_6(retType, retVar, level, p0, p1, p2, p3, p4, p5) ;
#define FN_FUNC_PARAMS_7(retType, retVar, level, p0, p1, p2, p3, p4, p5, p6) ;

#define FN_CHECKPOINT_1(label, level, p0) ;
#define FN_CHECKPOINT_2(label, level, p0, p1) ;
#define FN_CHECKPOINT_3(label, level, p0, p1, p2) ;
#define FN_CHECKPOINT_4(label, level, p0, p1, p2, p3) ;
#define FN_CHECKPOINT_5(label, level, p0, p1, p2, p3, p4) ;
#define FN_CHECKPOINT_6(label, level, p0, p1, p2, p3, p4, p5) ;
#define FN_CHECKPOINT_7(label, level, p0, p1, p2, p3, p4, p5, p6) ;

#define FN_OUTPUT(output) ;
#define FN_PARAM(param) ;
#define FN_PAUSE() ;
#define FN_RESUME() ;
#define FN_RETVAL(retVal) ;

#define FN_0
#define FN_1
#define FN_2
#define FN_3
#define FN_4
#define FN_5

#endif // #ifdef __cplusplus && defined(FN_INSTRUMENT)
#endif // #ifndef __TRACE_H

By viewing downloads associated with this article you agree to the Terms of Service and the article's licence.

If a file you wish to view isn't highlighted, and is a text file (not binary), please let us know and we'll add colourisation support for it.

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)


Written By
Engineer
United States United States
I am a software architect and I have been developing software for nearly two decades. Over the years I have learned to value maintainable solutions first. This has allowed me to adapt my projects to meet the challenges that inevitably appear during development. I use the most beneficial short-term achievements to drive the software I develop towards a long-term vision.

C++ is my strongest language. However, I have also used x86 ASM, ARM ASM, C, C#, JAVA, Python, and JavaScript to solve programming problems. I have worked in a variety of industries throughout my career, which include:
• Manufacturing
• Consumer Products
• Virtualization
• Computer Infrastructure Management
• DoD Contracting

My experience spans these hardware types and operating systems:
• Desktop
o Windows (Full-stack: GUI, Application, Service, Kernel Driver)
o Linux (Application, Daemon)
• Mobile Devices
o Windows CE / Windows Phone
o Linux
• Embedded Devices
o VxWorks (RTOS)
o Greenhills Linux
o Embedded Windows XP

I am a Mentor and frequent contributor to CodeProject.com with tutorial articles that teach others about the inner workings of the Windows APIs.

I am the creator of an open source project on GitHub called Alchemy[^], which is an open-source compile-time data serialization library.

I maintain my own repository and blog at CodeOfTheDamned.com/[^], because code maintenance does not have to be a living hell.

Comments and Discussions