Small C++ Code Profiler with Debug Console Window

• Download source code - 412 KB

Introduction

I'm a student of Game Development at Full Sail University in Florida. I created this profiler to determine which functions have a severe impact on performance in my games. I could then try to optimize those functions.

This profiler is a combination of a slightly modified version of CConsole classes written by Greeeg and a heavily modified version of the CProfiler classe written by Hernán Di Pietro. Visit their project pages for more information.

• CProfiler
• CConsole

Class Modifications

CConsole

The only modification done to the CConsole class was in the function Output(char* szString). I modified it so that it takes a string instead of a char*. The functionality of the function is identical. The fact that I only made one simple modification is proof that Greeegs class was extremely well built and flexible.

CProfiler

The original CProfiler class had very basic profiling functionality, it stored the current time (accurate to the microsecond) when the ProfileStart function is called, and it would measure the time again once the ProfileEnd function was called. The time that the function took to execute was the difference between the start time and end time.

I took the basic concept of Hernáns's class and expanded on it by adding a console output, the ability to profile multiple functions, the ability to profile a function multiple times and taking the average time it took to execute, etc.

The first step towards making these features possible was to create a profiled function structure. This structure stores the name of a function, the location of that function within the program, any notes the user might want to add, and other members that pertain to time measurment. Then I made the CProfiler class hold a vector of these profiled functions, that way I can output the results of the profiling tests to a LOG file. Having a vector of profiled functions also allowed me to identify which function is being profiled, so the user can have functions being profiled within other profiled functions. The major modifications were made within the definitions for the ProfileStart and ProfileEnd functions, where I create new profile functions, update them, and log them to the console or OutputDebug from VS.

Original ProfileStart:

void CProfiler::ProfileStart(LOGTYPE logtype)
{
	// get and store start time
	m_Retval = QueryPerformanceCounter (&m_StartCounter);
	// store logging type
	m_LogType = logtype;
}

Updated ProfileStart:

void CProfiler::ProfileStart(string funcName, string funcLocation, string notes,
    bool profileMultipleTimes, int numTotalProfileTimesBeforeLog) // starts profiling
{
	if(!profileMultipleTimes)
	{
		int nID = -1;
                // Go through the list of functions and see if this function 
                // has been profiled already.
		for(int i = (int)m_vProfiledFunctions.size() - 1; i >= 0; --i)
		{
			if(m_vProfiledFunctions[i].funcName == funcName &&
                               m_vProfiledFunctions[i].funcLocation == funcLocation)
			nID = i;
		}
                // If the function hasn't been profiled, create a new one and 
                // add it to the vector.
		if(nID == -1)
		{
			FUNCTION_PROFILE function;

			function.funcName = funcName;
			function.funcLocation = funcLocation;
			function.notes = notes;
			function.numTimesCalled = 1;
			function.elapsedTimes.push_back(0);
			m_Retval = QueryPerformanceCounter (&function.StartCounter);

			m_vProfiledFunctions.push_back(function);
		}
                // The function has been found. Update the values and reset 
                // the start counter.
		else
		{
			m_vProfiledFunctions[nID].numTimesCalled += 1;
			m_vProfiledFunctions[nID].elapsedTimes.push_back(0);
			m_Retval = QueryPerformanceCounter (
                               &m_vProfiledFunctions[nID].StartCounter);
		}
	}
	else
	{
		int index = -1;
                // Go through the list of functions and see if this function 
                // has been profiled already.
		for(int i = (int)(m_vProfiledFunctions.size() - 1); i >= 0; --i)
		{
			if(m_vProfiledFunctions[i].funcName == funcName &&
                                m_vProfiledFunctions[i].funcLocation == funcLocation)
			{
				index = i;
				break;
			}
		}
                // The function has been found. Update the values and reset 
                // the start counter.
		if(index != -1)
		{
			if(m_vProfiledFunctions[index].numTimesCalled < 
                               m_vProfiledFunctions[index].numTotalProfileTimes + 1)
			m_vProfiledFunctions[index].numTimesCalled += 1;

			m_vProfiledFunctions[index].multipleCalls = true;
			m_Retval = QueryPerformanceCounter (
                               &m_vProfiledFunctions[index].StartCounter);
		}
                // If the function hasn't been profiled, create a new one and 
                // add it to the vector.
		else
		{
			FUNCTION_PROFILE function;

			function.funcName = funcName;
			function.funcLocation = funcLocation;
			function.notes = notes;
			function.numTimesCalled = 1;
			function.multipleCalls = true;
			function.numTotalProfileTimes = numTotalProfileTimesBeforeLog;
			m_Retval = QueryPerformanceCounter (&function.StartCounter);
			function.elapsedTimes.push_back(0);

			m_vProfiledFunctions.push_back(function);
		}
	}
}

