【问题标题】:Profiling help required需要分析帮助
【发布时间】:2011-03-04 02:25:15
【问题描述】:

我有一个分析问题 - 假设我有以下代码...

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() 及其所有子函数所花费的时间?

【问题讨论】:

  • 这通常被称为“callgraph profile”,我很确定 Visual Studio 会这样做。虽然我的记忆有点模糊,因为我已经好几年没有做过任何 Windows 开发了。
  • 我很确定 vtune 允许进行细分,您可以在其中查看并按总时间消耗(包括它调用的函数)进行排序。但是,要使用它,您需要对应该在哪个功能上花费多少时间有一个合理的直觉。
  • @torak: 记得功能的名称吗? - 我确实对某些功能需要多长时间有一个粗略的了解,所以我确信这样的细分确实非常有用。
  • 如果 Valgrind 在 Windows 中工作,世界将会变得更美好。
  • @Mick:抱歉,我想不起来了。我会尽量记住启动 VTune 并检查何时回家。

标签: c++ c visual-studio-2008 intel-vtune


【解决方案1】:

这通常称为“调用图配置文件”,我相当肯定 Visual Studio 会这样做。

【讨论】:

    【解决方案2】:

    滚动您自己的非常简单分析器并不难。插入 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() 来检测您的代码。

    但优点包括:

    • 您可以对任何代码片段进行计时,而不仅仅是程序。
    • 添加和删除速度很快,就像您通过二进制搜索查找和/或删除代码热点一样。
    • 它只关注您感兴趣的代码。
    • 便携!
    • 亲吻

    一个棘手的不可移植的事情是定义函数 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)...
    

    【讨论】:

      【解决方案3】:

      我可以推荐我自己的开源分析器 raven::set::cRunWatch 吗?它正是针对这个问题而设计的,可以在使用 Visual Studio 2008 标准版的 Windows 上运行,因此您无需为包含分析器的版本付费。

      我已经获取了您的代码,稍微重新排列了它,因此它可以在没有前向声明的情况下进行编译,并添加了对 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 你会认出用户指南中的示例代码:-)

      【讨论】:

      • 确实需要提升。几乎我编写的每个程序都以一种或另一种方式使用 boost。 Boost 是免费的,而且非常有用。
      • @Joseph Quinsey 那么我希望您还缺少高分辨率性能计数器,它是 cRunWatch 跳动的心脏。
      【解决方案4】:

      通常,这是您想要观察函数的总时间而不是自身时间的地方,以确保您查看的时间包括被调用函数的时间。

      在 VTune 中,我建议使用自上而下的选项卡。或者,更好的是,如果您使用的是最新更新,请尝试新的实验性 Caller-Callee 视图。您可以在此处获取详细信息 - http://software.intel.com/en-us/forums/topic/376210。它会获得一个包含总时间的函数列表,以便您查看程序中最耗时的子树。

      【讨论】:

        猜你喜欢
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        • 2011-08-15
        • 1970-01-01
        • 2021-01-16
        相关资源
        最近更新 更多