2012-10-09 120 views
0

這裏是我的源代碼如何理解gprof輸出?

#include <stdio.h> 
#include <stdlib.h> 
#include <string.h> 
#include <inttypes.h> 
#include <windows.h> 

#include <string> 
#include <vector> 

static void set(const char *buf) 
{ 
    static std::string *localstring; 
    localstring = new std::string; 
    (*localstring) = buf; 
    delete localstring; 
} 

int main() 
{ 
    const uint32_t BUF_SIZE = 1024 * 4;//32; 
    char buf[BUF_SIZE+4]; 
    int i; 
    ULONG T0, T1; 

    for(i = 0; i < BUF_SIZE; i++) { 
     buf[i] = 'a' + i % 26; 
    } 


    T0 = GetTickCount(); 
    for(i = 0; i < 10000000; i++) { 
     const int pos = i % BUF_SIZE + 1; 
     const char save_ch = buf[pos - 1]; 
     set(buf); 
     buf[pos - 1] = 0; 
     buf[pos - 1] = save_ch; 
    } 
    T1 = GetTickCount(); 

    printf("Totally %u mseconds\n", T1 - T0); 
    return 0; 
} 

下面是分析結果:
平面輪廓:

Each sample counts as 0.01 seconds. 
    % cumulative self    self  total   
time seconds seconds calls Ts/call Ts/call name  
50.00  0.09  0.09        _fu0___ZNSs4_Rep20_S_empty_rep_storageE 
38.89  0.16  0.07        _fu1___ZNSs4_Rep20_S_empty_rep_storageE 
    5.56  0.17  0.01        std::string::assign(char const*, unsigned int) 
    5.56  0.18  0.01        strlen 

%   the percentage of the total running time of the 
time  program used by this function. 

cumulative a running sum of the number of seconds accounted 
seconds for by this function and those listed above it. 

self  the number of seconds accounted for by this 
seconds function alone. This is the major sort for this 
      listing. 

calls  the number of times this function was invoked, if 
      this function is profiled, else blank. 

self  the average number of milliseconds spent in this 
ms/call function per call, if this function is profiled, 
     else blank. 

total  the average number of milliseconds spent in this 
ms/call function and its descendents per call, if this 
     function is profiled, else blank. 

name  the name of the function. This is the minor sort 
      for this listing. The index shows the location of 
     the function in the gprof listing. If the index is 
     in parenthesis it shows where it would appear in 
     the gprof listing if it were to be printed. 

      Call graph (explanation follows) 


granularity: each sample hit covers 4 byte(s) for 5.56% of 0.18 seconds 

index % time self children called  name 
               <spontaneous> 
[1]  50.0 0.09 0.00     _fu0___ZNSs4_Rep20_S_empty_rep_storageE [1] 
----------------------------------------------- 
               <spontaneous> 
[2]  38.9 0.07 0.00     _fu1___ZNSs4_Rep20_S_empty_rep_storageE [2] 
----------------------------------------------- 
               <spontaneous> 
[3]  5.6 0.01 0.00     std::string::assign(char const*, unsigned int) [3] 
----------------------------------------------- 
               <spontaneous> 
[4]  5.6 0.01 0.00     strlen [4] 
----------------------------------------------- 

This table describes the call tree of the program, and was sorted by 
the total amount of time spent in each function and its children. 

Each entry in this table consists of several lines. The line with the 
index number at the left hand margin lists the current function. 
The lines above it list the functions that called this function, 
and the lines below it list the functions this one called. 
This line lists: 
    index A unique number given to each element of the table. 
     Index numbers are sorted numerically. 
     The index number is printed next to every function name so 
     it is easier to look up where the function in the table. 

    % time This is the percentage of the `total' time that was spent 
     in this function and its children. Note that due to 
     different viewpoints, functions excluded by options, etc, 
     these numbers will NOT add up to 100%. 

    self This is the total amount of time spent in this function. 

    children This is the total amount of time propagated into this 
     function by its children. 

    called This is the number of times the function was called. 
     If the function called itself recursively, the number 
     only includes non-recursive calls, and is followed by 
     a `+' and the number of recursive calls. 

    name The name of the current function. The index number is 
     printed after it. If the function is a member of a 
     cycle, the cycle number is printed between the 
     function's name and the index number. 


For the function's parents, the fields have the following meanings: 

    self This is the amount of time that was propagated directly 
     from the function into this parent. 

    children This is the amount of time that was propagated from 
     the function's children into this parent. 

    called This is the number of times this parent called the 
     function `/' the total number of times the function 
     was called. Recursive calls to the function are not 
     included in the number after the `/'. 

    name This is the name of the parent. The parent's index 
     number is printed after it. If the parent is a 
     member of a cycle, the cycle number is printed between 
     the name and the index number. 

If the parents of the function cannot be determined, the word 
`<spontaneous>' is printed in the `name' field, and all the other 
fields are blank. 

For the function's children, the fields have the following meanings: 

    self This is the amount of time that was propagated directly 
     from the child into the function. 

    children This is the amount of time that was propagated from the 
     child's children to the function. 

    called This is the number of times the function called 
     this child `/' the total number of times the child 
     was called. Recursive calls by the child are not 
     listed in the number after the `/'. 

    name This is the name of the child. The child's index 
     number is printed after it. If the child is a 
     member of a cycle, the cycle number is printed 
     between the name and the index number. 

If there are any cycles (circles) in the call graph, there is an 
entry for the cycle-as-a-whole. This entry shows who called the 
cycle (as parents) and the members of the cycle (as children.) 
The `+' recursive calls entry shows the number of function calls that 
were internal to the cycle, and the calls entry for each member shows, 
for that member, how many times it was called from other members of 
the cycle. 


Index by function name 

    [3] std::string::assign(char const*, unsigned int) [2] _fu1___ZNSs4_Rep20_S_empty_rep_storageE 
    [1] _fu0___ZNSs4_Rep20_S_empty_rep_storageE [4] strlen 

該方案的實際運行時間是從打印的消息15秒,而不是0.18來自分析結果的秒數。爲什麼這麼大的差異以及如何理解分析輸出?

BR,若塵

回答

0

你正在做的主要事情是new,字符串賦值和delete。 如果其中任何人花費時間在操作系統中,或者代碼與您的版本沒有關聯,則採樣器將不會看到它。就那麼簡單。

That's not gprof's only problem.