Профилирование времени сна с помощью perf
Я искал способ узнать, где моя программа проводит время. Я прочитал perf tutorial и попытался рассчитать время сна, как там описано. Я написал простейшую возможную программу для профиля:
#include <unistd.h>
int main() {
sleep(10);
return 0;
}
то я выполнил его с perf:
$ sudo perf record -e sched:sched_stat_sleep -e sched:sched_switch -e sched:sched_process_exit -g -o ~/perf.data.raw ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.013 MB /home/pablo/perf.data.raw (~578 samples) ]
$ sudo perf inject -v -s -i ~/perf.data.raw -o ~/perf.data
build id event received for [kernel.kallsyms]: d62870685909222126e7070d2bafdf029f7ed3b6
failed to write feature 2
$ sudo perf report --stdio --show-total-period -i ~/perf.data
Error:
The /home/pablo/perf.data file has no samples!
Кто-нибудь знает, как избежать этих ошибок? Что они имеют в виду? failed to write feature 2 не выглядит слишком удобным...
Обновление:
$ uname -a
Linux debian 3.12-1-amd64 #1 SMP Debian 3.12.9-1 (2014-02-01) x86_64 GNU/Linux
Ответы
Ответ 1
Из вашей второй команды perf появляется сообщение об ошибке https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times - perf inject -s
$ sudo perf inject -v -s -i ~/perf.data.raw -o ~/perf.data
build id event received for [kernel.kallsyms]: d62870685909222126e7070d2bafdf029f7ed3b6
failed to write feature 2
не удалось написать функцию 2, не выглядит слишком удобной для пользователя...
... но он был добавлен в perf, чтобы сделать ошибки более удобными: http://lwn.net/Articles/460520/ "perf: make perf.data более самоописательным (v5)" Стефаном Эранианом, 22 сентября 2011 года:
+static int do_write_feat(int fd, struct perf_header *h, int type, ....
+ pr_debug("failed to write feature %d\n", type);
Все функции перечислены здесь http://lxr.free-electrons.com/source/tools/perf/util/header.h#L13
15 HEADER_TRACING_DATA = 1,
16 HEADER_BUILD_ID,
Итак, похоже, что PHP-инъекция не смогла написать информацию о идентификаторах сборки (ошибка из функции write_build_id() from util/header.c), если я не ошибаюсь. Есть два случая, которые могут привести к ошибке: неудачный вызов perf_session__read_build_ids() или отказ в написании таблицы buildid dsos__write_buildid_table (это не наш случай, потому что нет сообщения об ошибке "не удалось написать buildid table", проверьте write_build_id)
Вы можете проверить, есть ли у вас все сборки, необходимые для сеанса. Также может быть полезно очистить кеш сборки (rm -rf ~/.debug) и проверить, что у вас есть обновленный vmlinux с информацией об отладке или kallsyms, включенными в вашем ядре.
ОБНОВЛЕНИЕ: в комментариях Павел говорит, что в его записи pref не было никаких событий sched:sched_stat_sleep, записанных в perf.data:
sudo perf record -e sched:sched_stat_sleep -e sched:sched_switch -e sched:sched_process_exit -g -o ~/perf.data.raw ./a.out
Как он объясняет в своем ответе, его дефонированное ядро default имеет CONFIG_SCHEDSTATS параметр с патчем поставщика. Redhat сделал то же самое с опцией в ядрах релизов с 3.11, и это объясняется в Redhat Bug 1013225 (Josh Boyer 2013-10- 28, комментарий 4):
Мы переключились на включение этого только в debug builds некоторое время назад. Кажется, что он полностью отключился от финальной сборки 3.11.0 и с тех пор остался без внимания. Внутреннее тестирование показывает, что опция имеет нетривиальное влияние на производительность для коммутаторов контекста.
Мы можем включить это в ядрах отладки снова, но я не уверен, что это стоит.
Josh Poimboeuf 2013-11-04 в комментарии 8 говорит, что влияние производительности обнаруживается:
В моих тестах я сделал много контекстных переключателей при различных нагрузках на ЦП. Я видел, что средняя скорость переключения контекста на 5-10% уменьшилась, когда была включена функция CONFIG_SCHEDSTATS.... Похоже, что удар производительности произошел только на ядрах после CFS ( >= 2.6.23). Предыдущий планировщик O (1), похоже, не имел этой проблемы.
Fedora отключила CONFIG_SCHEDSTAT в не-отладочных ядрах 12 июля 2013 года [kernel] Отключить LATENCYTOP/SCHEDSTATS в не-отладочных сборках. от Dave Jones. Первое ядро с отключенной опцией: 3.11.0-0.rc0.git6.4.
Чтобы использовать любое событие трассировки программы perf с именем типа sched:sched_stat_* (sched:sched_stat_wait, sched:sched_stat_sleep, sched:sched_stat_iowait), мы должны перекомпилировать ядро с включенным параметром CONFIG_SCHEDSTATS и заменить стандартные Debian, RedHat или Ядра Fedora, которые не имеют этой опции.
Спасибо, Павел Давыдов.
Ответ 2
Наконец-то я узнал, как заставить его работать. Проблема заключалась в том, что ядро debian по умолчанию построено без каких-либо опций конфигурации, что перфоманс должен иметь возможность контролировать время сна. Похоже, что CONFIG_SCHEDSTATS должно быть включено, чтобы заставить сборщик собирать статистику планировщика. Говорят, что накладные расходы выполняются слишком быстро. Также я включил CONFIG_SCHED_TRACER и некоторые параметры отслеживания блокировки, но я не уверен, что они имеют значение в моем случае. В любом случае статистические данные не собираются в планировщике без CONFIG_SCHEDSTATS (см. Каталог kernel/sched/ источника ядра).
Кроме того, есть очень хорошая статья о perf, написанная Бренданом Греггом, с множеством полезных примеров и некоторыми вариантами ядра, которые необходимы чтобы обеспечить правильную работу.
Обновление: Я проверил историю CONFIG_SCHEDSTATS в debian. Я проверил debian патчи ядра и построил скрипты repo:
svn checkout svn://svn.debian.org/svn/kernel/dists/trunk/linux/debian
И затем найдите опцию CONFIG_SCHEDSTATS там
$ grep -R CONFIG_SCHEDSTAT config/
config/config:# CONFIG_SCHEDSTATS is not set
Эта строка была добавлена в репо в commit 10837, в 2008-03-14, с комментарием "debian/config: Do complete reorganization". Кроме того, в this и this (благодаря osgx) сообщается, что параметры CONFIG_LATENCYTOP, CONFIG_SCHEDSTATS не включены, поскольку они могут влиять на производительность ядра. Итак, я думаю, что он никогда не включался в ядра debian по умолчанию. Однако я не нашел дискуссию о параметре статистики планировщика. Если я это сделаю, я напишу здесь.
Ответ 3
Это работает для меня для "первичной версии 3.11.1" в поле "openSUSE 13.1 (x86_64)".
Вот результат, если вам интересно:
# ========
# captured on: Sun Feb 16 09:49:38 2014
# hostname : *****************
# os release : 3.11.10-7-desktop
# perf version : 3.11.1
# arch : x86_64
# nrcpus online : 8
# nrcpus avail : 8
# cpudesc : Intel(R) Core(TM) i7-3840QM CPU @ 2.80GHz
# cpuid : GenuineIntel,6,58,9
# total memory : 32945368 kB
# cmdline : /usr/bin/perf inject -v -s -i perf.data.raw -o perf.data
# event : name = sched:sched_stat_sleep, type = 2, config = 0x48, config1 = 0x0, config2 = 0x
# event : name = sched:sched_switch, type = 2, config = 0x51, config1 = 0x0, config2 = 0x0, e
# event : name = sched:sched_process_exit, type = 2, config = 0x4e, config1 = 0x0, config2 =
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, software = 1, tracepoint = 2, uncore_cbox_0 = 6, uncore_cbox_1 = 7,
# ========
#
# Samples: 0 of event 'sched:sched_stat_sleep'
# Event count (approx.): 0
#
# Overhead Period Command Shared Object Symbol
# ........ ............ ....... ............. ......
#
# Samples: 8 of event 'sched:sched_switch'
# Event count (approx.): 80099958776
#
# Overhead Period Command Shared Object Symbol
# ........ ............ ....... ................. .................
#
100.00% 80099958776 bla [kernel.kallsyms] [k] thread_return
|
--- thread_return
thread_return
do_nanosleep
hrtimer_nanosleep
SyS_nanosleep
system_call_fastpath
0x7fbc0dec6570
__GI___libc_nanosleep
(nil)
# Samples: 0 of event 'sched:sched_process_exit'
# Event count (approx.): 0
#
# Overhead Period Command Shared Object Symbol
# ........ ............ ....... ............. ......
#
#
# (For a higher level overview, try: perf report --sort comm,dso)
#
}
