C++ Profiler工具之初体验 (转)

C++ Profiler工具之初体验

 

 

C++Profiler工具

精确度

对动态库的支持

对动态控制的支持

二次开发和维护成本

GUN profile

较高,对函数执行次数的统计是100%正确的,但是对函数执行时间的统计是通过采样平率估算的,存在一定的偏差。

No

编译时决定,灵活性较差

代码集成在glibc中,二次开发和修改的影响面较大,而且发布不易。

Google performance tools

一般,对函数次数和执行时间的统计都是通过采样频率估算的,存在一定的偏差和遗漏。

Yes

运行时控制,更方面操作

独立的第三方库,开源项目,二次开发和维护成本较低。

Oprofile

待调查

待调查

待调查

待调查

 

 

 

 

 

 

概要:本文同期调研了google profile工具以及其他常用profile的工具,如GNU gprof、oprofile等(都是开源项目),并对其实现原理做了简单分析和比较。希望对之后的推广使用或二期开发有所帮助。

 

一、 GUN Gropf

Gprof是GNU profiler工具。可以显示程序运行的“flatprofile”,包括每个函数的调用次数,每个函数消耗的处理器时间。也可以显示“调用图”,包括函数的调用关系,每个函数调用花费了多少时间。还可以显示“注释的源代码”,是程序源代码的一个复本,标记有程序中每行代码的执行次数。关于Gprof的使用以及实现原理网上已有多篇文章提及,本文就不再详述,只是对其进行梳理和总结,方便阅读。(Gprof的官方网址:http://www.cs.utah.edu/dept/old/texinfo/as/gprof_toc.html,http://sourceware.org/binutils/docs/gprof/index.html 绝对权威的参考资料。)

 

1.1 安装

Glibc自带,无需另外安装

 

1.2 用法

参考http://hi.baidu.com/juventus/blog/item/312dd42a0faf169b033bf6ff.html/cmtid/3c34349bb5a8ceb8c9eaf4c5

图形化输出请参考大师blog:http://www.51testing.com/?uid-13997-action-viewspace-itemid-79952

 

1.3 实现原理

引用官网说明:

Profiling works by changing how every function in your program iscompiled so that when it is called, it will stash away some informationabout where it was called from. From this, the profiler can figure outwhat function called it, and can count how many times it was called.This change is made by the compiler when your program is compiled withthe `-pg' option.

Profiling also involves watching your program as it runs, andkeeping a histogram of where the program counter happens to be everynow and then. Typically the program counter is looked at around 100times per second of run time, but the exact frequency may vary fromsystem to system.

A special startup routine allocates memory for the histogram andsets up a clock signal handler to make entries in it. Use of thisspecial startup routine is one of the effects of using `gcc ... -pg' tolink. The startup file also includes an `exit' function which isresponsible for writing the file `gmon.out'.

Number-of-calls information for library routines is collected byusing a special version of the C library. The programs in it are thesame as in the usual C library, but they were compiled with `-pg'. Ifyou link your program with `gcc ... -pg', it automatically uses theprofiling version of the library.

The output from gprof gives no indication of parts of your programthat are limited by I/O or swapping bandwidth. This is because samplesof the program counter are taken at fixed intervals of run time.Therefore, the time measurements in gprof output say nothing about timethat your program was not running. For example, a part of the programthat creates so much data that it cannot all fit in physical memory atonce may run very slowly due to thrashing, but gprof will say it useslittle time. On the other hand, sampling by run time has the advantagethat the amount of load due to other users won't directly affect theoutput you get.

当我们使用"-pg" 选项编译程序后,gcc会做三个工作:

1. 程序的入口处(main 函数之前)插入monstartup函数的调用代码,完成profile的初始化工作,包括分配保存信息的内存以及设置一个clock 信号处理函数;

2. 在每个函数的入口处插入_mcount函数的调用代码,用于统计函数的调用信息:包括调用时间、调用次数以及调用栈信息;

3. 在程序退出时(在 atexit () 里)插入_mcleanup()函数的调用代码,负责将profile信息输出到gmon.out中。

 

这些过程可以通过objdump反汇编显示出来:

objdump -S a.out

0000000000400aba<main>:

400aba: 55 push %rbp

400abb: 48 89e5 mov %rsp,%rbp

400abe: 48 83 ec20 sub $0x20,%rsp

400ac2: e8 69 fd ffff callq 400830<mcount@plt>

......

可以看出,在main函数的入口插入了一行汇编代码:callq 400830 <mcount@plt> ,这样main函数的第一行执行代码就是调用_mcount函数。

我们接下来再看看glibc的这三个函数具体都做了什么:

 

a ) __monstartup 此函数的定义在glibc的gmon/gmon.c中

A special startup routine allocates memory for the histogram andeither calls profil() or sets up a clock signal handler. This routine(monstartup) can be invoked in several ways. On Linux systems, aspecial profiling startup file gcrt0.o, which invokes monstartup beforemain, is used instead of the default crt0.o. Use of this specialstartup file is one of the effects of using `gcc ... -pg' to link. OnSPARC systems, no special startup files are used. Rather, the mcountroutine, when it is invoked for the first time (typically when main iscalled), calls monstartup.

linux系统中,__monstartup是在__gmon_start__ 中调用的。在程序链接过程中,gcc用gcrt0.o替代了默认的crt0.o,从而修改了main函数执行前的初始化工作:

crt0.o是应用程序编译链接时需要的起动文件,在程序链接阶段被链接。主要工作是初试化应用程序栈,初试化程序的运行环境和在程序退出时清除和释放资源。

__gmon_start__的定义在csu/gmon-start.c中

void

__gmon_start__ (void)

{

#ifdef HAVE_INITFINI

/* Protect from being called more than once. Since crti.o is linked

into every shared library, each of their init functions will call us. */

static int called;

 

if (called)

return;

 

called = 1;

#endif

 

/* Start keeping profiling records. */

__monstartup ((u_long) TEXT_START, (u_long) &etext);

 

/* Call _mcleanup before exiting; it will write out gmon.out from the

collected data. */

atexit (&_mcleanup);

__gmon_start__ 不仅调用了__monstartup函数,还注册了一个清理函数_mcleanup,此函数将在程序结束时被调用。_mcleanup的功能会在后续说明,接下来让我们看看__monstartup函数都做了什么。

void

__monstartup (lowpc, highpc)

u_long lowpc;

u_long highpc;

{

register int o;

char *cp;

struct gmonparam *p = &_gmonparam;

 

/*

* round lowpc and highpc to multiples of the density we're using

* so the rest of the scaling (here and in gprof) stays in ints.

*/

p->lowpc = ROUNDDOWN(lowpc, HISTFRACTION * sizeof(HISTCOUNTER));

p->highpc = ROUNDUP(highpc, HISTFRACTION * sizeof(HISTCOUNTER));

p->textsize = p->highpc - p->lowpc;

p->kcountsize = ROUNDUP(p->textsize / HISTFRACTION, sizeof(*p->froms));

p->hashfraction = HASHFRACTION;

p->log_hashfraction = -1;

/* The following test must be kept in sync with the corresponding

test in mcount.c. */

if ((HASHFRACTION & (HASHFRACTION - 1)) == 0) {

/* if HASHFRACTION is a power of two, mcount can use shifting

instead of integer division. Precompute shift amount. */

p->log_hashfraction = ffs(p->hashfraction * sizeof(*p->froms)) - 1;

}

p->fromssize = p->textsize / HASHFRACTION;

p->tolimit = p->textsize * ARCDENSITY / 100;

if (p->tolimit < MINARCS)

p->tolimit = MINARCS;

else if (p->tolimit > MAXARCS)

p->tolimit = MAXARCS;

p->tossize = p->tolimit * sizeof(struct tostruct);

 

cp = calloc (p->kcountsize + p->fromssize + p->tossize, 1);

if (! cp)

{

ERR("monstartup: out of memory\n");

p->tos = NULL;

p->state = GMON_PROF_ERROR;

return;

}

p->tos = (struct tostruct *)cp;

cp += p->tossize;

p->kcount = (HISTCOUNTER *)cp;

cp += p->kcountsize;

p->froms = (ARCINDEX *)cp;

 

p->tos[0].link = 0;

 

o = p->highpc - p->lowpc;

if (p->kcountsize < (u_long) o)

{

#ifndef hp300

s_scale = ((float)p->kcountsize / o ) * SCALE_1_TO_1;

#else

/* avoid floating point operations */

int quot = o / p->kcountsize;

 

if (quot >= 0x10000)

s_scale = 1;

else if (quot >= 0x100)

s_scale = 0x10000 / quot;

else if (o >= 0x800000)

s_scale = 0x1000000 / (o / (p->kcountsize >> 8));

else

s_scale = 0x1000000 / ((o << 8) / p->kcountsize);

#endif

} else

s_scale = SCALE_1_TO_1;

 

__moncontrol(1);

}

可以看书,函数中的大部分代码都是在做初始化工作,为profile信息分配存储空间,它的两个参数lowpc,highpc(通过调试可以得知lowpc起始是程序代码段的起始地址,而highpc是程序代码段的结束地址,&etext),分别代表了需要记录profile信息的地址范围,超过这个范围的地址,gprof是不会记录profile信息的。这也解释了为何gprof不能支持对动态库的解析,以为动态库的装载是在程序代码段之外的。我们通过一个实例可以证明这一点。

以一个简单的测试程序为例:

#include <stdio.h>

int or_f(int a,int b)

{

return a^b;

}

int main(int argc,char** argv)

{

printf("%d\n",or_f(1,2));

sleep(30);

return 1;

}

编译生成./test可执行程序。我们用readelf工具获取test文件的段信息,

readelf -S test

Section Headers:

[Nr] Name Type Address Offset

Size EntSize Flags Link Info Align

......

[12] .text PROGBITS 0000000000400540 00000540

0000000000000278 0000000000000000 AX 0 0 16

.......

从输出可以看出,test可执行程序的text代码地址为0x400540 ~ 0x400540 + 0x278。

接下来运行./test ,通过对glibc代码的修改,我们打印出__monstartup函数的两个实参值,结果如下:

lowpc: 400540, highpc: 4007c6,正好对应着test程序的代码段范围。

同时我们也dump出test程度在内存中的装载地址:

cat /proc/$self/maps:

00400000-00401000 r-xp 00000000 08:03 70746688 /tmp/test

00600000-00601000 rw-p 00000000 08:03 70746688 /tmp/test

10ca4000-10cc5000 rw-p 10ca4000 00:00 0 [heap]

3536600000-353661c000 r-xp 00000000 08:03 93028660 /lib64/ld-2.5.so

353681b000-353681c000 r--p 0001b000 08:03 93028660 /lib64/ld-2.5.so

353681c000-353681d000 rw-p 0001c000 08:03 93028660 /lib64/ld-2.5.so

2b4f1af23000-2b4f1af25000 rw-p 2b4f1af23000 00:00 0

2b4f1af25000-2b4f1b063000 r-xp 00000000 08:03 32931849 /root/glibc-2.5-42-build/lib/libc-2.5.so

2b4f1b063000-2b4f1b263000 ---p 0013e000 08:03 32931849 /root/glibc-2.5-42-build/lib/libc-2.5.so

2b4f1b263000-2b4f1b267000 r--p 0013e000 08:03 32931849 /root/glibc-2.5-42-build/lib/libc-2.5.so

2b4f1b267000-2b4f1b268000 rw-p 00142000 08:03 32931849 /root/glibc-2.5-42-build/lib/libc-2.5.so

2b4f1b268000-2b4f1b26f000 rw-p 2b4f1b268000 00:00 0

7fffa306b000-7fffa3080000 rw-p 7ffffffea000 00:00 0 [stack]

ffffffffff600000-ffffffffffe00000 ---p 00000000 00:00 0 [vdso]

test装载到内存的地址范围为00400000-00401000,为libc.so装载到内存的地址范围为2b4f1af25000-2b4f1b063000,现在不在lowpc和highpc范围之内,所以libc中的函数是不会被gprof解析的。

__monstartup函数的最后会调用__moncontrol函数来设置一个clock信号处理函数用于设置提取sample。

__moncontrol的定义在glibc的gmon/gmon.c中

void

__moncontrol (mode)

int mode;

{

struct gmonparam *p = &_gmonparam;

 

/* Don't change the state if we ran into an error. */

if (p->state == GMON_PROF_ERROR)

return;

 

if (mode)

{

/* start */

__profil((void *) p->kcount, p->kcountsize, p->lowpc, s_scale);

p->state = GMON_PROF_ON;

}

else

{

/* stop */

__profil(NULL, 0, 0, 0);

p->state = GMON_PROF_OFF;

}

}

其中__profil的定义在sysdeps/posix/profil.c中

 

int

__profil (u_short *sample_buffer, size_t size, size_t offset, u_int scale)

{

struct sigaction act;

struct itimerval timer;

#ifndef IS_IN_rtld

static struct sigaction oact;

static struct itimerval otimer;

# define oact_ptr &oact

# define otimer_ptr &otimer

 

if (sample_buffer == NULL)

{

/* Disable profiling. */

if (samples == NULL)

/* Wasn't turned on. */

return 0;

 

if (__setitimer (ITIMER_PROF, &otimer, NULL) < 0)

return -1;

samples = NULL;

return __sigaction (SIGPROF, &oact, NULL);

}

 

if (samples)

{

/* Was already turned on. Restore old timer and signal handler

first. */

if (__setitimer (ITIMER_PROF, &otimer, NULL) < 0

|| __sigaction (SIGPROF, &oact, NULL) < 0)

return -1;

}

#else

/* In ld.so profiling should never be disabled once it runs. */

//assert (sample_buffer != NULL);

# define oact_ptr NULL

# define otimer_ptr NULL

#endif

 

samples = sample_buffer;

nsamples = size / sizeof *samples;

pc_offset = offset;

pc_scale = scale;

 

act.sa_handler = (sighandler_t) &profil_counter;

act.sa_flags = SA_RESTART;

__sigfillset (&act.sa_mask);

if (__sigaction (SIGPROF, &act, oact_ptr) < 0)

return -1;

 

timer.it_value.tv_sec = 0;

timer.it_value.tv_usec = 1000000 / __profile_frequency ();

timer.it_interval = timer.it_value;

return __setitimer (ITIMER_PROF, &timer, otimer_ptr);

}

这个函数的主要作用就是定义了一个SIGPROF信号处理函数,并通过__setitimer函数设置SIGPROF的发送频率。这个信号处理函数的功能很关键,后续仍会说明。

 

b)_mcount 此函数的定义在sysdeps/generic/machine-gmon.h中

#define MCOUNT \

void _mcount (void) \

{ \

mcount_internal ((u_long) RETURN_ADDRESS (1), (u_long) RETURN_ADDRESS (0)); \

}

其中((u_long) RETURN_ADDRESS (nr)调用了__builtin_return_address(nr)函数,__builtin_return_address(nr)会返回当前调用栈中第nr帧的pc地址。所以(u_long)RETURN_ADDRESS (0)返回的是当前函数地址topc;而(u_long) RETURN_ADDRESS(1)返回的是当前函数的返回地址frompc。

__builtin_return_address(LEVEL)

 

---This function returns the return address of the currentfunction,or of one of its callers. The LEVEL argument is number offrames to scan up the call stack. A value of '0' yields the returnaddress of the current function,a value of '1' yields the returnaddress of the caller of the current function,and so forth.

mcount_internal的定义在gmon/mcont.c中

_MCOUNT_DECL(frompc, selfpc) /* _mcount; may be static, inline, etc */

{

register ARCINDEX *frompcindex;

register struct tostruct *top, *prevtop;

register struct gmonparam *p;

register ARCINDEX toindex;

int i;

 

p = &_gmonparam;

/*

* check that we are profiling

* and that we aren't recursively invoked.

*/

if (catomic_compare_and_exchange_bool_acq (&p->state, GMON_PROF_BUSY,

GMON_PROF_ON))

return;

 

/*

* check that frompcindex is a reasonable pc value.

* for example: signal catchers get called from the stack,

* not from text space. too bad.

*/

frompc -= p->lowpc;

if (frompc > p->textsize)

goto done;

 

/* The following test used to be

if (p->log_hashfraction >= 0)

But we can simplify this if we assume the profiling data

is always initialized by the functions in gmon.c. But

then it is possible to avoid a runtime check and use the

smae `if' as in gmon.c. So keep these tests in sync. */

