Требуется помощь в профилировании - PullRequest
7 голосов
/ 15 июня 2010

У меня проблема с профилированием - представьте, у меня есть следующий код ...

void main()
{
    well_written_function();
    badly_written_function();
}
void well_written_function()
{
    for (a small number)
    {
        highly_optimised_subroutine();
    }
}
void badly_written_function()
{
    for (a wastefully and unnecessarily large number)
    {
        highly_optimised_subroutine();
    }
}
void highly_optimised_subroutine()
{
    // lots of code
}

Если я запускаю это под vtune (или другими профилировщиками), очень трудно обнаружить, что что-то не так. Все горячие точки появятся в разделе с пометкой «// много кода», который уже оптимизирован. Badly_written_function () никоим образом не будет выделен, даже если он является причиной всех проблем.

Есть ли какая-то особенность vtune, которая поможет мне найти проблему?

Есть ли какой-то режим, в котором я могу найти время, затраченное на badly_written_function () и все его подфункции ?

Ответы [ 4 ]

1 голос
/ 16 июня 2010

Это обычно называют «профилем callgraph», и я вполне уверен, что Visual Studio сделает это.

1 голос
/ 16 июня 2010

Могу ли я предложить свой собственный профилировщик с открытым исходным кодом 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 от здесь Пример кода вы узнаете в Руководстве пользователя: -)

1 голос
/ 16 июня 2010

Прокатить свой собственный очень простой профилировщик не так уж и сложно. Вставить в 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;
}

где:

#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, и его ссылки, но я не пробовал их.

Редактировать: Очень хороший ответ 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)...
0 голосов
/ 09 марта 2013

Как правило, это то, где вы хотите наблюдать общее время функции, а не собственное время, чтобы убедиться, что вы смотрите на время, которое включает в себя время вызываемых функций.

В VTune,Я бы порекомендовал использовать сверху вниз вкладку для этого.Или, что еще лучше, и если вы используете последнее обновление, попробуйте новый экспериментальный вид Caller-Callee.Вы можете получить подробную информацию об этом здесь - http://software.intel.com/en-us/forums/topic/376210. Он получает плоский список функций с их общим временем, чтобы вы могли просмотреть, какие топовые поддеревья в вашей программе занимают много времени.

...