TL;DR: foo
为了获得分析事件又快又小,请再运行 100 次。频率设置有拼写错误,并且pprof
采样频率不会高于 CONFIG_HZ(通常为 250)。最好切换到更现代的 Linuxperf
分析器(作者的教程 https://perf.wiki.kernel.org/index.php/Tutorial, 维基百科 http://en.wikipedia.org/wiki/Perf_%28Linux%29).
长版:
Your foo
函数太短太简单了——只调用两个函数。编译测试g++ test.cc -lprofiler -o test.s -S -g
,过滤为test.s
with c++filt
使 C++ 名称可读的程序:
foo():
.LFB972:
.loc 1 27 0
pushq %rbp
movq %rsp, %rbp
.loc 1 28 0
movl $.LC0, %esi
movl std::cout, %edi
call std::basic_ostream<char, std::char_traits<char> >& std::operator<< <std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*)
movl std::basic_ostream<char, std::char_traits<char> >& std::endl<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&), %esi
movq %rax, %rdi
call std::basic_ostream<char, std::char_traits<char> >::operator<<(std::basic_ostream<char, std::char_traits<char> >& (*)(std::basic_ostream<char, std::char_traits<char> >&))
.loc 1 29 0
popq %rbp
ret
.LFE972:
.size foo(), .-foo()
因此,要在配置文件中查看它,您应该运行foo
更多次,改变int a = 1000;
主要是更大的东西,比如 10000 或更好的 100000(就像我在测试中所做的那样)。
您也可以修复不正确的“CPUPROFILE_FREQUENC=10000
“ 纠正CPUPROFILE_FREQUENCY
(注意Y
)。我应该说 CPUPROFILE_FREQUENCY 的 10000 设置太高,因为它通常每秒只能生成 1000 或 250 个事件,具体取决于内核配置CONFIG_HZ
(大多数 3.x 内核有 250 个,检查grep CONFIG_HZ= /boot/config*
)。 pprof 中 CPUPROFILE_FREQUENCY 的默认设置为 100。
我在 Ubuntu 14.04 上使用 bash 脚本测试了 CPUPROFILE_FREQUENCY 的不同值:100000、10000、1000、250
for a in 100000 100000 10000 10000 1000 1000 300 300 250 250; do
echo -n "$a ";
CPUPROFILE_FREQUENCY=$a CPUPROFILE=dump$a.txt ./test >/dev/null;
done
结果是相同的 120-140 个事件,每个 ./test 的运行时间约为 0.5 秒,因此来自 google-perftools 的 cpuprofiler 无法为单线程每秒执行比内核中设置的 CONFIG_HZ 更多的事件(我的有 250 个)。
100000 PROFILE: interrupts/evictions/bytes = 124/1/6584
100000 PROFILE: interrupts/evictions/bytes = 134/0/7864
10000 PROFILE: interrupts/evictions/bytes = 125/0/7488
10000 PROFILE: interrupts/evictions/bytes = 123/0/6960
1000 PROFILE: interrupts/evictions/bytes = 134/0/6264
1000 PROFILE: interrupts/evictions/bytes = 125/2/7272
300 PROFILE: interrupts/evictions/bytes = 137/2/7984
300 PROFILE: interrupts/evictions/bytes = 126/0/7216
250 PROFILE: interrupts/evictions/bytes = 123/3/6680
250 PROFILE: interrupts/evictions/bytes = 137/2/7352
原始a=1000foo
并且 cout 的函数运行得太快,无法在每次运行中获取任何分析事件(即使是 250 个事件/秒),因此您没有foo
,也没有任何输入/输出功能。在少量运行中,__write_nocancel
可能会得到采样事件,然后foo
将报告 libstdc++ 形式的 I/O 函数(不在最顶部的某个位置,因此使用--text
的选项pprof
or google-pprof
),自事件计数为零,子事件计数非零:
....
1 0.9% 99.1% 1 0.9% __write_nocancel
....
0 0.0% 100.0% 1 0.9% _IO_new_file_overflow
0 0.0% 100.0% 1 0.9% _IO_new_file_write
0 0.0% 100.0% 1 0.9% __GI__IO_putc
0 0.0% 100.0% 1 0.9% foo
0 0.0% 100.0% 1 0.9% new_do_write
0 0.0% 100.0% 1 0.9% std::endl
0 0.0% 100.0% 1 0.9% std::ostream::put
With a=100000
, foo 仍然太短太快,无法获取自己的事件,但 I/O 函数有几个。这是我长时间抓取的列表--text
output:
34 24.6% 24.6% 34 24.6% __write_nocancel
1 0.7% 95.7% 35 25.4% __GI__IO_fflush
1 0.7% 96.4% 1 0.7% __GI__IO_putc
1 0.7% 97.8% 2 1.4% std::operator<<
1 0.7% 98.6% 36 26.1% std::ostream::flush
1 0.7% 99.3% 2 1.4% std::ostream::put
0 0.0% 100.0% 34 24.6% _IO_new_file_sync
0 0.0% 100.0% 34 24.6% _IO_new_file_write
0 0.0% 100.0% 40 29.0% foo
0 0.0% 100.0% 34 24.6% new_do_write
0 0.0% 100.0% 2 1.4% std::endl
拥有零计数器的函数只能通过以下方式才能看到pprof
读取调用链的能力(如果不省略帧信息,它知道谁调用了获取样本的函数)。
我还可以推荐更现代、更强大(软件和硬件事件,高达 5 kHz 频率或更高;用户空间和内核分析)和更好支持的分析器,Linuxperf
分析器(作者的教程 https://perf.wiki.kernel.org/index.php/Tutorial, 维基百科 http://en.wikipedia.org/wiki/Perf_%28Linux%29).
有结果来自perf
with a=10000
:
$ perf record ./test3 >/dev/null
... skip some perf's spam about inaccessibility of kernel symbols
... note the 3 kHz frequency here VVVV
Lowering default frequency rate to 3250.
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate.
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.078 MB perf.data (~3386 samples) ]
查看文本报告perf.data
输出文件我会少用(因为perf report
默认情况下启动交互式配置文件浏览器):
$ perf report |less
... skip some extra info about the machine, kernel, and perf starting command
# Samples: 1K of event 'cycles'
# Event count (approx.): 1155264208
# Overhead Command Shared Object Symbol
41.94% test3 libm-2.19.so [.] __tan_sse2
16.95% test3 libm-2.19.so [.] __sin_sse2
13.40% test3 libm-2.19.so [.] __cos_sse2
4.93% test3 test3 [.] bar()
2.90% test3 libc-2.19.so [.] __GI___libc_write
....
0.20% test3 test3 [.] foo()
Or perf report -n | less
查看原始事件(示例)计数器:
# Overhead Samples Command Shared Object
41.94% 663 test3 libm-2.19.so [.] __tan_sse2
16.95% 268 test3 libm-2.19.so [.] __sin_sse2
13.40% 212 test3 libm-2.19.so [.] __cos_sse2
4.93% 78 test3 test3 [.] bar()
2.90% 62 test3 libc-2.19.so [.] __GI___libc_write
....
0.20% 4 test3 test3 [.] foo()