if ((HASHFRACTION & (HASHFRACTION - 1)) == 0) {

/* avoid integer divide if possible: */

i = frompc >> p->log_hashfraction;

} else {

i = frompc / (p->hashfraction * sizeof(*p->froms));

}

frompcindex = &p->froms[i];

toindex = *frompcindex;

if (toindex == 0) {

/*

* first time traversing this arc

*/

toindex = ++p->tos[0].link;

if (toindex >= p->tolimit)

/* halt further profiling */

goto overflow;

 

*frompcindex = toindex;

top = &p->tos[toindex];

top->selfpc = selfpc;

top->count = 1;

top->link = 0;

goto done;

}

top = &p->tos[toindex];

if (top->selfpc == selfpc) {

/*

* arc at front of chain; usual case.

*/

top->count++;

goto done;

}

/*

* have to go looking down chain for it.

* top points to what we are looking at,

* prevtop points to previous top.

* we know it is not at the head of the chain.

*/

for (; /* goto done */; ) {

if (top->link == 0) {

/*

* top is end of the chain and none of the chain

* had top->selfpc == selfpc.

* so we allocate a new tostruct

* and link it to the head of the chain.

*/

toindex = ++p->tos[0].link;

if (toindex >= p->tolimit)

goto overflow;

 

top = &p->tos[toindex];

top->selfpc = selfpc;

top->count = 1;

top->link = *frompcindex;

*frompcindex = toindex;

goto done;

}

/*

* otherwise, check the next arc on the chain.

*/

prevtop = top;

top = &p->tos[top->link];

if (top->selfpc == selfpc) {

/*

* there it is.

* increment its count

* move it to the head of the chain.

*/

top->count++;

toindex = prevtop->link;

prevtop->link = top->link;

top->link = *frompcindex;

*frompcindex = toindex;

goto done;

}

 

}

done:

p->state = GMON_PROF_ON;

return;

overflow:

p->state = GMON_PROF_ERROR;

return;

}

此函数的主要功能就是记录每个函数的调用次数,以及函数之间的调用关系表。并将这些信息保存在全局变量_gmonparam中。由于此函数是通过hack的方式来调用的(插入入口代码),因此其获取的信息都是精确的。强调z这一点的目的是为了下面将要介绍的另一个主要函数: profil_counter 。回溯到gcc的一个步骤,monstartup函数在初始化的最后阶段,通过sigaction调用注册了一个SIGPROF信号处理函数,这个函数profil_counter。这个函数会以__profile_frequency()的频率被调用,并完成profile的主要工作:收集sample信息,以此来计算每个函数的消耗时间。

profil_counter函数的定义依赖于具体的系统平台,X86_64平台下的定义是在sysdeps/unix/sysv/linux/x86_64/profil-counter.h中

static void

profil_counter (int signo, SIGCONTEXT scp)

{

profil_count ((void *) GET_PC (scp));

 

/* This is a hack to prevent the compiler from implementing the

above function call as a sibcall. The sibcall would overwrite

the signal context. */

asm volatile ("");

}

其最终调用的profil_count定义在sysdeps/posix/profil.c中

static inline void

profil_count (void *pc)

{

size_t i = (pc - pc_offset - (void *) 0) / 2;

 

if (sizeof (unsigned long long int) > sizeof (size_t))

i = (unsigned long long int) i * pc_scale / 65536;

else

i = i / 65536 * pc_scale + i % 65536 * pc_scale / 65536;

 

if (i < nsamples)

++samples[i];

}

这段代码的逻辑有点晦涩,需要联系之前的处理逻辑来理解。pc_offset、pc_scale以及samples这些全局变量的赋值是在__profil函数中处理的。回溯__profil的逻辑代码,就可以看出samples=_gmonparam->kcount, 用于保存sample信息,pc_offset =p->lowpc,是程序代码段的起始地址,pc_scale是一个比例因子,用于控制sample的提取粒度。综合上下文,gprof在这里的处理逻辑是将lowpc~lowpc+65536(linux下默认一个段的大小为64K)范围内的代码映射到一个内存数组,而pc_scale其实就是决定了映射粒度。对于任何一个处于[lowpc,lowpc+65536]范围内的pc,其对应的数组下标是: pc - lowpc / (65536/ pc_scale) = (pc - lowpc) * pc_scale /65536;这样一个数组项(一个sample)对应了一段pc_scale长度的程序地址,而每当这段地址内的代码被执行时,相应的sample计数就会加1。

 

c ) 最后当程序结束时,会调用_mcleanup,其定义在gmon/gmon.c中。

void

_mcleanup (void)

{

__moncontrol (0);

 

if (_gmonparam.state != GMON_PROF_ERROR)

write_gmon ();

 

/* free the memory. */

free (_gmonparam.tos);

}

首先其通过__moncontrol(0)结束profil工作,其次通过write_gmon ()函数将profile信息输出到gmon.out文件中。

write_gmo函数的定义在gmon/gmon.c中

static void

write_gmon (void)

{

struct gmon_hdr ghdr __attribute__ ((aligned (__alignof__ (int))));

int fd = -1;

char *env;

 

#ifndef O_NOFOLLOW

# define O_NOFOLLOW 0

#endif

 

env = getenv ("GMON_OUT_PREFIX");

if (env != NULL && !__libc_enable_secure)

{

size_t len = strlen (env);

char buf[len + 20];

__snprintf (buf, sizeof (buf), "%s.%u", env, __getpid ());

fd = open_not_cancel (buf, O_CREAT|O_TRUNC|O_WRONLY|O_NOFOLLOW, 0666);

}

 

if (fd == -1)

{

fd = open_not_cancel ("gmon.out", O_CREAT|O_TRUNC|O_WRONLY|O_NOFOLLOW,

0666);

if (fd < 0)

{

char buf[300];

int errnum = errno;

__fxprintf (NULL, "_mcleanup: gmon.out: %s\n",

__strerror_r (errnum, buf, sizeof buf));

return;

}

}

 

/* write gmon.out header: */

memset (&ghdr, '\0', sizeof (struct gmon_hdr));

memcpy (&ghdr.cookie[0], GMON_MAGIC, sizeof (ghdr.cookie));

*(int32_t *) ghdr.version = GMON_VERSION;

write_not_cancel (fd, &ghdr, sizeof (struct gmon_hdr));

 

/* write PC histogram: */

write_hist (fd);

 

/* write call-graph: */

write_call_graph (fd);

 

/* write basic-block execution counts: */

write_bb_counts (fd);

 

close_not_cancel_no_status (fd);

}

通过write_hist、write_call_graph、write_bb_counts这三个子函数,其分别将pc histogram、call-graph以及basic-block execution counts信息输出到gmon.out中。

 

1.4 gprof的输出分析

在gmon.out文件产生之后,可以通过GNU binutils中提供的工具gprof来分析数据,转换成容易阅读、理解的格式(文字、图片等)。

gprof的主要代码在gprof/gprof.c中

在gmon_out_read函数中,其分别通过hist_read_rec、cg_read_rec、bb_read_rec来读取gmon.out中对应的pc histogram、call-graph以及basic-block executioncounts信息。在将pchistogram映射到具体函数时间的处理上,gprof采用了一种近似算法:

sym_high_pc

sym_low_pc

 

 

 

 

 

其中,bin_low_pc待用sample数组中的任意一项所对应的PC地址:而bin_high_pc代表bin_low_pc下一个sample对应的PC地址:

bin_low_pc = lowpc + (bfd_vma)(hist_scale * i);

bin_high_pc = lowpc +(bfd_vma) (hist_scale * (i + 1));

sym_low_pc待用可执行程序中某个符号(函数名、段名等)所对应的PC地址,sym_high_pc为下一个符号项所对应的PC地址:

sym_low_pc =symtab.base[j].hist.scaled_addr;

sym_high_pc = symtab.base[j +1].hist.scaled_addr;

