剖析帮助需要

Question

我有一个问题剖析 - 想象我有以下代码...

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（）及其所有子功能所花费的时间？

Answer 1

这通常被称为“callgraph profile”，我相当确信Visual Studio会这样做。

Answer 2

滚动自己很简单分析器并不那么难。使用此profileCpuUsage（）不会增加太多的好处在简单的例子

#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; 
    } 
} 

现在公认的：插入到主（）：

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; 
} 

哪里。它的缺点是要求你通过手动通过在适当的位置调用profileCpuUsage（）来测试你的代码。

但优势包括：

• 您可以在时间任何的代码片段，而不仅仅是程序。
• 与查找和/或删除代码热点的二进制搜索一样，添加和删除操作非常快捷。
• 它只关注您感兴趣的代码。
• 便携！
• KISS

一个棘手的非便携的就是定义函数realElapsedTime（），所以它提供足够的粒度，以获得有效时间。这通常对我的作品（使用Cygwin下的Windows API）：

#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)... 

Answer 3

我可以推荐我自己的开源探测器raven :: set :: cRunWatch吗？它专门针对此问题而设计，并且可以在Windows上使用Visual Studio 2008标准版进行工作，因此您无需为包含该分析器的版本付费。

我已经采取了你的代码，重新排列稍微所以它编译没有前向声明，并添加了必要的调用来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到成为非常接近的第二次使用者，因此是罪魁祸首。

您可以从here获得cRunWatch你会认识到用户指南中的示例代码:-)

Answer 4

一般情况下，这是你要观察，而不是自我时间函数的总时间的东西，以确保您正在查看包含被调用函数时间的时间。

在VTune中，我会推荐使用Top-down标签。或者，甚至更好，如果您正在使用最新的更新，请尝试新的实验性Caller-Callee视图。你可以在这里获得详细信息 - http://software.intel.com/en-us/forums/topic/376210。它获得了一个功能的平面列表及其总时间，以便您可以查看程序中哪些是最耗时的子树。