Почему построчная статистика NYTProf не соответствует итоговым данным?

Question

У меня есть сценарий Perl, который занимает около 30 минут, поэтому, конечно, я запускаю Devel :: NYTProf. Отличный профайлер. Для многих моих подводных лодок я получаю некоторые данные, которые не имеют смысла для меня.

Я работаю с perl 5.10.0 в Linux, используя настройки NYTProf по умолчанию.

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

Статистика строк не складывается с общей суммой, потраченной на функцию. Что дает?

Например, у меня есть функция, которая, как сообщается, использует 233s (57 + 166). Строковый отчет по номерам содержит одну строку, которая использует 20 с, другую - 4 и одну - 2. Другие строки - <1 с, а функция не такая длинная. </p>

Что я могу сделать, чтобы устранить это несоответствие?

Я мог бы перейти на Perl 5.12, но для установки зависимостей потребовалась бы некоторая работа. Я счастлив запустить его в более медленном режиме. Есть ли способ увеличить частоту дискретизации? Запускать на более медленной машине?

Нажмите здесь для примера: мой выход NYTProf . В этом случае сабвуфер использует 225 секунд, но сложение всех чисел дает 56 секунд. В этом прогоне отключена оптимизация:

setenv NYTPROF optimize=0:file=nytprof.optout

Обновление Я перезапустил Perl 5.12, используя флаг опции findcaller = 1, как предложено, с более или менее одинаковыми результатами. (Я запускал другой набор данных)

Обновление Тим Б прав. Я изменил некоторые из своих ключевых подпрограмм для самостоятельного кэширования, вместо того, чтобы использовать memoize, и результаты NYTProf снова полезны. Спасибо, Тим.

Answer 1

Я только что добавил это в документацию NYTProf:

= head2 Если синхронизация операторов и подпрограмм не совпадают

NYTProf имеет два профилировщика: профилировщик оператора, который вызываетсякогда perl перемещается из одного оператора perl в другой, и профилировщик подпрограммы, который вызывается, когда perl вызывает или возвращает из подпрограммы.

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

Профилировщик операторов отслеживает, сколько времени было потрачено на накладные расходы, такие как запись данных профиля оператора на диск,Профилировщик подпрограмм вычитает накладные расходы, которые накопились между входом и выходом из подпрограммы, чтобы дать более точный профиль.Профилировщик операторов, как правило, работает очень быстро, потому что большинство записей буферизуется для сжатия zip, поэтому накладные расходы профилировщика на оператор, как правило, очень малы, часто это один тик.В результате накопленные накладные расходы довольно шумные.Это становится более значимым для подпрограмм, которые часто вызываются, а также выполняются быстро.Это может быть еще одним, меньшим, вкладом в несоответствие между временем выписки и исключительным временем.

Это, вероятно, объясняет разницу между суммой столбца времени выписки (31,7 с) и исключительным временем, сообщенным дляподпрограмма (57,2 с).Разница составляет примерно 100 микросекунд на вызов (что кажется немного большим, но не слишком разумным).

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

Профилировщик операторов, как правило, очень быстрый, потому что большинство записей буферизуются для сжатия zip, поэтому накладные расходы профилировщика на операторимеет тенденцию быть очень маленьким, часто единственной 'галочкой'.В результате накопленные накладные расходы довольно шумные.Это становится более значительным для подпрограмм, которые часто вызываются, а также выполняются быстро (в этом случае 250303 вызовов при 899 мкс / вызов).Поэтому я подозреваю, что это еще один, меньший вклад в несоответствие между временем выписки и исключительным временем.

Что еще более важно, я также добавил этот раздел:

= head2 Если заголовокВремя выполнения подпрограммы не совпадает с вызванными подпрограммами

Общее время выполнения подпрограммы указывается с заголовком типа «потрачено 10 с (2 + 8) в пределах ...».В этом примере 10 секунд были потрачены внутри подпрограммы («включающее время»), и из этого 8 секунд были потрачены в подпрограммах, вызываемых этой подпрограммой.Это оставляет 2 секунды как время, потраченное в самом коде подпрограммы («исключительное время», иногда также называемое «временем самопомощи»).

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

Иногда сумма времени для вызовов, сделанных строками кода в подпрограмме, меньше, чем время, включающее эксклюзивсообщается в заголовке (10-2 = 8 секунд в примере выше).

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

Одна из причин - использование старой версии perl ( см. ниже ).Другой вызывает подпрограммы, которые выходят через "goto⊂ "- чаще всего встречается в подпрограммах и коде AUTOLOAD с использованием модуля Memoize.

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

Модуль Memoize является основной причиной расхождений в вашем отчете. При вызовах Memoize::__ANON__[...] выполняется подпрограмма, сгенерированная Memoize, которая выглядит как sub { unshift @_, $cref; goto &_memoizer; }. Что goto &_memoizer реализовано perl как своего родаВозврат к вызывающему абоненту с последующим вызовом к указанному сабвуферу, и именно так NYTProf профилирует его.

Путаница вызвана тем, что, хотя add_bit_to_map записывается как вызывающий _memoizerпоэтому время в вызове добавляется к add_bit_to_map, местоположение файла и номера строки звонка записывается как местоположение goto.

Возможно, это можно улучшить в будущем выпуске.

Спасибо, что предложили мне исследовать это и улучшить документацию.

Тим Банс.

псЯ рекомендую задавать вопросы о NYTProf в списке рассылки .

Answer 2

Попробуйте отключить оптимизатор Perl.От Документы CPAN Devel :: NYTProf :

optimize = 0

Отключить оптимизатор perl.

По умолчанию NYTProf оставляет оптимизатор perl включенным,Это дает вам более точную синхронизацию профиля в целом, но может привести к нечетному количеству операторов для отдельных наборов линий.Это потому, что оптимизатор глазка Perl эффективно переписал операторы, но вы не можете видеть, как выглядит переписанная версия.

Например:

1     if (...) {   
2         return;
3     } may be rewritten as

1    return if (...)

, поэтому профиль не будет отображатьКоличество операторов для строки 2 в вашем исходном коде, потому что возвращение было объединено с оператором if в предыдущей строке.

Использование опции optimize = 0 отключает оптимизатор, поэтому вы получаете более низкую общую производительность, но более точно назначеннуюколичество операторов.

Если вы найдете какие-либо другие примеры влияния оптимизатора на выход NYTProf (кроме производительности, очевидно), пожалуйста, сообщите нам.