gprof只将[bin_low_pc, bin_high_pc]和[sym_low_pc ,sym_high_pc]重合区域(以箭头标识)的sample次数算为sym_low_pc符号的消耗时间。

overlap = MIN (bin_high_pc,sym_high_pc) - MAX (bin_low_pc, sym_low_pc);

credit = overlap * time /hist_scale; // time = sample[i], hist_scale = pc_scale.

 

1.5 小结

Gprof是GUN 工具链中自带的profiler,无需安装成本,与gcc的结合让其使用方便,能够快速上手。但是gprof也有其一定的缺陷,

1、它的测试结果并不能保证完全准确: 它无法统计程序耗在IO以及swap上的时间:

The output from gprof gives no indication of parts of your programthat are limited by I/O or swapping bandwidth. This is because samplesof the program counter are taken at fixed intervals of the program'srun time. Therefore, the time measurements in gprof output say nothingabout time that your program was not running. For example, a part ofthe program that creates so much data that it cannot all fit inphysical memory at once may run very slowly due to thrashing, but gprofwill say it uses little time. On the other hand, sampling by run timehas the advantage that the amount of load due to other users won'tdirectly affect the output you get.

而且,由于其通过采集sample来计算profile的方式,本身就存在一定的失真:

The run-time figures that gprof gives you are based on a samplingprocess, so they are subject to statistical inaccuracy. If a functionruns only a small amount of time, so that on the average the samplingprocess ought to catch that function in the act only once, there is apretty good chance it will actually find that function zero times, ortwice.

By contrast, the number-of-calls figures are derived by counting,not sampling. They are completely accurate and will not vary from runto run if your program is deterministic.

The sampling period that is printed at the beginning of theflat profile says how often samples are taken. The rule of thumb isthat a run-time figure is accurate if it is considerably bigger thanthe sampling period.

The actual amount of error is usually more than one sampling period. In fact, if a value is n times the sampling period, the expected error in it is the square-root of nsampling periods. If the sampling period is 0.01 seconds and foo'srun-time is 1 second, the expected error in foo's run-time is 0.1seconds. It is likely to vary this much on the average from one profiling run to the next. (Sometimes it will vary more.)

This does not mean that a small run-time figure is devoid of information. If the program's totalrun-time is large, a small run-time for one function does tell you thatthat function used an insignificant fraction of the whole program'stime. Usually this means it is not worth optimizing.

2. gprof不能支持动态库的解析。原因在本文中已经分析。

3. gprof不易维护和扩展,因为gprof的代码是封装在GNU工具链的glibc以及binutils中,修改libc的风险较大,而且版本也不易维护(不同系统中使用的libc版本不一致,如果单独更新glibc,会出现程序crash)。

 

二、 GooglePerformance Tools

Goolgleperformance tools是google公司开发的一套用于C++Profile的工具集。其中包括:

一个优化的内存管理算法—tcmalloc性能优于malloc。

一个用于CPU profile的工具,用于检测程序的性能热点,这个功能和gprof类似。

一个用于堆检查工具,用于检测程序在是够有内存泄露,这个功能和valgrind类似。

一个用于Heap profile的工具,用于监控程序在执行过程的内存使用情况。

官方文档:

http://code.google.com/p/google-perftools/wiki/GooglePerformanceTools

 

它的使用方式比较简单:首先在编译程序的时候加上相应的链接库,然后在运行程序时

通过设置相应的环境变量来激活工具。

 

1.使用其提供的内存管理函数---TC Malloc:

gcc [...] -ltcmalloc

 

2.使用其堆内存检查工具:

gcc [...] -o myprogram -ltcmalloc

HEAPCHECK=normal ./myprogram

 

3.使用Heap Profiler:

gcc [...] -o myprogram -ltcmalloc

HEAPPROFILE=/tmp/netheap ./myprogram

 

4.使用Cpu Profiler:

gcc [...] -o myprogram -lprofiler

CPUPROFILE=/tmp/profile ./myprogram

 

它的输出也很清晰,下图是一个CpuProfiler的结果图,其中每个方块代码一个函数,方块间的箭头描述了函数之间的调用关系,每个方块里面有两个数字:X ofY,其中Y表示在程序执行过程中函数所消耗的总体时间,X表示函数自身所消耗的时间,所以Y-X及时函数所调用的子函数消耗时间。如果函数没有子函数,则只显示总体时间。(X,Y的单位得sample,每个sample所代表的时间可以设置,默认为10ms)

 

 

2.1 安装

a) 安装libunwind

libunwind是一个用于解析程序调用栈的C++库,由于glibc内建的栈回滚功能在64位系统上有bug,因此googleperformance tools建议使用libunwind

下载libunwind-0.99-beta.tar.gz

cd $HOME

tarxzvf libunwind-0.99-beta.tar.gz

mkdir libunwind-0.99-beta-build

cd libunwind-0.99-beta

./configure –prefix=$HOME/libunwind-0.99-beta-build

 

b) 安装Google PerformanceTools

注意:如果在系统目录中找不到libunwind,google performance tools将默认使用glibc的内建功能,因此我们需要手动设置libunwind的安装目录。

下载google-perftools-1.6.tar.gz

cd $HOME

tar xzvf google-perftools-1.6.tar.gz

mkdir google-perftools-1.6-build

cd google-perftools-1.6

./configure –prefix=$HOME/ google-perftools-1.6-build

CPPFLAGS=-I$HOME/libunwind-0.99-beta-build/include

LDFLAGS=-L$HOME/libunwind-0.99-beta-build/lib

make && make install

 

2.2 用法

参考官方文档

这里有两点想突出介绍下,一个是对动态库的支持,一个对动态profiler功能的支持。

 

2.2.1 动态库的支持

在第一章节里面我们已经证明和分析GUNProfiler不提供对动态库的支持,虽然可以通过修改glibc的代码来扩展此功能,但是维护成本较大。而Goolgle performancetools本身就已经提供了对动态库的支持功能。当然动态库的使用也分两种情况:一种是在运行时动态链接库,一种是在运行时动态加载库。

运行时链接可以动态地将程序和共享库链接并让 Linux 在执行时加载库(如果它已经在内存中了,则无需再加载)。以一个具体例子来说明:

 

//libtestprofiler.h

extern "C"{

int loopop();

}

libtestprofiler.cpp只定义了一个耗时计算函数,便于分析。

 

// libtestprofiler.cpp

#include "libtestprofiler.h"

extern "C"{

int loopop()

{

int n = 0;

for(int i = 0; i < 1000000; i++)

for(int j = 0; j < 10000; j++)

{

n |= i%100 + j/100;

}

return n;

}

将libtestprofiler.cpp编译为动态库:

g++--shared -fPIC -g -O0 -o libtestprofiler.so libtestprofiler.cpp

在主程序中调用动态库:

 

#include <iostream>

#include "libtestprofiler.h"

using namespace std;

 

int main(int argc,char** argv)

{

cout << "loopop: " << loopop() << endl;

return 1;

}

编译主程序,并动态链接libtestprofiler.so:

a) 首先采用GUN Profile的方式编译主程序

g++ -g -O0 -omain main.cpp -ltestprofiler -L. –pg

./main

gprof –b ./main结果如下:

 

Each sample counts as 0.01 seconds.

no time accumulated

 

% cumulative self self total

time seconds seconds calls Ts/call Ts/call name

0.00 0.00 0.00 1 0.00 0.00 global constructors keyed to main

0.00 0.00 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)

0.00 0.00 0.00 1 0.00 0.00 data_start

和预想一样,GNU Profile 不能解析动态库的性能热点。

 

b) 再以google CPU Profile的方式编译主程序:

g++ -g -O0 -omain main.cpp -ltestprofiler -L. -lprofiler-L/home/wul/google-perftools-1.6-build/lib

CPUPROFILE=perf.out./main

pprof --text./main ./perf.out,结果如下:

 

Using local file ./main.

Using local file ./perf.out.

Removing killpg from all stack traces.

Total: 5923 samples

5923 100.0% 100.0% 5923 100.0% loopop

0 0.0% 100.0% 5923 100.0% __libc_start_main

0 0.0% 100.0% 5923 100.0% _start

0 0.0% 100.0% 5923 100.0% main

由此证明,Google CPU Profiler支持对动态链接库的性能分析。

 

运行时加载允许程序可以有选择地调用库中的函数。使用动态加载过程,程序可以先加载一个特定的库(已加载则不必),然后调用该库中的某一特定函数,这是构建支持插件的应用程序的一个普遍的方法。

还是以上述程序为例,对主程序代码进修改:

 

#include <stdio.h>

#include <dlfcn.h>

 

char LIBPATH[] = "./libtestprofiler.so";

typedef int (*op_t) ();

 

int main(int argc,char** argv)

{

void* dl_handle;

op_t loopop;

char* error;

 

/* Open the shared object */

dl_handle = dlopen( LIBPATH, RTLD_LAZY );

if (!dl_handle) {

printf( "dlopen failed! %s\n", dlerror() );

return 1;

}

 

/* Resolve the symbol (loopop) from the object */

loopop = (op_t)dlsym( dl_handle, "loopop");

error = dlerror();

if (error != NULL) {

printf( "dlsym failed! %s\n", error );

return 1;

}

 

/* Call the resolved loopop and print the result */

printf("result: %d\n", (loopop)() );

 

/* Close the object */

dlclose( dl_handle );

 

return 0;

}

编译:

g++ -g -O0 -o main_dl main_dl.cpp -lprofiler -L/home/wul/google-perftools-1.6-build/lib-ldl

CPUPROFILE=perf_dl.out./main_dl

pprof--text ./main_dl ./perf_dl.out,结果如下:

 

Using local file ./main_dl.

Using local file ./perf_dl.out.

Removing killpg from all stack traces.

Total: 5949 samples

843 14.2% 14.2% 843 14.2% 0x00002b2f203d25d6

……

0 0.0% 100.0% 1 0.0% 0x00002b2f203d25ed

0 0.0% 100.0% 5949 100.0% __libc_start_main

0 0.0% 100.0% 5949 100.0% _start

0 0.0% 100.0% 5949 100.0% main

很奇怪,这个结果显示libtestprofiler.so库中的符号没有正确解析,perf_dl.out文件也没有包含libtestprofiler.so的内存映射信息,但是我们确实在主程序已经通过dlopen将动态库装载到内存并执行成功了,为何在主程序的内存映射表中找不到动态库的信息呢?经过一番分析和调查,终于找到原因,因为perf_dl.out文件的输出工作是在主程序执行结束之后、系统回收资源的时候调用的(具体见实现原理一节),而在此时主程序执行了dlclose()函数卸载了libtestprofiler.so,所以随后dump出的内存映射表当然就不会包含libtestprofiler.so的信息了。我们测试下将dlclose(dl_handle)注释后的运行结果:

 

Using local file ./main_dl.

Using local file ./perf_dl.out.

Removing killpg from all stack traces.

Total: 5923 samples

5923 100.0% 100.0% 5923 100.0% loopop

0 0.0% 100.0% 5923 100.0% __libc_start_main

0 0.0% 100.0% 5923 100.0% _start

0 0.0% 100.0% 5923 100.0% main

哈哈,动态库中的符号又能正常解析了。

 

2.2.2 动态profiler功能

这里首先需要解释下何谓动态profiler功能:传统的profiler工具,以GUNProfiler为例,只能编译阶段控制profiler的开关(-fprofile-arcs-ftest-coverage),但是我们有时候需要在程序的运行阶段,或者说运行的中间阶段控制profiler的开关。Googleperformance tools可以通过CPUPROFILE环境变量在程序运行初阶段控制cpuprofiler的开关,而且根据文档/usr/doc/google-perftools-1.5/pprof_remote_servers.html的提示,可以通过功能扩展可以实现在运行中间阶段或通过http协议远程控制profiler信息的功能。gperftools-httpd项目就已经初步完成了这个功能,我们可以体验一下。

1.从http://code.google.com/p/gperftools-httpd/下载gperftools-httpd安装。

2.修改下测试程序 main.cpp, 正常运行时间,方便测试

 

#include <iostream>

#include "gperftools-httpd.h"

#include "libtestprofiler.h"

using namespace std;

int main(int argc,char** argv)