I know this function is a bit messy and could be made simpler, but the basic functionality is there and it gets the job done. (Besides I only started programming C++ 8 months ago... Gimme a break)

The ProfileEnd function also went through a major overhaul, because now it's outputting the results to a console, or OutputDebug (VS). Check out the CProfiler.cpp from my example if you want to see exactly what's going on.

The last change was the inclusion of the Shutdown function. This function basically iterates through the vector of profiled functions and saves all the results to a text LOG file, if the user so specifies in the LOGTYPE parameter in the Initialize function. I will explain all the functions and how to use them in detail in the following sections.

Overview

The CProfiler class calculates the amount of time a function takes to execute. The class is a singleton, so you can have access to it anywhere in your program. The profiler has a debug console window to display the results of the profiled functions. It can also output the results to the OutputDebug window in Visual Studio. But, most importantly, it saves the results of all the profiled functions to a LOG text file, so you can evaluate the results after the program has finished. The profiler is very simple and easy to use, but it's also powerful. You can profile functions within functions; so, for example, if you want to know how long a program takes to initialize, you profile the Initialize function, but within that function, you can profile individual function calls to know exactly what inside the Initialize function takes the longest to execute. The last interesting feature is that you can profile functions multiple times (within a loop, for example), and you can specify how many times you want the profiler to profile that function. After it has profiled the function the specified amount of times, it'll display the time the last call took to execute, as well as the average time the function took to execute.

The CProfiler Class

The CProfiler class consists of three main parts: the console class, a profiled function structure, and the actual profiler class.

The CConsole Class

The CConsole class is nearly identical to the class Greeeg wrote; the only difference is that I use strings to output messages while he uses char pointers. Please see his project page if you need assistance with his class.

The FUNCTION_PROFILE Structure

struct FUNCTION_PROFILE
{
    string           funcName;
    string           funcLocation;
    string           notes;
    UINT             numTimesCalled;
    UINT             numTotalProfileTimes;
    LARGE_INTEGER    StartCounter;
    bool             multipleCalls;

    vector<__int64>  elapsedTimes;
    __int64 	     totalElapsedTime;

    FUNCTION_PROFILE()
    {
        funcName = "";
        funcLocation = "";
        notes = "";
        numTimesCalled = 0;
        multipleCalls = false;
        numTotalProfileTimes = 1;
        totalElapsedTime = 0;
        ZeroMemory(&StartCounter,sizeof(StartCounter));
    }
};

The first few members are pretty self explanatory, the name of the function being profiled, the location of said function, any notes you might want to add (optional), number of times called, and number of times you want to profile the function (this is only valid if the bool multipleCalls is set to true).

The vector<_int64> elapsedTimes is the collection of time (in ticks) of the function. We need a vector here because if a function is profiled more than once, you want to know the time that each call took to execute.

And finally, the totalElapsedTime is incremented by the elapsed time every time the function is called; again, this is only valid if the bool multipleCalls is set to true. This variable is used to calculate the average time a multiple profiled function took to execute.

The CProfiler Class

The CProfiler class declaration is as follows:

class CProfiler
{
public:
    static CProfiler*   GetInstance(void);
    CConsole*        	GetConsole() { return &console; }

