Профилирование справки требуется

Могу ли я предложить свой собственный профайлер с открытым исходным кодом raven::set::cRunWatch? Он предназначен именно для этой проблемы и работает на Windows с использованием Visual Studio 2008 Standard Edition, так что вам не нужно платить за версию, в которую включен профайлер.

Я взял ваш код, немного изменил его, чтобы он компилировался без прямых объявлений, и добавил необходимые вызовы cRunWatch

// RunWatchDemo.cpp : Defines the entry point for the console application.
//

#include "stdafx.h"

void highly_optimised_subroutine()
{
    raven::set::cRunWatch runwatch("highly_optimised_subroutine");
    Sleep( 2 );
}


void badly_written_function()
{
    raven::set::cRunWatch runwatch("badly_written_function");
    for (int k = 1; k < 1000; k++ )
    {
        highly_optimised_subroutine();
    }
}

void well_written_function()
{
    raven::set::cRunWatch runwatch("well_written_function");
   for (int k = 1; k < 10; k++ )
    {
        highly_optimised_subroutine();
    }
}


int _tmain(int argc, _TCHAR* argv[])
{
raven::set::cRunWatch::Start();

    well_written_function();
    badly_written_function();

raven::set::cRunWatch::Report();

    return 0;
}   

При запуске он выдает результат

raven::set::cRunWatch code timing profile
                    Scope   Calls       Mean (secs)     Total
highly_optimised_subroutine     1008    0.002921        2.944146
   badly_written_function        1      2.926662        2.926662
    well_written_function        1      0.026239        0.026239

Это показывает, что badly_written_function является очень близким вторым пользователем и, следовательно, виновником.

Вы можете получить cRunWatch из здесь Вы узнаете пример кода в руководстве пользователя :-)

Создать свой собственный очень простой профилировщик не так уж сложно. Вставьте в main():

int main()
{
    profileCpuUsage(1);                 // start timer #1
    well_written_function();
    profileCpuUsage(2);                 // stop timer #1, and start timer #2
    badly_written_function();
    profileCpuUsage(-1);                // print stats for timers #1 and #2
    return 0;
}

where:

#define NUMBER(a) ((int)(sizeof(a) / sizeof(a)[0]))

void profileCpuUsage(int slice)
{
    static struct {
        int iterations;
        double elapsedTime;
    } slices[30];                             // 0 is a don't care slice

    if (slice < 0) {                          // -1 = print
        if (slices[0].iterations)
            for (slice = 1; slice < NUMBER(slices); slice++)
                printf("Slice %2d  Iterations %7d  Seconds %7.3f\n", slice,
                    slices[slice].iterations, slices[slice].elapsedTime);
    }
    else {
        static int i;                         // = previous slice
        static double t;                      // = previous t1
        const double t1 = realElapsedTime();  // see below for definition
        assert (slice < NUMBER(slices));
        slices[i].iterations  += 1;
        slices[i].elapsedTime += t1 - t;      // i = 0 first time through
        i = slice;
        t = t1;
    }
}

Теперь признаем, что в вашем простом примере использование этой profileCpuUsage() не добавляет много пользы. И ее недостаток в том, что вам придется вручную инструментировать ваш код, вызывая profileCpuUsage() в соответствующих местах.

Но есть и преимущества:

• Вы можете засекать по времени любой фрагмент кода, а не только процедуры.
• Его можно быстро добавлять и удалять, поскольку вы выполняете бинарный поиск, чтобы найти и/или удалить "горячие точки" кода.
• Он фокусируется только на интересующем вас коде.
• Портативный!
• KISS

Один хитрый непортативный момент - определить функцию realElapsedTime() так, чтобы она обеспечивала достаточную детализацию для получения достоверного времени. Обычно это работает для меня (используя Windows API под CYGWIN):

#include <windows.h>
double realElapsedTime(void)   // <-- granularity about 50 microsec on test machines
{
    static LARGE_INTEGER freq, start;
    LARGE_INTEGER count;
    if (!QueryPerformanceCounter(&count))
        assert(0 && "QueryPerformanceCounter");
    if (!freq.QuadPart) {      // one time initialization
        if (!QueryPerformanceFrequency(&freq))
            assert(0 && "QueryPerformanceFrequency");
        start = count;
    }
    return (double)(count.QuadPart - start.QuadPart) / freq.QuadPart;
}

Для прямого Unix есть обычное:

double realElapsedTime(void)                      // returns 0 first time called
{
    static struct timeval t0;
    struct timeval tv;
    gettimeofday(&tv, 0);
    if (!t0.tv_sec)
        t0 = tv;
    return tv.tv_sec - t0.tv_sec + (tv.tv_usec - t0.tv_usec) / 1000000.;
}

realElapsedTime() дает время настенных часов, а не время процесса, что обычно то, что я хочу.

Существуют и другие менее портативные методы достижения более тонкой детализации с помощью RDTSC; см. например http://en.wikipedia.org/wiki/Time_Stamp_Counter и его ссылки, но я их не пробовал.

Edit: Очень хороший ответ ravenspoint'а, похоже, не слишком отличается от моего. И в его ответе используются красивые описательные строки, а не просто уродливые числа, которые меня часто расстраивали. Но это можно исправить всего лишь дюжиной дополнительных строк (но это почти удваивает количество строк!).

Обратите внимание, что мы хотим избежать любого использования malloc(), и я даже немного сомневаюсь насчет strcmp(). Поэтому количество фрагментов никогда не увеличивается. А хэш-коллизии просто отмечаются, а не решаются: человек-профайлер может исправить это, вручную увеличив количество фрагментов с 30, или изменив описание. Не проверено

static unsigned gethash(const char *str)    // "djb2", for example 
{
    unsigned c, hash = 5381;
    while ((c = *str++))
        hash = ((hash << 5) + hash) + c;    // hash * 33 + c 
    return hash;
}

void profileCpuUsage(const char *description)
{
    static struct {
        int iterations;
        double elapsedTime;
        char description[20];               // added!
    } slices[30];

    if (!description) {
        // print stats, but using description, mostly unchanged...
    }
    else {
        const int slice = gethash(description) % NUMBER(slices);
        if (!slices[slice].description[0]) { // if new slice
            assert(strlen(description) < sizeof slices[slice].description);
            strcpy(slices[slice].description, description);
        }
        else if (!!strcmp(slices[slice].description, description)) {
            strcpy(slices[slice].description, "!!hash conflict!!");
        }
        // remainder unchanged...
    }
}

И еще один момент: обычно вы хотите отключить это профилирование для релизных версий; это также относится к ответу ravenspoint. Это можно сделать с помощью трюка с использованием злого макроса для его отключения:

#define profileCpuUsage(foo)                // = nothing

Если это будет сделано, вам, конечно, придется добавить круглые скобки к определению, чтобы отключить отключающий макрос:

void (profileCpuUsage)(const char *description)...