{

ghttpd();

while(1)

cout << "loopop: " << loopop() << endl;

return 1;

}

这个程序主要做了两点修改,调用ghttpd()启动一个轻量级web servive,已完成pprof的远程请求服务;通过while循环加长了程序的执行时间,已方便验证动态profiler功能。

3.编译,需要连接libghttpd.so、libprofiler.so

g++-g -O0 -o main main.cpp-I/home/wul/gperftools-httpd-0.2-ltestprofiler -L.-L/home/wul/gperftools-httpd-0.2/ -lghttpd -lprofiler -L/home/wul/google-perftools-1.6-build/lib-dl -lpthread

4. 启动测试程序

./main 注意我们这时并没有设置CPUPROFILE环境变量,即表示此时CPU PROFILE功能还没有打开。

5.通过pprof工具远程打开测试程序的CPU profile功能:

pprof ./main http://localhost:9999/pprof/profile,结果如下:

 

Using local file ./main.

Gathering CPU profile from http://localhost:9999/pprof/profile?seconds=30 for 30 seconds to

/home/wul/pprof/main.1292168091.localhost

Be patient...

Wrote profile to /home/wul/pprof/main.1292168091.localhost

Removing _L_mutex_unlock_15 from all stack traces.

Welcome to pprof! For help, type 'help'.

(pprof) text

Total: 2728 samples

2728 100.0% 100.0% 2728 100.0% loopop

0 0.0% 100.0% 2728 100.0% __libc_start_main

0 0.0% 100.0% 2728 100.0% _start

0 0.0% 100.0% 2728 100.0% main

从结果中可以看出,当pprof向本地web服务http://localhost:9999/发送Getpprof/profile请求时,测试程序就会自动开启profile功能,默认的监控时间段是now~now+30s(时间长短可以通过seconds参数设置),等待30s之后,测试程序停止profile,将结果返回给pprof并保存在/home/wul/pprof/main.1292168091.localhost中,此时再通过text命令就可以看到解析后的输出了。pprof工具还支持其它的query参数,譬如采样频率控制、触发采样事件等,具体可以参考gperftools-httpd以及google performancetools的官方文档。

 

2.3 实现原理

Google performance tools包含四大功能,但是本章主要集中介绍CPU profiler功能,以便和GNU profiler做横向对比。

 

2.3.1 CPU Profile

googleCPU profile的实现方式不同于gprof,但是两个的实现原理有点相似。CPUprofiler是通过设置SIGPROF信号处理函数来采集sample的,这点和gprof一样,但是CPUprofiler没有在函数入口插入代码,而是通过保存调用栈信息来记录函数的调用图和调用次数。CPUprofiler的主要实现代码在src/profiler.cc中。这个文件中定义了一个CpuProfiler类,并声明一个该类的静态实例。这样在main函数之前,此静态实例就会被初始化。

 

 

// Initialize profiling: activated if getenv("CPUPROFILE") exists.

CpuProfiler::CpuProfiler()

: prof_handler_token_(NULL) {

// TODO(cgd) Move this code *out* of the CpuProfile constructor into a

// separate object responsible for initialization. With ProfileHandler there

// is no need to limit the number of profilers. charfname[PATH_MAX]; if (!GetUniquePathFromEnv("CPUPROFILE", fname)) { return;

}

// We don't enable profiling if setuid -- it's a security risk

#ifdef HAVE_GETEUID

if (getuid() != geteuid())

return;

#endif

if (!Start(fname, NULL)) {

RAW_LOG(FATAL, "Can't turn on cpu profiling for '%s': %s\n",

fname, strerror(errno));

}

}

 

该构造函数首先会判断系统变量CPUPROFILE是否被设置,如果设置了,则启动CPU profiler进程,否则,直接返回。我们在看看Start函数做了什么:

 

 

bool CpuProfiler::Start(const char* fname, const ProfilerOptions* options) {

SpinLockHolder cl(&lock_);

 

if (collector_.enabled()) {

return false;

}

 

ProfileHandlerState prof_handler_state;

ProfileHandlerGetState(&prof_handler_state);

 

ProfileData::Options collector_options;

collector_options.set_frequency(prof_handler_state.frequency);

if (!collector_.Start(fname, collector_options)) {

return false;

}

 

filter_ = NULL;

if (options != NULL && options->filter_in_thread != NULL) {

filter_ = options->filter_in_thread;

filter_arg_ = options->filter_in_thread_arg;

}

 

// Setup handler for SIGPROF interrupts

EnableHandler();

 

return true;

}

 

此函数首先会调用ProfileHandlerGetState来获取其它的控制参数,包括CPUPROFILE_REALTIME和CPUPROFILE_FREQUENCY。

 

 

CPUPROFILE_FREQUENCY=x

default: 100

How many interrupts/second the cpu-profiler samples.

CPUPROFILE_REALTIME=1

default: [not set]

If set to any value (including 0 or the empty string), useITIMER_REAL instead of ITIMER_PROF to gather profiles. In general,ITIMER_REAL is not as accurate as ITIMER_PROF, and also interacts badlywith use of alarm(), so prefer ITIMER_PROF unless you have a reasonprefer ITIMER_REAL.

 

其次,函数调用ProfileData::Start为记录profiler信息分配内存并初始化,其定义在profiledata.cc中。

 

 

bool ProfileData::Start(const char* fname,

const ProfileData::Options& options) {

if (enabled()) {

return false;

}

 

// Open output file and initialize various data structures

int fd = open(fname, O_CREAT | O_WRONLY | O_TRUNC, 0666);

if (fd < 0) {

// Can't open outfile for write

return false;

}

 

start_time_ = time(NULL);

fname_ = strdup(fname);

 

// Reset counters

num_evicted_ = 0;

count_ = 0;

evictions_ = 0;

total_bytes_ = 0;

 

hash_ = new Bucket[kBuckets];

evict_ = new Slot[kBufferLength];

memset(hash_, 0, sizeof(hash_[0]) * kBuckets);

// Record special entries

evict_[num_evicted_++] = 0; // count for header

evict_[num_evicted_++] = 3; // depth for header

evict_[num_evicted_++] = 0; // Version number

CHECK_NE(0, options.frequency());

int period = 1000000 / options.frequency();

evict_[num_evicted_++] = period; // Period (microseconds)

evict_[num_evicted_++] = 0; // Padding

 

out_ = fd;

 

return true;

}

 

其中slot数组evict_就是profiler输出文件中的保存内容,具体可参考profiler输出文件的格式说明。Bucket数组hash_是用于临时保存程序调用栈信息的hash表,num_evicted记录evict_数组中的有效长度。这些变量在后续将会经常出现。回到profiler.cc中的CpuProfiler::Start函数,其最后一步调用的是EnableHandler(), 用于设置SIGPROF的信号处理函数。

 

 

void CpuProfiler::EnableHandler() {

RAW_CHECK(prof_handler_token_ == NULL, "SIGPROF handler already registered");

prof_handler_token_ = ProfileHandlerRegisterCallback(prof_handler, this);

RAW_CHECK(prof_handler_token_ != NULL, "Failed to set up SIGPROF handler");

}

 

函数通过ProfileHandlerRegisterCallback注册了一个回调函数prof_handler:

 

 

ProfileHandlerToken* ProfileHandler::RegisterCallback(

ProfileHandlerCallback callback, void* callback_arg) {

ProfileHandlerToken* token = new ProfileHandlerToken(callback, callback_arg);

 

SpinLockHolder cl(&control_lock_);

DisableHandler();

{

SpinLockHolder sl(&signal_lock_);

callbacks_.push_back(token);

}

// Start the timer if timer is shared and this is a first callback.

if ((callback_count_ == 0) && (timer_sharing_ == TIMERS_SHARED)) {

StartTimer();

}

++callback_count_;

EnableHandler();

return token;

}

 

紧接着通过ProfileHandler::EnableHandler注册SIGPROF信号处理函数SignalHandler。

 

 

void ProfileHandler::EnableHandler() {

struct sigaction sa;

sa.sa_sigaction = SignalHandler;

sa.sa_flags = SA_RESTART | SA_SIGINFO;

sigemptyset(&sa.sa_mask);

const int signal_number = (timer_type_ == ITIMER_PROF ? SIGPROF : SIGALRM);

RAW_CHECK(sigaction(signal_number, &sa, NULL) == 0, "sigprof (enable)");

}

 

到此,CPU profile的初始化工作基本上都完成了,总结一下主要是完成了两个工作:一个是内存的分配以及初始化,一个是注册SIGPROF信号处理函数,以便采集sample信息。所以接下来的重点将是分析CPU profile是如何采集sample的。首先看看SignalHandler函数的定义:

 

 

void ProfileHandler::SignalHandler(int sig, siginfo_t* sinfo, void* ucontext) {

int saved_errno = errno;

RAW_CHECK(instance_ != NULL, "ProfileHandler is not initialized");

{

SpinLockHolder sl(&instance_->signal_lock_);

++instance_->interrupts_;

for (CallbackIterator it = instance_->callbacks_.begin();

it != instance_->callbacks_.end();

++it) {

(*it)->callback(sig, sinfo, ucontext, (*it)->callback_arg);

}

}

errno = saved_errno;

}

 

从代码中可以看出,SignalHandler除了记录中断次数之外,遍历调用了callbacks_链中的所有回调函数,回溯CPU Profile前面的初始化工作,这里就会调用prof_handler函数:

 

 

// Signal handler that records the pc in the profile-data structure. We do no

// synchronization here. profile-handler.cc guarantees that at most one

// instance of prof_handler() will run at a time. All other routines that

// access the data touched by prof_handler() disable this signal handler before

// accessing the data and therefore cannot execute concurrently with

// prof_handler().

void CpuProfiler::prof_handler(int sig, siginfo_t*, void* signal_ucontext,

void* cpu_profiler) {

CpuProfiler* instance = static_cast<CpuProfiler*>(cpu_profiler);

 

if (instance->filter_ == NULL ||

(*instance->filter_)(instance->filter_arg_)) {

void* stack[ProfileData::kMaxStackDepth];

// The top-most active routine doesn't show up as a normal

// frame, but as the "pc" value in the signal handler context.

stack[0] = GetPC(*reinterpret_cast<ucontext_t*>(signal_ucontext));

 

// We skip the top two stack trace entries (this function and one

// signal handler frame) since they are artifacts of profiling and

// should not be measured. Other profiling related frames may be

// removed by "pprof" at analysis time. Instead of skipping the top

// frames, we could skip nothing, but that would increase the

// profile size unnecessarily.

int depth = GetStackTraceWithContext(stack + 1, arraysize(stack) - 1,

2, signal_ucontext);

depth++; // To account for pc value in stack[0];

 

instance->collector_.Add(depth, stack);

}

}

 

从代码的注解片段中可以理解此函数的主要工作就是记录将当前程序的调用栈信息。顾名思义,GetPC函数用于获取当前pc指针,它是利用linux系统的信号处理机制来获取当前pc的(具体可参考《unix环境高级编程》), 其主要实现代码在getpc.h中:

 

 

inline void* GetPC(const ucontext_t& signal_ucontext) {

// fprintf(stderr,"In GetPC3");

return (void*)signal_ucontext.PC_FROM_UCONTEXT; // defined in config.h

}

 

GetStackTraceWithContext函数完成了cpu profiler过程中最重要的一步,它最终调用了libunwind库,dump出了当前的函数调用栈信息,其主要实现代码在stacktrace_libunwind-inl.h中:

 

 

