Запутанный вывод gprof

Я запустил 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 секунды. Почему это может быть так неправильно?


c++ optimization profiling gprof
person Jesse Beder    schedule 27.01.2009    source источник

Ответы (6)


arrow_upward
9
arrow_downward

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

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

person Jesse Beder    schedule 01.02.2009
comment
Правильно. gprof будет игнорировать любой неинструментальный код, обычно включая время, затрачиваемое на стандартную библиотеку и системные вызовы. Получение точной информации о профилировании для программ, связанных с вводом-выводом и выделением памяти, может оказаться непростой задачей. - person Chris Conway; 22.02.2010
comment
У меня только что была такая же проблема. Браво за это. - person Matt Joiner; 08.09.2010

arrow_upward
6
arrow_downward

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

Совокупное количество секунд – это время, проведенное в [независимо] и вызовах над ним (например, [независимо] + main)

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

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

person Drew Dormann    schedule 27.01.2009
comment
На самом деле у меня была программа с функцией, которая не вызывала никаких других функций, но у меня была аналогичная проблема. Настроив эту функцию, было сэкономлено гораздо больше времени, чем предполагал gprof. - person casualcoder; 28.01.2009
comment
Процентное время — это ТОЛЬКО время, проведенное в рассматриваемой функции. Очевидно, что так, иначе main была бы главной функцией в каждом профиле gprof. - person Sol; 29.01.2009

arrow_upward
2
arrow_downward

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

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

person Sol    schedule 28.01.2009
comment
Я использовал время в инструментированном коде, но я также проверил его на нескольких запусках неинструментального кода и довольно близко (в пределах секунды). - person Jesse Beder; 29.01.2009
comment
Вы проверили (как я предложил), чтобы увидеть, что, по мнению gprof, было общее время прогона? - person Sol; 30.01.2009
comment
Да, это 1,03 секунды. Почему это может быть так неправильно? - person Jesse Beder; 01.02.2009

arrow_upward
1
arrow_downward

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

person casualcoder    schedule 28.01.2009

arrow_upward
1
arrow_downward

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

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

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

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

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

person Mike Dunlavey    schedule 23.11.2009

arrow_upward
0
arrow_downward

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

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

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

Я думаю, что странно, что вы видите 0 для «себя» и «всего звонков».

Цитируя раздел о точности gprof: " Фактический объем ошибки обычно превышает один период выборки. На самом деле, если значение в n раз больше периода выборки, ожидаемая ошибка в нем равна квадратному корню из n периодов выборки. Если период выборки составляет 0,01 секунды и foo's время выполнения составляет 1 секунду, ожидаемая ошибка во время выполнения foo составляет 0,1 секунды. Скорее всего, она будет сильно варьироваться в среднем от одного запуска профилирования к другому (иногда она будет отличаться больше).

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

person codelogic    schedule 27.01.2009
comment
Но этого не могло быть: если он вызывался 5498021 раз, то это должно было занять 0,32 с * 5498021 ~ 20 дней! Кроме того, ссылка неясна (я читал ее раньше) - это количество секунд, учитываемых только этой функцией, кажется, указывает на общее количество, а не на вызов, но не ясно. - person Jesse Beder; 28.01.2009