    void            	Initialize(string buildInfo, LOGTYPE logtype =
                            LOG_DEBUG_OUTPUT);
    void            	Shutdown();
    void            	ProfileStart(string funcName, string funcLocation,
                            string notes = "", bool profileMultipleTimes = false,
                            int numTotalProfileTimesBeforeLog = 1000);
    void             	ProfileEnd  (string funcName, string funcLocation);
    void             	LogResults  (int nID);
    double            	SecsFromTicks ( __int64 ticks);
        
private:
    CProfiler(void);
    ~CProfiler(void);    
    CProfiler(const CProfiler &ref);
    CProfiler &operator=(const CProfiler &ref);

    CConsole console;

    string            	m_sBuildInfo;
    
    LARGE_INTEGER       m_QPFrequency;   // ticks/sec resolution
    LARGE_INTEGER       m_EndCounter;    // finish time
    DWORD            	m_Retval;        // return value for API functions
    LOGTYPE            	m_LogType;       // logging type

    bool            	m_bLogMultipleNow;
    
    // Vector of all profiled functions, necessary for the LOG file.
    vector<FUNCTION_PROFILE> m_vProfiledFunctions; 
};

The first time the GetInstance() function is called, it will create the only instance of the class that will be used throughout the program; after that, it returns a pointer to the instance of the class.

GetConsole() returns a pointer to the console class, so you can use it to add text to the debug console. For example:

CProfiler* profiler = CProfiler::GetInstance();
profiler->GetConsole()->Output("Debug Information");
profiler->GetConsole()->Output();

One thing to note is that calling profiler->GetConsole()->Output(); will make a newline.

I will cover how to use the Initialize, ProfileStart, ProfileEnd, and Shutdown functions in the Using the Code section.

The LogResults function will log the results of the profiled function to either the Console or DebugOutput (from VS), depending on the LOGTYPE specified in the Initialize function.

Using the Code

The first thing you must do anywhere you want to profile your code is to get the instance to the class. Being a singleton class, you can't have CProfiler objects, so you have to create a pointer to the class. The class creates itself, so you don't have to worry about creating it.

CProfiler* profiler = CProfiler::GetInstance();

Then, at the beginning of your program, you need to initialize the profiler by calling the Initialize function.

profiler->Initialize("Test Build", LOGALL);

The two parameters the function takes are a string BuildInfo and LOGTYPE.

The BuildInfo is a string that will be displayed on top of the console window before any functions are profiled. It will also appear on the top of the LOG file.

The LOGTYPE is an enumeration with logging options. You can chose one of the following:

• LOG_DEBUG_OUTPUT - Logs the results to the VS Debug Output window only.
• LOGCONSOLE - Logs the results to the console only.
• LOGTEXTOUT - Logs the results to a text LOG file only.
• LOGALL - Logs the results to the console and a text LOG file.

After the profiler is initialized, you can then start profiling functions by calling ProfileStart and ProfileEnd. For example:

CProfiler* profiler = CProfiler::GetInstance();

profiler->ProfileStart("TestFunction", "WinMain()",
    "See how long the test function takes to execute.");

TestFunction();

profiler->ProfileEnd("TestFunction", "WinMain()");

To profile functions multiple times (within a loop, for example) is very similar:

while(true)
{

    profiler->ProfileStart("Update", "WinMain()",
        "See how long the test function takes to execute.", true, 10000);

    Update();

    profiler->ProfileEnd("Update", "WinMain()");

}

After the function is profiled 10000 times, the profiler will calculate the average time it took to execute, and it'll output the result.

Conclusion

Geez... Making an article on CodeProject takes a long time... Thank goodness, it's over :)

I would like to personally thank Hernán Di Pietro and Greeeg for sharing their awesome programs. Without their knowledge, I would have never been able to do this. I would also lose points in my class, because having a code profiler for our game is a required feature. Thanks guys!

Feel free to use, modify, and expand this profiler. It's free to use even in commercial applications. Just please make sure to mention myself and the other authors somewhere in your application. Also, please leave a comment or suggestion, I like to get feedback from the programming community. Happy coding everyone!