int GET_STACK_TRACE_OR_FRAMES {

fprintf(stderr,"in libunwind\n");

void *ip;

int n = 0;

unw_cursor_t cursor;

unw_context_t uc;

#if IS_STACK_FRAMES

unw_word_t sp = 0, next_sp = 0;

#endif

 

if (recursive) {

return 0;

}

++recursive;

unw_getcontext(&uc);

int ret = unw_init_local(&cursor, &uc);

assert(ret >= 0);

skip_count++; // Do not include current frame

 

while (skip_count--) {

if (unw_step(&cursor) <= 0) {

goto out;

}

#if IS_STACK_FRAMES

if (unw_get_reg(&cursor, UNW_REG_SP, &next_sp)) {

goto out;

}

#endif

}

 

while (n < max_depth) {

if (unw_get_reg(&cursor, UNW_REG_IP, (unw_word_t *) &ip) < 0) {

break;

}

#if IS_STACK_FRAMES

sizes[n] = 0;

#endif

result[n++] = ip;

if (unw_step(&cursor) <= 0) {

break;

}

#if IS_STACK_FRAMES

sp = next_sp;

if (unw_get_reg(&cursor, UNW_REG_SP, &next_sp) , 0) {

break;

}

sizes[n - 1] = next_sp - sp;

#endif

}

out:

--recursive;

return n;

 

这个函数的过程有点复杂,它的主要功能是回滚当前调用栈,并将栈指针都保存在stack数组中,根据这些信息就可以记录程序指令的执行次数,以及描述函数之间的调用关系图。(具体实现原理请参考libunwind官网说明)。再对到prof_handler函数中,程序的最后一步就是将当前获取的调用栈信息保存到预先分配的内存中,其具体实现在profiledata.cc文件中:

 

 

void ProfileData::Add(int depth, const void* const* stack) {

if (!enabled()) {

return;

}

 

if (depth > kMaxStackDepth) depth = kMaxStackDepth;

RAW_CHECK(depth > 0, "ProfileData::Add depth <= 0");

 

// Make hash-value

Slot h = 0;

for (int i = 0; i < depth; i++) {

Slot slot = reinterpret_cast<Slot>(stack[i]);

h = (h << 8) | (h >> (8*(sizeof(h)-1)));

h += (slot * 31) + (slot * 7) + (slot * 3);

}

 

count_++;

 

// See if table already has an entry for this trace

bool done = false;

Bucket* bucket = &hash_[h % kBuckets];

for (int a = 0; a < kAssociativity; a++) {

Entry* e = &bucket->entry[a];

if (e->depth == depth) {

bool match = true;

for (int i = 0; i < depth; i++) {

if (e->stack[i] != reinterpret_cast<Slot>(stack[i])) {

match = false;

break;

}

}

if (match) {

e->count++;

done = true;

break;

}

}

}

 

if (!done) {

// Evict entry with smallest count

Entry* e = &bucket->entry[0];

for (int a = 1; a < kAssociativity; a++) {

if (bucket->entry[a].count < e->count) {

e = &bucket->entry[a];

}

}

if (e->count > 0) {

evictions_++;

Evict(*e);

}

 

// Use the newly evicted entry

e->depth = depth;

e->count = 1;

for (int i = 0; i < depth; i++) {

e->stack[i] = reinterpret_cast<Slot>(stack[i]);

}

}

}

 

此函数的处理流程如下:

1.对stack数组的所有项做hash,得到一个hash值;

2.根据hash值在hash_表中查找此调用栈,如果找到匹配项则增加该项的执行次数;

3.如果没有找到则将从相应的hash槽中pop出执行次数最少的一个调用栈,将此调用栈中的所有栈指针值按顺序保存到evict_数组中,并将新调用栈push到hash槽中。

 

到此,CPU profile的主要流程都走完了,总结一下其一直在循环执行一个动作:定期保存程序的当前调用栈信息。在被测程序执行结束之后,CPU profile所做的最后一步工作就是将evict_数组中保存的数据输出到%CPUPROFILER环境变量制定的文件中(profiledata.cc):

 

void ProfileData::Stop() {

if (!enabled()) {

return;

}

 

// Move data from hash table to eviction buffer

for (int b = 0; b < kBuckets; b++) {

Bucket* bucket = &hash_[b];

for (int a = 0; a < kAssociativity; a++) {

if (bucket->entry[a].count > 0) {

Evict(bucket->entry[a]);

}

}

}

 

if (num_evicted_ + 3 > kBufferLength) {

// Ensure there is enough room for end of data marker

FlushEvicted();

}

 

// Write end of data marker

evict_[num_evicted_++] = 0; // count

evict_[num_evicted_++] = 1; // depth

evict_[num_evicted_++] = 0; // end of data marker

FlushEvicted();

 

// Dump "/proc/self/maps" so we get list of mapped shared libraries

DumpProcSelfMaps(out_);

 

Reset();

fprintf(stderr, "PROFILE: interrupts/evictions/bytes = %d/%d/%" PRIuS "\n",

count_, evictions_, total_bytes_);

}

 

在dump出evict_数组数据之后,函数还通过DumpProcSelfMaps将/prof/self/map中的信息追加到输出文件中,这些信息记录了应用程序的内存映射情况,是pprof工具解析指令符号的重要依据。(关于/prof/self/map中的信息说明可以参考《程序员的自我修养》)

 

虽然监控程序已经停止,但是CPUprofiler的工作还没完全结束,因为之前保存在$CPUPROFILER文件中的数据都是二进制格式的,不具备可读性,需要借助pprof工具的解析功能才能揭露它的真实信息。

pprof是用perl语言编写的解析工具,它的主要功能就是将CPU profile的输出数据转换成容易阅读理解的可视格式,如text、pdf、gif等,接下来本文将讲解pprof的主要工作原理,具体细节可以参考pprof代码。

$CPUPROFILER文件中保存了两部分信息:前部分是定期dump的调用栈信息,每个调用栈信息中都包含了执行次数、栈深度以及栈指针值(即指令地址);后半部分记录应用程序的内存映射图。所以第一步,pprof根据内存映射图和程序符号表将调用栈中的指令地址翻译成容易理解的程序代码;第二步,pprof根据第一部分保存的栈信息描述出程序中的函数调用图;最后一步,pprof根据栈执行次数计算出每段代码的执行次数,再根据定时器的执行频率估算出程序段的执行时间,进而找出程序的性能热点。

 

2.4 小结

Google performance tools采用了和GUNProfiler近似的原理、不同的方式来达到profiler的效果。由于其通过记录调用栈信息来反推程序段的执行次数,不可避免地会出现遗漏和误算情况,而且和GUNProfiler一样,它也是通过sample的采样频率来估算程序段的运行时间,因此最终计算结果并不是十分精确的,具有一定的误差。但是,Google performance tools较之其他Profiler工具而言,有其自身的特点和优势,Googleperformance tools是一个用户态程序,不需要内核提供支持(对比oprofiler);它对被监控程序的入侵程序度较小(对比GUNProfiler),无需修改程序代码,以attach的方式跟踪程序执行状态;而且它也是google的开源项目之一,工程量较小,方面后期扩展和二次开发。

 

三、 C++ Profiler工具特性对比

总结前两章的调研结果,对目前常用的C++ profiler工具做了一个简单的对比,对比的焦点主要集中在日常使用中大家所发现或比较关注的问题。不过由于时间关系,所选工具和对比项都十分有限,希望能在后期的进一步工作中完善补充。

 

 

C++Profiler工具

精确度

对动态库的支持

对动态控制的支持

二次开发和维护成本

GUN profile

较高,对函数执行次数的统计是100%正确的,但是对函数执行时间的统计是通过采样平率估算的,存在一定的偏差。

No

编译时决定,灵活性较差

代码集成在glibc中,二次开发和修改的影响面较大,而且发布不易。

Google performance tools

一般,对函数次数和执行时间的统计都是通过采样频率估算的,存在一定的偏差和遗漏。

Yes

运行时控制,更方面操作

独立的第三方库,开源项目,二次开发和维护成本较低。

Oprofile

待调查

待调查

待调查

待调查

 

 

 

 

 

 

 

 

未完待续……

使用Gnu gprof进行Linux平台下的程序分析 (转)

Gprof 简介:

Gprof功能:打印出程序运行中各个函数消耗的时间,可以帮助程序员找出众多函数中耗时最多的函数。产生程序运行时候的函数调用关系,包括调用次数,可以帮助程序员分析程序的运行流程。

有了函数的调用关系,这会让开发人员大大提高工作效率,不用费心地去一点点找出程序的运行流程,这对小程序来说可能效果不是很明显,但对于有几万,几十万代码量的工程来说,效率是毋庸置疑的!而且这个功能对于维护旧代码或者是分析Open Source来说那是相当诱人的,有了调用图,对程序的运行框架也就有了一个大体了解,知道了程序的“骨架“,分析它也就不会再那么茫然,尤其是对自己不熟悉的代码和Open Source。费话不多说了,让我们开始我们的分析之旅吧!

Gprof 实现原理:

通过在编译和链接你的程序的时候(使用 -pg 编译和链接选项),gcc 在你应用程序的每个函数中都加入了一个名为mcount ( or “_mcount” , or “__mcount” , 依赖于编译器或操作系统)的函数,也就是说你的应用程序里的每一个函数都会调用mcount, 而mcount 会在内存中保存一张函数调用图,并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间,调用次数等等的所有信息。

Gprof基本用法:

1. 使用 -pg 编译和链接你的应用程序。

2. 执行你的应用程序使之生成供gprof 分析的数据。

3. 使用gprof 程序分析你的应用程序生成的数据。

Gprof 简单使用:

让我们简单的举个例子来看看Gprof是如何使用的。

1.打开linux终端。新建一个test.c文件,并生用-pg 编译和链接该文件。 test.c 文件内容如下:

 

#include "stdio.h"

#include "stdlib.h"

void a(){

  printf("\t\t+---call a() function\n");

}

void c(){

  printf("\t\t+---call c() function\n");

}

int b(){

printf("\t+--- call b() function\n");

a();

c();

return 0;

}

int main(){

printf(" main() function()\n");

b();

}



命令行里面输入下面命令,没加-c选项,gcc 会默认进行编译并链接生成a.out:

[linux /home/test]$gcc -pg test.c



如果没有编译错误,gcc会在当前目录下生成一个a.out文件,当然你也可以使用 –o 选项给生成的文件起一个别的名字,像 gcc –pg test.c –o test , 则gcc会生成一个名为test的可执行文件,在命令行下输入[linux /home/test]$./test , 就可以执行该程序了,记住一定要加上 ./ 否则程序看上去可能是执行,可是什么输出都没有。

 

2.执行你的应用程序使之生成供gprof 分析的数据。 命令行里面输入:

 

[linux /home/test]$a.out

main() function()

+--- call b() function

+---call a() function

+---call c() function

[linux /home/test]$

你会在当前目录下看到一个gmon.out 文件, 这个文件就是供gprof 分析使用的。

 

3.使用gprof 程序分析你的应用程序生成的数据。

命令行里面输入:

 

[linux /home/test]$ gprof -b a.out gmon.out | less

由于gprof输出的信息比较多,这里使用了 less 命令,该命令可以让我们通过上下方向建查看gprof产生的输出,| 表示gprof -b a.out gmon.out 的输出作为 less的输入。下面是我从gprof输出中摘抄出的与我们有关的一些详细信息。


				

% cumulative self self total

time seconds seconds calls Ts/call Ts/call name

0.00 0.00 0.00 1 0.00 0.00 a

0.00 0.00 0.00 1 0.00 0.00 b

0.00 0.00 0.00 1 0.00 0.00 c

Call graph

granularity: each sample hit covers 4 byte(s) no time propagated

index % time self children called name

0.00 0.00 1/1 b [2]

[1] 0.0 0.00 0.00 1 a [1]

-----------------------------------------------

0.00 0.00 1/1 main [10]

[2] 0.0 0.00 0.00 1 b [2]

0.00 0.00 1/1 a [1]

0.00 0.00 1/1 c [3]

-----------------------------------------------

0.00 0.00 1/1 b [2]

[3] 0.0 0.00 0.00 1 c [3]

 

从上面的输出我们能明显的看出来,main 调用了 b 函数, 而b 函数分别调用了a 和 c 函数。由于我们的函数只是简单的输出了一个字串,故每个函数的消耗时间都是0 秒。

gprof产生的信息解释如下:

 

 

使用Gnu gprof进行Linux平台下的程序分析(图一)
gprof产生的信息解释

 

常用的Gprof 命令选项解释:

-b不再输出统计图表中每个字段的详细描述。

-p 只输出函数的调用图(Call graph 的那部分信息)。

-q 只输出函数的时间消耗列表。

-E Name不再输出函数Name 及其子函数的调用图,此标志类似于 -e 标志,但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。

-e Name 不再输出函数Name 及其子函数的调用图(除非它们有未被限制的其它父函数)。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。

-F Name 输出函数Name 及其子函数的调用图,它类似于 -f 标志,但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。

-f Name输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。

-z 显示使用次数为零的例程(按照调用计数和累积时间计算)。

到这为止你可能对gprof 有了一个比较感性的认识了,你可能会问如何用它去分析一个真正的Open Source 呢!下面就让我们去用gprof去分析一个Open Source,看看如何去在真实的环境中使用它。

使用Gprof 分析 Cflow开源项目

CFlow 是程序流程分析工具,该工具可以通过分析C源代码,产生程序调用图!有点跟Gprof差不多,不过CFlow是通过源代码进行的静态分析并且 不能分析C++ 程序,你可以到http://www.gnu.org/software/cflow/去下载源代码。

假设你已经下载了该源代码(cflow-1.1.tar.gz),并把它放置在/home目录下,让我们看看如何在这个应用上使用gprof。

1. 使用 -pg 编译和链接该应用程序,请输入下列命令。

 

  [linux /home/]tar zxvf cflow-1.1.tar.gz

[linux /home/cflow-1.1/src]$./configure

[linux /home]$make CFLAGS=-pg LDFLAGS=-pg 

如果没有出错你会在/home/cflow-1.1/src 目录下发行一个名为cflow的可执行文件,这就是我们加入-pg编译选项后编译出来的可以产生供gprof提取信息的可执行文件。记住一定要在编译和链接的时候都使用-pg选项,否则可能不会产生gmon.out文件。对于cflow项目,CFLAGS=-pg 是设置它的编译选项,LDFLAGS=-pg是设置它的链接选项。当然你也可以直接修改它的Makefile来达到上述相同的目的,不过一定要记住编译和链接都要使用-pg选项。

 

2. 运行cflow 程序使之生成gmon.out 文件供gprof使用。

 

[linux /home/cflow-1.1/src]$cflow parser.c

查看/home/cflow-1.1/src目录下有没有产生gmon.out文件,如果没有请重复第一步,并确认你已经在编译和链接程序的时候使用了-pg 选项。Cflow的使用请参考http://www.gnu.org/software/cflow/manual/cflow.html。

 

3. 使用gprof分析程序

[linux /home/cflow-1.1/src]$gprof -b cflow gmon.out | less

恭喜你,不出意外你会在屏幕上看到gprof的输出,函数消耗时间和函数调用图,下面是我从我的输出中摘抄出来的一小段。

 


				

% cumulative self self total

time seconds seconds calls Ts/call Ts/call name

0.00 0.00 0.00 118262 0.00 0.00 include_symbol

0.00 0.00 0.00 92896 0.00 0.00 is_printable

0.00 0.00 0.00 28704 0.00 0.00 set_level_mark

0.00 0.00 0.00 28703 0.00 0.00 is_last

0.00 0.00 0.00 19615 0.00 0.00 auto_processor

0.00 0.00 0.00 15494 0.00 0.00 gnu_output_handler

0.00 0.00 0.00 12286 0.00 0.00 delete_parm_processor

0.00 0.00 0.00 7728 0.00 0.00 newline

0.00 0.00 0.00 7728 0.00 0.00 print_function_name

0.00 0.00 0.00 7728 0.00 0.00 print_level

。。。。。。

。。。。。。

Call graph

granularity: each sample hit covers 4 byte(s) no time propagated

index % time self children called name

[1] 0.0 0.00 0.00 79+855 [1]

0.00 0.00 166 dcl [52]

0.00 0.00 163 parse_dcl [53]

0.00 0.00 150 dirdcl [56]

0.00 0.00 129 parse_declaration [63]

0.00 0.00 98 parse_variable_declaration [66]

0.00 0.00 63 maybe_parm_list [69]

0.00 0.00 63 parse_function_declaration [70]

0.00 0.00 39 func_body [74]

。。。。。。

。。。。。。

 

通过分析%time你就知道了那个函数消耗的时间最多,你可以根据这个输出信息做有目的的优化,不过cflow执行的速度是在是太快了,以至%time都是0 (消耗时间是以秒为单位进行统计的)。

生成图形化的函数调用图

1.Graphviz 工具

看到这里你也可能觉得上面的函数调用图实在是不方便察看,也看不出来一个程序调用的整体框架。没有关系,我再介绍一个有用的工具给你,使用 Graphviz,Graphviz or Graph Visualization 是由 AT&T 开发的一个开源的图形可视化工具。它提供了多种画图能力,但是我们重点关注的是它使用 Dot 语言直连图的能力。在这里,将简单介绍如何使用 Dot 来创建一个图形,并展示如何将分析数据转换成 Graphviz 可以使用的规范, Dot 使用的图形规范。

使用 Dot 语言,你可以指定三种对象:图、节点和边。为了让你理解这些对象的含义,我将构建一个例子来展示这些元素的用法。

下图给出了一个简单的定向图(directed graph),其中包含 3 个节点。第一行声明这个图为 G,并且声明了该图的类型(digraph)。接下来的三行代码用于创建该图的节点,这些节点分别名为 node1、node2 和 node3。节点是在它们的名字出现在图规范中时创建的。边是在在两个节点使用边操作(->)连接在一起时创建的,如第 6 行到第 8 行所示。我还对边使用了一个可选的属性 label,用它来表示边在图中的名称。最后,在第 9 行完成对该图规范的定义。

使用 Dot 符号表示的示例图(test.dot)

 

 1: digraph G {

2:   node1;

3:   node2;

4:   node3;

5:

6:   node1 -> node2 [label="edge_1_2"];

7:   node1 -> node3 [label="edge_1_3"];

8:   node2 -> node3 [label="edge_2_3"];

9: }

要将这个 .dot 文件转换成一个图形映像,则需要使用 Dot 工具,这个工具是在 Graphviz 包中提供的。清单 6 介绍了这种转换。

清单 6. 使用 Dot 来创建 JPG 映像

[linux /home]$ dot -Tjpg test.dot -o test.jpg

在这段代码中,我告诉 Dot 使用 test.dot 图形规范,并生成一个 JPG 图像,将其保存在文件 test.jpg 中。所生成的图像如图1所示。在此处,我使用了 JPG 格式,但是 Dot 工具也可以支持其他格式,其中包括 GIF、PNG 和 postscript等等。

 

使用Gnu gprof进行Linux平台下的程序分析(图二)
图 1. Dot 创建的示例图



Dot 语言还可以支持其他一些选项,包括外形、颜色和很多属性。有兴趣可以查看graphviz相关文档。

2.从gprof的输出中提取调用图信息,产生可供Graphviz使用的dot文件。

这样的脚本有人已经实现了,我们只要下载一个现成的就可以了,首先从http://www.ioplex.com/~miallen/ 网站下载一个mkgraph脚本。解压该脚本到包含gmon.out文件的目录下。使用mkgraph0.sh产生调用的jpg图像文件。例如:使用上面的例子,生成cflow的调用图。

[linux /home/cflow-1.1/src]$ mkgraph0.sh cflow gmon.out

部分调用图如下,有了这个图是不是对程序整体框架有了个清晰地了解,如果你对生成的调用图效果不满意,你还可以通过修改mkgraph0脚本使之产生合适的dot文件即可:

 

 

 

使用Gnu gprof进行Linux平台下的程序分析(图三)
部分调用图如下



总结:

使用gprof , Graphviz , mkgraph 生成函数调用图

1. 使用 -pg 编译和链接你的应用程序。

2. 执行你的应用程序使之生成供gprof 分析的数据。

3. 使用mkgraph脚本生成图形化的函数调用图。

 

相关资料:

文档:用 Graphviz 可视化函数调用

文档:Speed your code with the GNU profiler

文档:gropf 帮助文件

Mkgraph 脚本:http://www.ioplex.com/~miallen/

Graphviz 工具:http://www.graphviz.org

Cflow :http://www.gnu.org/software/cflow/

zz: linux环境下 C++性能测试工具 gprof 和gprof2dot

linux环境下 C++性能测试工具 gprof 和gprof2dot

http://www.4ucode.com/Study/Topic/1909519

http://coolaj86.info/articles/super-simple-gprof.html

http://sam.zoy.org/writings/programming/gprof.html

http://www.cs.utah.edu/dept/old/texinfo/as/gprof.html

 

1 简介

改进应用程序的性能是一项非常耗时耗力的工作,但是究竟程序中是哪些函数消耗掉了大部分执行时间,这通常都不是非常明显的。GNU 编译器工具包所提供了一种剖析工具 GNU profiler(gprof)。gprof 可以为 Linux平台上的程序精确分析性能瓶颈。gprof精确地给出函数被调用的时间和次数,给出函数调用关系。

 

gprof 用户手册网站 http://sourceware.org/binutils/docs-2.17/gprof/index.html

 

2 功能

Gprof GNU gnu binutils工具之一,默认情况下linux系统当中都带有这个工具。

1. 可以显示“flat profile”,包括每个函数的调用次数,每个函数消耗的处理器时间,

2. 可以显示“Call graph”,包括函数的调用关系,每个函数调用花费了多少时间。

3. 可以显示“注释的源代码”--是程序源代码的一个复本,标记有程序中每行代码的执行次数。

 

3 原理

通过在编译和链接程序的时候(使用 -pg 编译和链接选项),gcc 在你应用程序的每个函数中都加入了一个名为mcount ( or “_mcount” , or “__mcount” , 依赖于编译器或操作系统)的函数,也就是说你的应用程序里的每一个函数都会调用mcount, 而mcount 会在内存中保存一张函数调用图,并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间,调用次数等等的所有信息。

 

4 使用流程

1. 在编译和链接时 加上-pg选项。一般我们可以加在 makefile 中。

2. 执行编译的二进制程序。执行参数和方式同以前。

3. 在程序运行目录下 生成 gmon.out 文件。如果原来有gmon.out 文件,将会被重写。

4. 结束进程。这时 gmon.out 会再次被刷新。

5. 用 gprof 工具分析 gmon.out 文件。

 

5 参数说明

l -b 不再输出统计图表中每个字段的详细描述。

l -p 只输出函数的调用图(Call graph的那部分信息)。

l -q 只输出函数的时间消耗列表。

l -e Name 不再输出函数Name 及其子函数的调用图(除非它们有未被限制的其它父函数)。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。

l -E Name 不再输出函数Name 及其子函数的调用图,此标志类似于 -e 标志,但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。

l -f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。

l -F Name 输出函数Name 及其子函数的调用图,它类似于 -f 标志,但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。

l -z 显示使用次数为零的例程(按照调用计数和累积时间计算)。

 

一般用法: gprof b 二进制程序 gmon.out >report.txt

 

6 报告说明

Gprof 产生的信息解释:

%time

Cumulative

seconds

Self

Seconds

Calls

Self

TS/call

Total

TS/call

name

该函数消耗时间占程序所有时间百分比

程序的累积执行时间

(只是包括gprof能够监控到的函数)

该函数本身执行时间

所有被调用次数的合共时间

函数被调用次数

函数平均执行时间

(不包括被调用时间)

函数的单次执行时间

函数平均执行时间

(包括被调用时间)

 

函数的单次执行时间

函数名

 

Call Graph 的字段含义:

Index

%time

Self

Children

Called

Name

索引值

函数消耗时间占所有时间百分比

函数本身执行时间

执行子函数所用时间

被调用次数

函数名

 

注意:

程序的累积执行时间只是包括gprof能够监控到的函数。工作在内核态的函数和没有加-pg编译的第三方库函数是无法被gprof能够监控到的,(如sleep()等)

Gprof 的具体参数可以 通过 man gprof 查询。

 

7 共享库的支持

对于代码剖析的支持是由编译器增加的,因此如果希望从共享库中获得剖析信息,就需要使用 -pg 来编译这些库提供已经启用代码剖析支持而编译的 C 库版本(libc_p.a)。

如果需要分析系统函数(如libc库),可以用 lc_p替换-lc。这样程序会链接libc_p.so或libc_p.a。这非常重要,因为只有这样才能监控到底层的c库函数的执行时间,(例如memcpy(),memset(),sprintf()等)。

gcc example1.c –pg -lc_p -o example1

注意要用ldd ./example | grep libc来查看程序链接的是libc.so还是libc_p.so

 

8 用户时间与内核时间

gprof 的最大缺陷:它只能分析应用程序在运行过程中所消耗掉的用户时间,无法得到程序内核空间的运行时间。通常来说,应用程序在运行时既要花费一些时间来运行用户代码,也要花费一些时间来运行 “系统代码”,例如内核系统调用sleep()。

有一个方法可以查看应用程序的运行时间组成,在 time 命令下面执行程序。这个命令会显示一个应用程序的实际运行时间、用户空间运行时间、内核空间运行时间

time ./program

输出:

real 2m30.295s

user 0m0.000s

sys 0m0.004s

 

9 注意事项

1. g++在编译和链接两个过程,都要使用-pg选项。

2. 只能使用静态连接libc库,否则在初始化*.so之前就调用profile代码会引起“segmentation fault,解决办法是编译时加上-static-libgcc或-static。

3. 如果不用g++而使用ld直接链接程序,要加上链接文件/lib/gcrt0.o,如ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p。也可能是gcrt1.o

4. 要监控到第三方库函数的执行时间,第三方库也必须是添加 pg 选项编译的。

5. gprof只能分析应用程序所消耗掉的用户时间.

6. 程序不能以demon方式运行。否则采集不到时间。(可采集到调用次数)

7. 首先使用 time 来运行程序从而判断 gprof 是否能产生有用信息是个好方法。

8. 如果 gprof 不适合您的剖析需要,那么还有其他一些工具可以克服 gprof 部分缺陷,包括 OProfile 和 Sysprof。

9. gprof对于代码大部分是用户空间的CPU密集型的程序用处明显。对于大部分时间运行在内核空间或者由于外部因素(例如操作系统的 I/O 子系统过载)而运行得非常慢的程序难以进行优化。

10. gprof 不支持多线程应用,多线程下只能采集主线程性能数据。原因是gprof采用ITIMER_PROF信号,在多线程内只有主线程才能响应该信号。但是有一个简单的方法可以解决这一问题:http://sam.zoy.org/writings/programming/gprof.html

11. gprof只能在程序正常结束退出之后才能生成报告(gmon.out)。

a) 原因: gprof通过在atexit()里注册了一个函数来产生结果信息,任何非正常退出都不会执行atexit()的动作,所以不会产生gmon.out文件。

