Как я должен интерпретировать вывод OProfile?
Я недавно попытался профилировать свое приложение с OProfile. Собранные данные уже очень ценны для меня, но у меня возникают трудности с их точной интерпретацией. После запуска моего приложения с настроенным и запущенным oprofile я сгенерировал отчет и получил:
root @ se7xeon: srC# opreport image: test -l -t 1
Статистика переполнения недоступна
Процессор: P4 / Xeon с 2-мя гиперпотоками, частота 3191,66 МГц (по оценкам)
Подсчитанные события GLOBAL_POWER_EVENTS (время, в течение которого процессор не останавливается) с единичной маской 0x01 (обязательно), считают 750000
образцы% символа
215522 84.9954 cci:: Image:: interpolate (unsigned char *, cci:: Matrix const &) const
17998 7.0979 cci:: Calc:: diff (unsigned char const *, unsigned char const *)
13171 5.1942 cci:: Image:: getIRect (unsigned char *, int, int) const
5519 2,1765 cci::Image::getFRect(без знака char*, double, double) const
Итак, моя функция интерполяции отвечает за 84% (слишком длительного) времени выполнения приложения. Кажется хорошей идеей разобраться в этом:
root @ se7xeon: srC# opannotate image: test --source
[...]
/* cci::Image::interpolate(unsigned char*, cci::Matrix<cci::Point2DF> const&) const total: 215522 84.9954 */
1392 0.5529 :void Image::interpolate(CCIPixel *output, const Matrix<Point2DF> &inputPoints) const throw()
4 0.0016 :{
[...]
: col0 = static_cast<int>(point[idx].x);
3 0.0012 : col1 = col0+1;
629 0.2498 : row0 = static_cast<int>(point[idx].y);
385 0.1529 : row1 = row0+1;
56214 22.3266 : if (col0 < 0 || col1 >= m_width || row0 < 0 || row1 >= m_height)
: {
: col0 = row0 = col1 = row1 = 0;
: }
Если я правильно понимаю, условное условие отвечает за более 22% времени выполнения программы. Открывающая фигурная скобка и объявление функции, похоже, требуют времени, это должно соответствовать накладным расходам вызова функции (последовательность "push-параметры в стеке, переходе, параметрах pop")?
Я изменил некоторые вещи в исходном коде (связанные с более поздним узким местом, потому что не знал, как оптимизировать if), перекомпилировал, снова запустил oprofile (не забывая opcontrol --reset). Теперь аннотированный код выглядит следующим образом:
6 0.0024 : curPx = point[idx].x;
628 0.2477 : curPy = point[idx].y;
410 0.1617 : col0 = static_cast<int>(curPx);
57910 22.8380 : col1 = col0+1;
: row0 = static_cast<int>(curPy);
: row1 = row0+1;
: if (col0 < 0 || col1 >= m_width || row0 < 0 || row1 >= m_height)
: {
: col0 = row0 = col1 = row1 = 0;
: }
На этот раз оператор if вообще не требует времени (?), Самая дорогая инструкция - "col1 = col0 + 1", и весь блок, занимающий много времени, кажется, сместился вверх. Как это может быть? Можно ли вообще доверять этому, чтобы точно определить узкие места в источнике?
Другой вопрос, который вызывает у меня сомнения, заключается в том, что когда я установил opcontrol, я вошел в отслеживаемое событие как GLOBAL_POWER_EVENTS, с числом выборок 750k. На выходе функция интерполяции, кажется, занимает 84%, но количество сэмплов, записанных внутри нее, чуть выше 200 тыс. Это даже не 50% запрошенного числа. Должен ли я понять, что оставшиеся ~500 тыс. Образцов были взяты приложениями, не указанными в выходных данных (ядро, Xorg и т. Д.)?
2 ответа
При профилировании оптимизированного кода вы действительно не можете полагаться на точные строки исходного кода. Компилятор слишком много перемещает.
Для получения точной картины вам нужно взглянуть на вывод дизассемблера кода.
OProfile может (они говорят мне) получить образцы стека по времени настенных часов (не CPU), и он может дать вам проценты на уровне строки. То, что вы ищете, это строки, которые содержатся в большом проценте образцов стека.
Я не включил бы оптимизацию компилятора, пока не закончу настраивать код вручную, потому что он просто скрывает вещи.
Когда вы говорите, что процедура интерполяции использует 84% времени, это вызывает вопрос. Вся программа занимает некоторое время, верно? Это занимает 100% этого времени. Если вы сократите время программы вдвое или удвоите его, это все равно займет 100% времени. То, будет ли 84% для интерполяции слишком большим или нет, зависит от того, делается ли это больше, чем необходимо.
Поэтому я бы посоветовал вам не спрашивать, слишком ли велик процент рутины. Скорее вы ищите строки кода, которые занимают значительное количество времени, и спрашиваете, можно ли их оптимизировать. Увидеть разницу? После оптимизации кода он может значительно сократить общее время выполнения, но он все равно может составить большой процент от меньшего общего количества. Код не оптимален, когда ничего не занимает большой процент. Код оптимален, когда из всех вещей, которые занимают большой процент, ничего нельзя улучшить.
Меня не волнуют вещи, которые просто дают цифры. Что я хочу, так это понимание. Например, если на эту процедуру приходится 84% времени, то, если вы взяли 10 выборок из стека, это было бы на 8,4 из них. Точное число не имеет значения. Важно понять, почему это было там. Неужели так много нужно быть там? Вот что может сказать вам пример стековых образцов. Может быть, вы на самом деле делаете интерполяцию в два раза чаще, чем необходимо? Часто люди, анализируя причину, обнаруживают, что рутину, которую они пытаются ускорить, не нужно было называть почти так же, может быть, вовсе нет. Я не могу угадать в вашем случае. Только понимание состояния программы может вам это сказать.