Tracing of C++ Code Execution

Sometimes it’s quite handy to have ability of seeing what is being executed and how much time does it take. Ok, so lets define several helpers in order to have that ability.

#define TRACE_BEGIN_EX(what, watch) \
	std::clog << what << std::endl; \
	watch.restart()

#define TRACE_END_EX(what, watch) \
	watch.stop(); \
	std::clog << what << \
	" Time: " << watch.getElapsedSeconds() << "s." << std::endl

Have you spotted that parameter “watch”? It is an instance of the following class.

/*!
	Represents stopwatch for measuring code execution time.
*/
class Stopwatch
{
public:
	/*!
		Initializes and starts stopwatch.
	*/
	Stopwatch();

	/*!
		Clears elapsed time value and starts stopwatch.
	*/
	void restart();

	/*!
		Stops stopwatch.
	*/
	void stop();

	/*!
		Returns number of elapsed seconds since start.
	*/
	numeric_t getElapsedSeconds() const;

private:
	clock_t _begin;
	numeric_t _length;
};

If you wonder what is “numeric_t” – this is nothing but simple alias of “float”. So, lets see an example of usage (excerpt from the source code).

...
TRACE_BEGIN_EX("Application started (MPI process #"
		<< _processIndex << ").", _watch);
...
TRACE_END_EX("Application finished (MPI process #"
		<< _processIndex << ").", _watch);

It will be more useful if we’ll introduce few new macros.

#define TRACE_PREPARE \
	Stopwatch __trace_stopwatch; \
	std::ostringstream __trace_ostream; \
	std::string __trace_subject

#define TRACE_BEGIN(what) \
	__trace_ostream.str(std::string()); \
	__trace_ostream << what; \
	__trace_subject = __trace_ostream.str(); \
	TRACE_BEGIN_EX("Started: " << __trace_subject << ".", __trace_stopwatch)

#define TRACE_END \
	TRACE_END_EX("Finished: " << __trace_subject << ".", __trace_stopwatch)

#define TRACE(message, action) \
	TRACE_BEGIN(message); \
	{action;} \
	TRACE_END

So now we are able to write something like this (excerpt from source code of image fusion application).

TRACE("transformation and transfer of fused image",
{
	saveChannel(0);
	saveChannel(1);
	saveChannel(2);
});

Ok, once we have compiled and run application, we can see something like this.

...
Started: transformation and transfer of fused image.
Finished: transformation and transfer of fused image. Time: 0.15s.
...

Good, but what if we releasing production version and tracing no more needed? That’s simple! Lets change our macros.

#if defined(_TRACE)

#include <iostream>
#include <sstream>
#include "Stopwatch.h"

#define TRACE_BEGIN_EX(what, watch) \
	std::clog << what << std::endl; \
	watch.restart()

#define TRACE_END_EX(what, watch) \
	watch.stop(); \
	std::clog << what << \
	" Time: " << watch.getElapsedSeconds() << "s." << std::endl

#define TRACE_PREPARE \
	Stopwatch __trace_stopwatch; \
	std::ostringstream __trace_ostream; \
	std::string __trace_subject

#define TRACE_BEGIN(what) \
	__trace_ostream.str(std::string()); \
	__trace_ostream << what; \
	__trace_subject = __trace_ostream.str(); \
	TRACE_BEGIN_EX("Started: " << __trace_subject << ".", __trace_stopwatch)

#define TRACE_END \
	TRACE_END_EX("Finished: " << __trace_subject << ".", __trace_stopwatch)

#define TRACE(message, action) \
	TRACE_BEGIN(message); \
	{action;} \
	TRACE_END

#else

#define TRACE_BEGIN_EX(what, watch)
#define TRACE_END_EX(what, watch)
#define TRACE_PREPARE
#define TRACE_BEGIN(what)
#define TRACE_END
#define TRACE(message, action) {action;}

#endif

So now if we’ll compile our code without “_TRACE” being defined, tracing simply disappears and doesn’t have any impact on performance.

To summarize, these simple but quite powerful macros let us easily trace our code execution (including time of execution), and at the same time we have an option to disable it by simply not defining “_TRACE” macro. Quite nice, isn’t it? 🙂

Thanks for attention!

Useful Information In Exceptions

Developing image fusion software under my master’s work, I do specific assumptions on image channel size, minimal required memory size, etc. And if something goes wrong, the best way is to throw exception :). So, here is some kind of helper for including useful information (besides message itself)  to exception.

/*!
	For internal use.
*/
#define __TO_STRING(what) #what
#define __WHAT(message, file, line, date, time) \
	message " (" file ": " __TO_STRING(line) ", built at " date " " time ")"

/*!
	Throws standard exception with given message and
	information about source file name, line and build date.
*/
#define THROW_EXCEPTION(message) throw std::exception( \
	__WHAT(message, __FILE__, __LINE__, __DATE__, __TIME__))

So, here is an example of usage of that macro.

int main()
{
	try
	{
		THROW_EXCEPTION("Error!");
	}
	catch(const std::exception& e)
	{
		std::cerr << e.what() << std::endl;
	}

	return 0;
}

In this case STDERR will contain next line.

Error! (d:\projects\test\main.cpp: 22, built at Nov 12 2011 13:51:15)

Now we can explicitly see where that exception was thrown, moreover – we know when build was made.

That’s it, thanks for attention! 🙂