b) 程序可从main函数中正常退出,或者通过系统调用exit()函数退出。

 

 

10 多线程应用

gprof 不支持多线程应用,多线程下只能采集主线程性能数据。原因是gprof采用ITIMER_PROF信号,在多线程内只有主线程才能响应该信号。

采用什么方法才能够分析所有线程呢?关键是能够让各个线程都响应ITIMER_PROF信号。可以通过桩子函数来实现,重写pthread_create函数

 

//////////////////// gprof-helper.c////////////////////////////

#define _GNU_SOURCE

#include <sys/time.h>

#include <stdio.h>

#include <stdlib.h>

#include <dlfcn.h>

#include <pthread.h>

 

static void * wrapper_routine(void *);

 

/* Original pthread function */

static int (*pthread_create_orig)(pthread_t *__restrict,

__const pthread_attr_t *__restrict,

void *(*)(void *),

void *__restrict) = NULL;

 

/* Library initialization function */

void wooinit(void) __attribute__((constructor));

 

void wooinit(void)

{

pthread_create_orig = dlsym(RTLD_NEXT, "pthread_create");

fprintf(stderr, "pthreads: using profiling hooks for gprof\n");

if(pthread_create_orig == NULL)

{

char *error = dlerror();

if(error == NULL)

{

error = "pthread_create is NULL";

}

fprintf(stderr, "%s\n", error);

exit(EXIT_FAILURE);

}

}

 

