Click here to Skip to main content
15,884,629 members
Articles / Programming Languages / C++

Another Profiler for VC++

Rate me:
Please Sign up or sign in to vote.
3.71/5 (8 votes)
26 Nov 2006CPOL3 min read 43.9K   432   22   7
A profiler which calculates the total and execution time elapsed for each function profiled

Introduction

This is a profiler for Visual C++ 2003.

I needed a profiler for C++ (Visual Studio 2003) to check out where the bottleneck is in some of my projects. No bells and whistles. The profiler should be very easy to use. And it should be able to count the execution time instead of/on top of the total time elapsed for each function (explained later).

On the other hand, I don't need an ultra-accurate timer and a reasonable overhead by the profiling code is acceptable. My reason is: I know optimization is "evil" -- well, over-optimization perhaps. So I just want to spot out the stupid functions which look innocent but use up 30% of the execution time and can easily be reduced to 5%.

I definitely don’t need a fancy UI with a CListCtrl. I’d prefer a CSV output so that I can view and analyze the results in Excel.

And here it is.

The Execution Time

The timing of functions is well-explained by Hernán Di Pietro’s CProfile - A simple class to do code profiling and tracing. I will say a bit about recording the execution time of functions here.

Consider functions Foo() and Bar(). Foo() calls Bar(). If I recorded the time at the entry and exit points Foo() and calculated the duration, I would include the execution time of Bar()s in Foo()s. I want to know what time exactly does and only does Foo() take. So on top of recording the entry and exit time, I also have an offset amount. This amount is deducted by every profiled function call.

I use a stack to find out the matching entry and exit records of each function call. The total elapsed time and the execution time (offset by duration of function calls in the function) are then calculated. Each duration is put in a CMap with keys of the function names. Note that since all function names by the directive __FUNCTION__ are constant strings. There is no need to copy/delete the char pointers.

Usage

Just add profile.cpp and profile.h in your project. Include “profile.h” and put the macro “PP” at the very beginning of each function to be profiled. At the end of your program, call CProfiler::ExportProf(). A CSV file will be saved under the application directory. The demo project is commented and should be very straight-forward. In the demo project, functions in the class CProfTest are to be profiled.

This is the first time I have posted an article here. I just hope I haven’t broken too many rules. Any criticism and/or feedback is equally welcome.

Update Nov 30, 2006

Thanks to eTurtle and yarp's posts.

To profile a multithreading program. I add a map of stacks to keep track of the entry/exit times for each separate thread. So the offset mentioned above won't affect other threads. I added a CCriticalSection to protect the operations of the static collection. I am not sure whether this is necessary. And I am not sure whether there are some cases there I overlooked. But so far it seems it works OK for my simple multithreading test case. Of course this is supposed to be a "quick 'n dirty" trick. ;)

Please let me know should there be any problem.

Also fixed some minor bugs and added some more comments, tidied up the code a bit. Please download the updated version when it's ready.

I add the "locale" support for the CSV and fixed the date format as pointed by eTurtle. I thought I could think straight when I prepared this article and the project -- after half a dozen beers...

後會有期。

License

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


Written By
Hong Kong Hong Kong
It's over!!!

Comments and Discussions

 
GeneralGreat work Pin
navan4-Dec-08 1:22
navan4-Dec-08 1:22 
Generalmeasurement results Pin
uli20002-Jul-08 8:27
uli20002-Jul-08 8:27 
QuestionWhat does T/I E/I fields int the report mean? Pin
suggam8-May-08 8:54
suggam8-May-08 8:54 
QuestionHow about multi-thread ? Pin
yarp29-Nov-06 19:20
yarp29-Nov-06 19:20 
AnswerRe: How about multi-thread ? Pin
ferdo30-Nov-06 4:42
ferdo30-Nov-06 4:42 
GeneralRe: How about multi-thread ? Pin
yarp30-Nov-06 18:41
yarp30-Nov-06 18:41 
GeneralMinor bug (VS.NET2005) Pin
eFotografo28-Nov-06 0:53
professionaleFotografo28-Nov-06 0:53 
Nice code, excellent for those quick'n'dirty profiling jobs that don't require the services of a full blown profiler package!

I did have one minor problem when using under VS2005 however - the format specifiers used to format the date/time are invalid. The change is quite simple:

Line 43:
strFileName.AppendFormat("\\prof-%s.csv", CTime::GetCurrentTime().Format("%Y-%m-%d_%H%M%S"));

Line 65:
CTime::GetCurrentTime().Format("%Y-%m-%d %H:%M:%S"), ls,


Note the use of "%m" for the MONTH ("%M" refers to the MINUTES) and "%d" for the DAY ("%D" is an invalid specifier).

One other minor detail was the use of a comma as the list separator in the generated CSV file. Probably the majority of readers will have no problem with that, however my system (using the Portuguese locale), uses a semicolon as the list separator. Rather than hard code it, an alternative would be to query the system for the currently defined character(s) and use those directly. The following changes do exactly that:

1. At the top of profile.cpp add:
#include <locale.h>

2. Change the start of method ExportProf() to read:
void CProfile::ExportProf(CString strFileName/*=""*/)
{
#ifdef FUNCTION_PROFILE

    // the list separator may be upto 4 characters wide
    TCHAR ls[5] = {0};
    GetLocaleInfo(LOCALE_USER_DEFAULT, LOCALE_SLIST, ls, 5);

    strFileName = strFileName.Trim();

and finally update the format strings to make use of the list separator:
[...]
    m_llQPFreq = liQPFreq.QuadPart / 1000; // unit of millisec

    strLine.Format("App%sTime%sCPU\n",ls,ls);
    file.WriteString(strLine);

    // application info
    strLine.Format(
        "%s%s%s%s%0.2lfMHz\n", 
            ::AfxGetAppName(), ls, 
            CTime::GetCurrentTime().Format("%Y-%m-%d %H:%M:%S"), ls,
            (double)(m_llQPFreq / 1e6));
        file.WriteString(strLine);
[...].

[...]
        // writing the results into a CSV file
        strLine.Format("Function%sInvocations%sTotal%sExecution\n", ls, ls, ls);
        file.WriteString(strLine);
[...].

[...]
            double dbExecElapsed = pFuncRec->m_nExecElapsed / 1000.0;
            strLine.Format(
                "%s%s%d%s%10.3lf%s%10.3lf\n", 
                lpszFuncName, ls,
                pFuncRec->m_nInvoke, ls,
                dbTotElapsed, ls,
                dbExecElapsed);
            file.WriteString(strLine);
        }

        strLine.Format("%s%s%d%s%10.3lf%s%10.3lf\n", 
            "Total", ls,
            TotRec.m_nInvoke, ls,
            (double)(TotRec.m_nTotElapsed / 1000.0), ls,
            (double)(TotRec.m_nExecElapsed / 1000.0));
        file.WriteString(strLine);
[...].



Regards,

John

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.