テキスト モードには、次のような出力行があります。
たとえば、収集プロファイルなど、多くの行があります。
$ CPUPROFILE=a.pprof LD_PRELOAD=./libprofiler.so ./a.out
プログラムa.out
は以下と同じです: Kcachegrind/callgrind is inaccurate for dispatcher functions?
次に、pproftop
コマンドで分析します。
$ pprof ./a.out a.pprof
Using local file ./a.out.
Using local file a.pprof.
Welcome to pprof! For help, type 'help'.
(pprof) top
Total: 185 samples
76 41.1% 41.1% 76 41.1% do_4
51 27.6% 68.6% 51 27.6% do_3
37 20.0% 88.6% 37 20.0% do_2
21 11.4% 100.0% 21 11.4% do_1
0 0.0% 100.0% 185 100.0% __libc_start_main
0 0.0% 100.0% 185 100.0% dispatcher
0 0.0% 100.0% 34 18.4% first2
0 0.0% 100.0% 42 22.7% inner2
0 0.0% 100.0% 68 36.8% last2
0 0.0% 100.0% 185 100.0% main
では、ここには何がありますか: 合計サンプル数は 185 です。Frequency はデフォルトです (10 ms ごとに 1 サンプル、または 1 秒あたり 100 サンプル)。その場合、合計実行時間は ~ 1.85 秒です。
最初の列は、a.out が特定の関数で機能するときに取得されたサンプルの数です。これを頻度で割ると、特定の関数の合計時間の見積もりが得られます。たとえばdo_4
、約 0.8 秒実行されます。
2 番目の列は、特定の関数のサンプル カウントを合計カウントで割った値、または合計プログラム実行時間におけるこの関数のパーセンテージです。これdo_4
は最も遅い関数 (合計プログラム時間の 41%) でありdo_1
、プログラム実行時間のわずか 11% です。あなたはこのコラムに興味を持っていると思います。
3 番目の列は、現在の行と前の行の合計です。do_4
したがって、最も遅い 2 つの関数がdo_3
合計実行時間の 68% (41%+27%) を占めていることがわかります。
4 列目と 5 列目は 1 列目と 2 列目と同様です。ただし、これらは、指定された関数自体のサンプルだけでなく、指定されたから呼び出されたすべての関数のサンプルも、直接的および間接的に説明します。main
そこから呼び出されたすべてが総実行時間の 100% であり (main
プログラム自体、またはプログラムの呼び出しツリーのルートであるため)、last2
その子は実行時間の 36.8% であることがわかります (私のプログラムの子は: の半分です)。への呼び出しとdo_4
呼び出しの半分do_3
= 41.1 + 27.6 /2 = 69.7/2 ~= 34% + 関数自体の一部の時間)
PS: 他にも便利な pprof コマンドがいくつかあります。たとえば、callgrind
またはgv
プロファイリング情報が追加されたコール ツリーのグラフィック表現が表示されます。