/* Our data structure passed to the wrapper */

typedef struct wrapper_s

{

void * (*start_routine)(void *);

void * arg;

pthread_mutex_t lock;

pthread_cond_t wait;

struct itimerval itimer;

} wrapper_t;

 

/* The wrapper function in charge for setting the itimer value */

static void * wrapper_routine(void * data)

{

/* Put user data in thread-local variables */

void * (*start_routine)(void *) = ((wrapper_t*)data)->;start_routine;

void * arg = ((wrapper_t*)data)->;arg;

 

/* Set the profile timer value */

setitimer(ITIMER_PROF, &((wrapper_t*)data)->;itimer, NULL);

 

/* Tell the calling thread that we don't need its data anymore */

pthread_mutex_lock(&((wrapper_t*)data)->;lock);

pthread_cond_signal(&((wrapper_t*)data)->;wait);

pthread_mutex_unlock(&((wrapper_t*)data)->;lock);

 

/* Call the real function */

return start_routine(arg);

}

 

/* Our wrapper function for the real pthread_create() */

int pthread_create(pthread_t *__restrict thread,

__const pthread_attr_t *__restrict attr,

void * (*start_routine)(void *),

void *__restrict arg)

{

wrapper_t wrapper_data;

int i_return;

 

/* Initialize the wrapper structure */

wrapper_data.start_routine = start_routine;

wrapper_data.arg = arg;

getitimer(ITIMER_PROF, &wrapper_data.itimer);

pthread_cond_init(&wrapper_data.wait, NULL);

pthread_mutex_init(&wrapper_data.lock, NULL);

pthread_mutex_lock(&wrapper_data.lock);

 

/* The real pthread_create call */

i_return = pthread_create_orig(thread,

attr,

&wrapper_routine,

&wrapper_data);

 

/* If the thread was successfully spawned, wait for the data

* to be released */

if(i_return == 0)

{

pthread_cond_wait(&wrapper_data.wait, &wrapper_data.lock);

}

 

pthread_mutex_unlock(&wrapper_data.lock);

pthread_mutex_destroy(&wrapper_data.lock);

pthread_cond_destroy(&wrapper_data.wait);

 

return i_return;

}

 

///////////////////

然后编译成动态库 gcc -shared -fPIC gprof-helper.c -o gprof-helper.so -lpthread -ldl

 

使用例子:

/////////////////////a.c/////////////////////////////

#include <stdio.h>;

#include <stdlib.h>;

#include <unistd.h>;

#include <pthread.h>;

#include <string.h>;

void fun1();

void fun2();

void* fun(void * argv);

int main()

{

int i =0;

int id;

pthread_t thread[100];

for(i =0 ;i< 100; i++)

{

id = pthread_create(&thread[i], NULL, fun, NULL);

printf("thread =%d\n",i);

}

printf("dsfsd\n");

return 0;

}

void* fun(void * argv)

{

fun1();

fun2();

return NULL;

}

 

void fun1()

{

int i = 0;

while(i<100)

{

i++;

printf("fun1\n");

}

}

 

void fun2()

{

int i = 0;

int b;

while(i<50)

{

i++;

printf("fun2\n");

//b+=i;

}

}

///////////////

 

gcc -pg a.c gprof-helper.so

 

运行程序:

./a.out

 

分析gmon.out:

gprof -b a.out gmon.out

 

 

 

利用 gprof2dot 和graphviz 图形化定位linux c/c++系统性能瓶颈

http://www.cnblogs.com/rocketfan/archive/2009/11/15/1603465.html

http://www.51testing.com/?uid-13997-action-viewspace-itemid-79952

 

gprof 使用说明 zz

一. 概要
1. Gprof 是在运行中收集程序的统计信息。
程序的运行方式会严重影响统计的信息结果。因为不同的执行路径下,程序的行为方式会有很大的差别。

2. Gprof 使用步骤
(1) 编译链接程序的时候,使能Gprof
(2) 执行程序生成profile data file
(3) 使用Gprof分析profile data

3. 输出格式
(1) flat profile
每一个函数花费了多少时间,每一个函数被调用了多少次
(2) call graph
对每一个函数来说,哪个函数调用了它,多少次;它调用了哪些个函数,多少次
这个函数花费了多少时间,它调用的函数花费了多少时间
(3) annotated source
生成一份源代码的拷贝,标注出每一个block被执行了多少次

二. 为 Gprof 编译程序
1. 给GNU Tools 传递PG选项
gcc -g -pg .............
编译器和连接器都需要加上-pg 选项
2. 执行程序
程序执行结束后,会生成gmon.out 统计文件,这个就是profiler data file。
注意:只有在程序正常终止的时候,才会生成这个文件。也就是说,程序必须是从exit或者return终止的。
3. 分析生成结果
gprof [Options] <可执行文件> <profiler data file>

三. Gprof 的输出格式
G平日哦方可生成四种格式的统计结果,其中的line-by-line的输出,已经转移到gconv工具上。
所以目前的Gprof主要是三种格式的输出。

1. Flat Profile:

 

  1. % the percentage of the total running time of the
  2. time program used by this function.(在整个程序运行时间中,
  3. 这个函数运行时间所占的百分比)
  4.  
  5. cumulative a running sum of the number of seconds accounted
  6. seconds for by this function and those listed above it.
  7. (这个函数和列在它之前的函数,以秒为单位运行时间的总和)
  8.  
  9. self the number of seconds accounted for by this
  10. seconds function alone. This is the major sort for this
  11. listing.(这个函数自身运行时间的总和,以秒为单位)
  12.  
  13. calls the number of times this function was invoked, if
  14. this function is profiled, else blank.(这个函数
  15. 被调用的总次数)
  16.  
  17. self the average number of milliseconds spent in this
  18. ms/call function per call, if this function is profiled,
  19. else blank.(这个函数每次被调用的平均时间,以毫秒为单位)
  20.  
  21. total the average number of milliseconds spent in this
  22. ms/call function and its descendents per call, if this
  23. function is profiled, else blank.(这个函数和在它内部调用的
  24. 函数,每次被调用的平均运行时间)
  25.  
  26. name the name of the function. This is the minor sort
  27. for this listing. The index shows the location of
  28. the function in the gprof listing. If the index is
  29. in parenthesis it shows where it would appear in
  30. the gprof listing if it were to be printed.


2. Call Graph
granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds

