Текстовый режим имеет строки вывода, которые выглядят так:
В нем будет много строк, например, профиль сбора:
$ CPUPROFILE=a.pprof LD_PRELOAD=./libprofiler.so ./a.out
Программа a.out
такая же, как здесь: Kcachegrind / callgrind неточен для функций диспетчера?
Затем проанализируйте его с помощью команды pprof top
:
$ 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;и частота является значением по умолчанию (1 выборка каждые 10 мс; или 100 выборок в секунду).Тогда общее время выполнения составляет ~ 1,85 секунды.
Первый столбец - это количество выборок, которое было взято, когда a.out работает в данной функции.Если мы разделим его на частоту, мы получим оценку общего времени для данной функции, например, do_4
работает в течение ~ 0,8 сек
Второй столбец - это количество выборок в данной функции, деленное на общеесчитать или процент этой функции в общем времени выполнения программы .Так что do_4
- самая медленная функция (41% от общего времени программы), а do_1
- только 11% времени выполнения программы.Я думаю, что вы заинтересованы в этом столбце.
Третий столбец - это сумма текущих и предыдущих строк;таким образом, мы можем знать, что 2 самые медленные функции, do_4
и do_3
, в сумме составляли 68% общего времени выполнения (41% + 27%)
4-й и 5-й столбцы похожи на первый и второй;но эти будут учитывать не только выборки самой данной функции, но также выборки всех функций, вызываемых из данной, как прямо, так и косвенно.Вы можете видеть, что main
и все, что из него вызывается, составляют 100% от общего времени выполнения (поскольку main
- это сама программа или корень дерева вызовов программы), а last2
с ее дочерними элементами - 36,8% времени выполнения (его дети в моей программе: половина вызовов do_4
и половина вызовов do_3
= 41,1 + 27,6 / 2 = 69,7 / 2 ~ = 34% + некоторое время в самой функции)
PS: есть некоторые другие полезные команды pprof, например callgrind
или gv
, которые показывают графическое представление дерева вызовов с добавленной информацией профилирования.