剖析幫助需要

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。它獲得了一個功能的平面列表及其總時間，以便您可以查看程序中哪些是最耗時的子樹。