index % time self children called name
<spontaneous>
[1] 100.0 0.00 0.05 start [1]
0.00 0.05 1/1 main [2]
0.00 0.00 1/2 on_exit [28]
0.00 0.00 1/1 exit [59]
-----------------------------------------------
0.00 0.05 1/1 start [1]
[2] 100.0 0.00 0.05 1 main [2]
0.00 0.05 1/1 report [3]
-----------------------------------------------
0.00 0.05 1/1 main [2]
[3] 100.0 0.00 0.05 1 report [3]
0.00 0.03 8/8 timelocal [6]
0.00 0.01 1/1 print [9]
0.00 0.01 9/9 fgets [12]
0.00 0.00 12/34 strncmp <cycle 1> [40]
0.00 0.00 8/8 lookup [20]
0.00 0.00 1/1 fopen [21]
0.00 0.00 8/8 chewtime [24]
0.00 0.00 8/16 skipspace [44]
-----------------------------------------------
[4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
0.01 0.02 244+260 offtime <cycle 2> [7]
0.00 0.00 236+1 tzset <cycle 2> [26]
-----------------------------------------------


虚线分割的每一个部分叫做一个entity,用来描述一个函数或者一个cycle。
其中每一个以 [数字] 开始的行叫做 primary line,这个entity主要就是描述它的。
在 primary line 之前的行显示的是调用这个函数的函数,也就是caller。在它之后
的是这个函数调用的函数,也就是subroutine。

2.1 Primary Line

index % time self children called name
...
[3] 100.0 0.00 0.05 1 report [3]

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 

  1. index
  2. Entries are numbered with consecutive integers. Each function therefore has an index number, which appears at the beginning of its primary line.
  3.  
  4. Each cross-reference to a function, as a caller or subroutine of another, gives its index number as well as its name. The index number guides you if you wish to look for the entry for that function.
  5.  
  6. % time
  7. This is the percentage of the total time that was spent in this function, including time spent in subroutines called from this function.(花费在这个函数中的时间在整个程序全部运行时间中的百分比,其中包括花费在这个函数调用的子函数中的时间)
  8.  
  9. The time spent in this function is counted again for the callers of this function. Therefore, adding up these percentages is meaningless.(在这个函数的调用函数caller中,这个函数的运行时间,还会被计算在内,所以将这些百分数加在一起没有意义)
  10.  
  11. self
  12. This is the total amount of time spent in this function. This should be identical to the number printed in the seconds field for this function in the flat profile.(这个函数自身花费的时间。这个数应该和Flat Profile中的记录一样)
  13.  
  14. children
  15. This is the total amount of time spent in the subroutine calls made by this function. This should be equal to the sum of all the self and children entries of the children listed directly below this function. (花费在这个函数调用的所有函数的总时间。这个数应该和列在这个函数下面的子函数的全部 self 和 children之和相等)
  16. called This is the number of times the function was called.(这个函数被调用的次数)
  17.  
  18. If the function called itself recursively, there are two numbers, separated by a `+'. The first number counts non-recursive calls, and the second counts recursive calls.(如果这个函数被循环调用,这里就会有两个被“+”分隔的数字,第一个数字表示非递归调用的次数,第二个表示递归调用的次数)
  19.  
  20. In the example above, the function report was called once from main.
  21.  
  22. name
  23. This is the name of the current function. The index number is repeated after it.
  24.  
  25. If the function is part of a cycle of recursion, the cycle number is printed between the function's name and the index number . For example, if function gnurr is part of cycle number one, and has index number twelve, its primary line would be end like this:
  26.  
  27. gnurr <cycle 1> [12]
  28. 如果这个函数是一个循环递归的一部分,循环编号将会打印在函数名和函数索引号之间。例如:如果函数gnurr是循环一的一部分,并且它的索引号是12,它的primary line就应该如下:
  29. gnurr <cycle 1> [12]



2.2 Lines for a function's caller

index % time self children called name
...
0.00 0.05 1/1 main [2]
[3] 100.0 0.00 0.05 1 report [3]
 

  1. self
  2. An estimate of the amount of time spent in report itself when it was called from main.
  3. (report自己花费的时间)
  4.  
  5. children
  6. An estimate of the amount of time spent in subroutines of report when report was called from main.
  7. (report的子函数花费的总时间)
  8.  
  9. The sum of the self and children fields is an estimate of the amount of time spent within calls to
  10. report from main.
  11.  
  12. called
  13. Two numbers: the number of times report was called from main, followed by the total number of
  14. nonrecursive calls to report from all its callers.(两个数字:第一个,从main函数中调用report的次数,
  15. 第二个,report被非递归形式调用的总次数)
  16.  
  17. name and index number
  18. The name of the caller of report to which this line applies, followed by the caller's index number.
  19.  
  20. Not all functions have entries in the call graph; some options to gprof request the omission of certain
  21. functions. When a caller has no entry of its own, it still has caller-lines in the entries of the
  22. functions it calls.(不是所有的函数在call graph中都有entity)
  23.  
  24. If the caller is part of a recursion cycle, the cycle number is printed between the name and the index
  25. number.(如果caller是一个递归循环的一部分,循环编号会打印在caller的名字和编号之间)

如果caller不能确定,就会出现<spontaneous>作为caller。

gprof 看看gobject的效率,API调用。

http://www.ezdoum.com/stories.php?story=07/10/10/5189338

 

1. 重新编译glib

CFLAGS="-pg -g" ./autogen.sh --disable-gtk-doc --enable-debug=minimum \
     --prefix=/your install path --disable-shared

make; make install

2. 写个测试代码

#define REPEATS 100000

#include <glib.h>
#include <glib-object.h>

/*************************/

#define TYPE_TEST_OBJECT    (test_object_get_type ())
#define TEST_OBJECT(obj)    (G_TYPE_CHECK_INSTANCE_CAST ((obj), \
                             TYPE_TEST_OBJECT, TestObject))
#define IS_TEST_OBJECT(obj) (G_TYPE_CHECK_INSTANCE_TYPE ((obj), \
                             TYPE_TEST_OBJECT))

typedef struct _TestObject       TestObject;
typedef struct _TestObjectClass  TestObjectClass;

struct _TestObject
{
    GObject    parent_instance;

    gint       foo;
    gchar     *bar;
};

struct _TestObjectClass
{
    GObjectClass parent_class;
};

GType        test_object_get_type     (void) G_GNUC_CONST;
TestObject  *test_object_new          (void);

enum
{
    PROP_0,
    PROP_FOO,
    PROP_BAR
};

static void   test_object_class_init   (TestObjectClass *klass);
static void   test_object_init         (TestObject      *object);
static void   test_object_finalize     (GObject         *object);
static void   test_object_set_property (GObject         *object,
				        guint            property_id,
					const GValue    *value,
					GParamSpec      *pspec);
static void   test_object_get_property (GObject         *object,
                                        guint            property_id,
                                        GValue          *value,
                                        GParamSpec      *pspec);


static GObjectClass *parent_class = NULL;


GType
test_object_get_type (void)
{
  static GType test_object_type = 0;

  if (!test_object_type)
    {
      static const GTypeInfo test_object_info =
      {
        sizeof (TestObjectClass),
	(GBaseInitFunc) NULL,
	(GBaseFinalizeFunc) NULL,
	(GClassInitFunc) test_object_class_init,
	NULL,		/* class_finalize */
	NULL,		/* class_data     */
	sizeof (TestObject),
	0,              /* n_preallocs    */
	(GInstanceInitFunc) test_object_init,
      };

      test_object_type =
	g_type_register_static (G_TYPE_OBJECT, "TestObject",
				&test_object_info, 0);
    }

  return test_object_type;
}


static void
test_object_class_init (TestObjectClass *klass)
{
  GObjectClass *object_class;
  GParamSpec   *param_spec;

  object_class = G_OBJECT_CLASS (klass);
  parent_class = g_type_class_peek_parent (klass);

  object_class->set_property = test_object_set_property;
  object_class->get_property = test_object_get_property;

  param_spec = g_param_spec_string ("bar", NULL, NULL,
				    NULL,
				    G_PARAM_READABLE | G_PARAM_WRITABLE
#ifdef MAKE_IT_SLOW_2
                                    | G_PARAM_CONSTRUCT_ONLY
#endif
                                    );
  g_object_class_install_property (object_class, PROP_BAR, param_spec);

  param_spec = g_param_spec_int ("foo", NULL, NULL,
				 G_MININT, G_MAXINT, 0,
				 G_PARAM_READABLE | G_PARAM_WRITABLE
#ifdef MAKE_IT_SLOW_2
                                    | G_PARAM_CONSTRUCT_ONLY
#endif
                                 );
  g_object_class_install_property (object_class, PROP_FOO, param_spec);

  object_class->finalize = test_object_finalize;
}

static void
test_object_init (TestObject *object)
{
  object->bar = NULL;
  object->foo = 0;
}

static void
test_object_finalize (GObject *object)
{
  TestObject *obj;

  obj = (TestObject *) (object);

  g_free (obj->bar);

  if (G_OBJECT_CLASS (parent_class)->finalize)
    G_OBJECT_CLASS (parent_class)->finalize (object);
}

static void
test_object_set_property (GObject      *object,
			  guint         property_id,
			  const GValue *value,
			  GParamSpec   *pspec)
{
  TestObject *test_object;

  test_object = TEST_OBJECT (object);

  switch (property_id)
    {
    case PROP_FOO:
      test_object->foo = g_value_get_int (value);
      break;

    case PROP_BAR:
      g_free (test_object->bar);
      test_object->bar = g_value_dup_string (value);
      break;

    default:
      G_OBJECT_WARN_INVALID_PROPERTY_ID (object, property_id, pspec);
      break;
    }
}

static void
test_object_get_property (GObject     *object,
			  guint        property_id,
			  GValue      *value,
			  GParamSpec  *pspec)
{
  TestObject *test_object;

  test_object = TEST_OBJECT (object);

  switch (property_id)
    {
    case PROP_BAR:
      g_value_set_string (value, test_object->bar);
      break;

    case PROP_FOO:
      g_value_set_int (value, test_object->foo);
      break;

    default:
      G_OBJECT_WARN_INVALID_PROPERTY_ID (object, property_id, pspec);
      break;
    }
}


TestObject *
test_object_new (void)
{
#ifdef MAKE_IT_SLOW_1
  return TEST_OBJECT (g_object_new (test_object_get_type (),
                                    "foo", 5,
                                    "bar", "blah",
                                    NULL));
#else
  TestObject *obj =
    TEST_OBJECT (g_object_new (test_object_get_type (),
                               NULL));
  obj->foo = 5;
  obj->bar = g_strdup ("blah");
  return obj;
#endif
}


/*************************/


int main (int argc, char *argv[])
{
  GTimeVal start, end;
  int i;
  TestObject *obj[REPEATS];

  g_type_init_with_debug_flags (G_TYPE_DEBUG_NONE);

  test_object_new ();

  g_get_current_time (&start);
  for (i = 0; i < REPEATS; i++)
    obj[i] = test_object_new ();
  g_get_current_time (&end);

  if (end.tv_usec - start.tv_usec < 0)
    end.tv_sec--, end.tv_usec += 1000000;
  g_print ("loop %d, %ld.%06ld sec\n", REPEATS,
           (end.tv_sec - start.tv_sec),
           (end.tv_usec - start.tv_usec));
  return 0;
}

3. 编译测试代码

Then try:
  gcc -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags --libs gobject-2.0` 
vs.
  gcc -DMAKE_IT_SLOW_1 -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags gobject-2.0` `pkg-config --libs gobject-2.0`
or
  gcc -DMAKE_IT_SLOW_2 -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags gobject-2.0` `pkg-config --libs gobject-2.0`

 

4. 用gprof看看:

gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
  0.00      0.00     0.00   200002     0.00     0.00  test_object_get_type
  0.00      0.00     0.00   100001     0.00     0.00  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) no time propagated

index % time    self  children    called     name
                0.00    0.00  200002/200002      test_object_new [2]
[1]      0.0    0.00    0.00  200002         test_object_get_type [1]
-----------------------------------------------
                0.00    0.00  100001/100001      main [8]
[2]      0.0    0.00    0.00  100001         test_object_new [2]
                0.00    0.00  200002/200002      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [1] test_object_get_type    [2] test_object_new

 

build again:

gcc -DMAKE_IT_SLOW_1 -Wall -pg -g gobject-test.c -o gobject-test `pkg-config --cflags --libs gobject-2.0`
gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ns/call  ns/call  name    
 50.12      0.01     0.01   400004    12.53    12.53  test_object_get_type
 50.12      0.01     0.01                             frame_dummy
  0.00      0.01     0.00   100001     0.00    25.06  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) for 99.77% of 0.01 seconds

index % time    self  children    called     name
                0.00    0.00  200002/400004      test_object_set_property [5]
                0.00    0.00  200002/400004      test_object_new [3]
[1]     50.0    0.01    0.00  400004         test_object_get_type [1]
-----------------------------------------------
                                                 <spontaneous>
[2]     50.0    0.01    0.00                 frame_dummy [2]
-----------------------------------------------
                0.00    0.00  100001/100001      main [4]
[3]     25.0    0.00    0.00  100001         test_object_new [3]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------
                                                 <spontaneous>
[4]     25.0    0.00    0.00                 main [4]
                0.00    0.00  100001/100001      test_object_new [3]
-----------------------------------------------
                                                 <spontaneous>
[5]     25.0    0.00    0.00                 test_object_set_property [5]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [2] frame_dummy             [1] test_object_get_type    [3] test_object_new

 

build again:

gcc -DMAKE_IT_SLOW_2 -Wall -pg -g gobject-test.c -o gobject-test `pkg-config --cflags --libs gobject-2.0`
gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
  0.00      0.00     0.00   400004     0.00     0.00  test_object_get_type
  0.00      0.00     0.00   100001     0.00     0.00  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) no time propagated

index % time    self  children    called     name
                0.00    0.00  200002/400004      test_object_set_property [14]
                0.00    0.00  200002/400004      test_object_new [2]
[1]      0.0    0.00    0.00  400004         test_object_get_type [1]
-----------------------------------------------
                0.00    0.00  100001/100001      main [8]
[2]      0.0    0.00    0.00  100001         test_object_new [2]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [1] test_object_get_type    [2] test_object_new