TL; DR:foo
は、プロファイリングイベントを取得するために高速で小さく、それを100回以上実行します。頻度設定はtypoで行われ、pprof
はCONFIG_HZ(通常は250)よりも頻繁にサンプリングされません。より現代的なLinux perf
プロファイラ(tutorial from its authors、wikipedia)に切り替える方が良いです。
ロングバージョン:
あなたfoo
機能はあまりにも短いと簡単です - ちょうど2つの関数を呼び出します。読み込み可能なC++の名前を作るためにc++filt
プログラムとtest.s
のフィルタリングと、g++ test.cc -lprofiler -o test.s -S -g
でテストをコンパイルした:
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
に注意してください)を修正することもできます。私は10000はCPUPROFILE_FREQUENCYの設定が高すぎると言います。通常、カーネル設定CONFIG_HZ
(ほとんどの3.xカーネルは250、チェックはgrep CONFIG_HZ= /boot/config*
)に応じて、毎秒1000または250イベントを生成する可能性があるからです。 pprofのCPUPROFILE_FREQUENCYのデフォルト設定は100です。
私は、Ubuntu 14で、CPUPROFILE_FREQUENCY:100000,10000,1000,250の異なる値をbashスクリプトでテストしました。04
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
そして、結果はすべての./test約0.5秒の同じ120〜140回のイベントやランタイムたので、グーグル-perftoolsからcpuprofilerは、単一のスレッドのために毎秒以上のイベントを行うことができない、CONFIG_HZセットよりカーネルでは(my has 250)。元A = 1000のfoo
とcoutのの機能を持つ
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
は、あなたが何foo
を持っていないので、すべての実行でそれらに任意のプロファイリングイベント(でも上の250のイベント/秒)を取得するにはあまりにも速く走る、また任意の入力/出力機能。少量の実行では、__write_nocancel
がサンプリングイベントを取得し、次にfoo
が発生し、libstdC++のI/O関数が報告されます(--text
オプションはpprof
またはgoogle-pprof
)。自己イベントカウントはゼロです。ゼロ以外の子イベントがカウント:a=100000
で
....
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
を、fooがまだ独自のイベントを取得するには短すぎると高速ですが、I/O機能がいくつか得ました。これは私が長い間--text
出力からgreppedリストです:コールチェーンを読み取るpprof
機能のみに感謝を見ゼロ自身のカウンターと
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
機能(フレーム情報が省略されていない場合には、サンプルを得た関数を呼び出す誰を知っています) 。
私はまた(、ソフトウェアとハードウェアの両方のイベント最大5 kHzの周波数以上;ユーザ空間とカーネルプロファイリングの両方)より有能な、より近代的なお勧めすることができ、より良いサポートプロファイラ、Linuxのperf
プロファイラ(tutorial from its authors、wikipediaを) 。
a=10000
とperf
からの結果があります。
$ 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 report
ため、デフォルトの開始対話型のプロファイルブラウザで)私はあまりを使用しますperf.data
出力ファイルからテキスト・レポートを表示するには:
$ 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()
は、または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()
あなたは "CPUPROFILE_FREQUENC = 10000"を試したと言いますが、それにはYがないので、実際の(そして無視される)場合は、小さなfooを表示するのに十分なサンプルがないかもしれません。 – mgkrebbs
あなたは壁掛け時間ではなく、CPU時間を見ています。 'foo'が使用するCPU時間はほとんどありません。 I/Oを実行するライブラリ関数を呼び出すだけで、I/O中にCPUサンプルは発生しません。 –