Смущающий вывод gprof

Question

Я запустил gprof в программе на C ++, которая заняла 16.637s, согласно time(), и получил это для первой строки вывода:

%   cumulative   self              self     total           
time   seconds   seconds    calls   s/call   s/call  name    
31.07      0.32     0.32  5498021     0.00     0.00  [whatever]

Почему он перечисляет 31.07% времени, если это заняло .32 секунд? Это время звонка? (Разве это не было бы само собой / звонить?)

Я впервые использую gprof, поэтому, пожалуйста, будьте добры:)

Редактировать: при прокрутке вниз кажется, что gprof только думает, что моя программа занимает 1,03 секунды. Почему это может быть так неправильно?

Answer 1

Узкое место оказалось в файловом вводе / выводе (см. Является ли std :: ifstream значительно медленнее, чем FILE? ). Я переключился на чтение всего файла в буфере, и он значительно ускорился.

Проблема здесь заключалась в том, что gprof не генерирует точное профилирование при ожидании файлового ввода-вывода (см. http://www.regatta.cs.msu.su/doc/usr/share/man/info/ru_RU/a_doc_lib/cmds/aixcmds2/gprof.htm). На самом деле seekg и tellg даже не было в списке профилирования и они были узким местом!

Answer 2

Собственные секунды - это время, проведенное в [чем угодно].

Совокупные секунды - это время, проведенное в [что угодно] и вызовы над ним (например, [что угодно] + основной)

Ни одно из них не включает время, потраченное на функции, вызываемые из [что угодно]. Вот почему вы не видите больше времени в списке.

Если ваша [любая] функция вызывает, например, много printf, ваш вывод gprof сообщает вам, что printf потребляет большую часть этого времени.

Answer 3

Это довольно хороший обзор , как читать вывод gprof . 31,07%, на которые вы смотрите, это часть общего времени выполнения, которое, по мнению gprof, расходуется только на эту функцию (не включая функции, которые она вызывает). Вероятность того, что процент такой большой, а время мало, заключается в том, что gprof считает, что программа не займет столько времени, сколько вы. Это легко проверить, прокрутив этот первый раздел вывода gprof: совокупные секунды будут увеличиваться и увеличиваться, пока не будут ограничены в общем времени работы программы (с точки зрения gprof). Я думаю, вы найдете, что это примерно одна секунда, а не 16, которые вы ожидаете.

Что касается того, почему там такое большое расхождение, я не могу сказать. Возможно, gprof не видит весь код. Или вы использовали время для инструментированного кода во время его профилирования? Я не ожидал бы, что это будет работать правильно ...

Answer 4

Вы столкнулись с проблемой, общей для gprof и других профилировщиков, основанных на тех же принципах - 1) выборка счетчика программы для получения некоторой гистограммы, 2) инструментальные функции для измерения времени, подсчета и получите график вызовов.

Для выявления проблем с производительностью, они упускают суть.
Речь идет не об измерении процедур, а о поиске виновного кода.

Предположим, у вас есть сэмплер, который стробоскопически делает рентгеновские снимки программы в случайные часы. В каждом примере программа может находиться в середине ввода-вывода, она может быть в скомпилированном вами коде, она может быть в какой-то библиотечной подпрограмме, например malloc .

Но независимо от того, где он находится, ответственность за то, что он потратил этот отрезок времени, совместно разделяется каждой строкой кода в стеке вызовов , потому что, если какой-либо из этих вызовов не был выполнен, он не будет выполнять работу, запрошенную этим призывом.

Итак, посмотрите на каждую строку кода, которая отображается в нескольких выборках стека вызовов (чем больше выборок, тем лучше). Вот где деньги. Не просто смотрите, где находится счетчик программ. Вверху стека находятся «глубокие карманы».

Answer 5

Вы пробовали другие инструменты, упомянутые в этом вопросе ? Было бы интересно, как они сравниваются.

Answer 6

Да, эти значения "секунд" равны не для вызова. Процентное время для всего запуска программы. По сути, ваша программа потратила 31% своего времени на эту функцию (из-за количества вызовов + времени, затраченного на один вызов).

Возможно, вы захотите прочитать о том, как анализировать плоские профили gprof.

Исправление: Извините, эти первые две секунды значения являются кумулятивными, как указано в ОП.

Я думаю, что странно, что вы видите 0 для "self" и "total s / call".

Цитирование раздела о gprof precision : «Фактическая величина ошибки обычно превышает один период выборки. Фактически, если значение равно n раз периода выборки, ожидаемая ошибка в нем квадратный корень из n периодов выборки.Если период выборки составляет 0,01 секунды, а время выполнения foo равно 1 секунде, ожидаемая ошибка во время выполнения foo составляет 0,1 секунды. к следующему. (Иногда это будет отличаться больше.) "

Также, возможно, это связано с тем, что стоит отметить, что gprof не профилирует многопоточные программы. В таких случаях лучше использовать что-то вроде Sysprof или OProfile .