Что означает опция perf для измерения событий на уровне пользователя и ядра?

Инструмент Perf для Linux предоставляет доступ к счетчикам событий процессора. Это позволяет вам указать события, которые будут подсчитаны и когда подсчитывать эти события.

https://perf.wiki.kernel.org/index.php/Tutorial

По умолчанию события измеряются как на уровне пользователя, так и на уровне ядра:

perf stat -e cycles dd if=/dev/zero of=/dev/null count=100000

Чтобы измерять только на уровне пользователя, необходимо передать модификатор:

perf stat -e cycles:u dd if=/dev/zero of=/dev/null count=100000

Чтобы измерить как пользователя, так и ядро ​​(явно):

perf stat -e cycles:uk dd if=/dev/zero of=/dev/null count=100000

От этого я ожидал, что cycles:u означало "только подсчитывать события во время выполнения неядерного кода", и записанные значения не будут отображаться в символы ядра, но это не так.

Вот пример:

perf record -e cycles:u du -sh ~
[...]
perf report --stdio -i perf.data
[...]
9.24%  du       [kernel.kallsyms]  [k] system_call
[...]
0.70%  du       [kernel.kallsyms]  [k] page_fault
[...]

Если я делаю то же самое, но использую cycles:uk затем я получаю больше сообщений о ядре, так что модификаторы событий имеют эффект. С помощью cycles:k создает отчеты с почти исключительно символами ядра, но включает несколько символов libc.

Что тут происходит? Это ожидаемое поведение? Я неправильно понимаю язык, используемый в связанном документе?

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

Modifiers | Description                          | Example
----------+--------------------------------------+----------
u         | monitor at priv level 3, 2, 1 (user) | event:u
k         | monitor at priv level 0 (kernel)     | event:k

Редактировать: больше информации:

Процессор Intel Haswell. Конкретная модель - это i7-5820K.

Distro является актуальной версией Arch Linux (график релизов) с ядром 4.1.6.

Сама версия perf - 4.2.0.

Edit2:

Больше выводов из примера работает. Как вы видете, cycles:u в основном сообщает неядерные символы. Я знаю, что иногда неверные атрибуты perf учитываются в соседней инструкции, когда вы смотрите на вывод аннотированной сборки. Может быть, это связано?

циклы: U

# perf record -e cycles:u du -sh ~
179G    /home/khouli
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.116 MB perf.data (2755 samples) ]
# sudo perf report --stdio -i perf.data
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 2K of event 'cycles:u'
# Event count (approx.): 661835375
#
# Overhead  Command  Shared Object      Symbol
# ........  .......  .................  ..............................
#
    11.02%  du       libc-2.22.so       [.] _int_malloc
     9.73%  du       libc-2.22.so       [.] _int_free
     9.24%  du       du                 [.] fts_read
     9.23%  du       [kernel.kallsyms]  [k] system_call
     4.17%  du       libc-2.22.so       [.] strlen
     4.17%  du       libc-2.22.so       [.] __memmove_sse2
     3.47%  du       libc-2.22.so       [.] __readdir64
     3.33%  du       libc-2.22.so       [.] malloc_consolidate
     2.87%  du       libc-2.22.so       [.] malloc
     1.83%  du       libc-2.22.so       [.] msort_with_tmp.part.0
     1.63%  du       libc-2.22.so       [.] __memcpy_avx_unaligned
     1.63%  du       libc-2.22.so       [.] __getdents64
     1.52%  du       libc-2.22.so       [.] free
     1.47%  du       libc-2.22.so       [.] __memmove_avx_unaligned
     1.44%  du       du                 [.] 0x000000000000e609
     1.41%  du       libc-2.22.so       [.] _wordcopy_bwd_dest_aligned
     1.19%  du       du                 [.] 0x000000000000e644
     0.93%  du       libc-2.22.so       [.] __fxstatat64
     0.85%  du       libc-2.22.so       [.] do_fcntl
     0.73%  du       [kernel.kallsyms]  [k] page_fault
[lots more symbols, almost all in du...]

циклы: ик

# perf record -e cycles:uk du -sh ~
179G    /home/khouli
[ perf record: Woken up 1 times to write data ]
[ext4] with build id 0f47443e26a238299e8a5963737da23dd3530376 not found,
continuing without symbols
[ perf record: Captured and wrote 0.120 MB perf.data (2856 samples) ]
# perf report --stdio -i perf.data
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 2K of event 'cycles:uk'
# Event count (approx.): 3118065867
#
# Overhead  Command  Shared Object      Symbol
# ........  .......  .................  ..............................................
#
    13.80%  du       [kernel.kallsyms]  [k] __d_lookup_rcu
     6.16%  du       [kernel.kallsyms]  [k] security_inode_getattr
     2.52%  du       [kernel.kallsyms]  [k] str2hashbuf_signed
     2.43%  du       [kernel.kallsyms]  [k] system_call
     2.35%  du       [kernel.kallsyms]  [k] half_md4_transform
     2.31%  du       [kernel.kallsyms]  [k] ext4_htree_store_dirent
     1.97%  du       [kernel.kallsyms]  [k] copy_user_enhanced_fast_string
     1.96%  du       libc-2.22.so       [.] _int_malloc
     1.93%  du       du                 [.] fts_read
     1.90%  du       [kernel.kallsyms]  [k] system_call_after_swapgs
     1.83%  du       libc-2.22.so       [.] _int_free
     1.44%  du       [kernel.kallsyms]  [k] link_path_walk
     1.33%  du       libc-2.22.so       [.] __memmove_sse2
     1.19%  du       [kernel.kallsyms]  [k] _raw_spin_lock
     1.19%  du       [kernel.kallsyms]  [k] __fget_light
     1.12%  du       [kernel.kallsyms]  [k] kmem_cache_alloc
     1.12%  du       [kernel.kallsyms]  [k] __ext4_check_dir_entry
     1.05%  du       [kernel.kallsyms]  [k] lockref_get_not_dead
     1.02%  du       [kernel.kallsyms]  [k] generic_fillattr
     0.95%  du       [kernel.kallsyms]  [k] do_dentry_open
     0.95%  du       [kernel.kallsyms]  [k] path_init
     0.95%  du       [kernel.kallsyms]  [k] lockref_put_return
     0.91%  du       libc-2.22.so       [.] do_fcntl
     0.91%  du       [kernel.kallsyms]  [k] ext4_getattr
     0.91%  du       [kernel.kallsyms]  [k] rb_insert_color
     0.88%  du       [kernel.kallsyms]  [k] __kmalloc
     0.88%  du       libc-2.22.so       [.] __readdir64
     0.88%  du       libc-2.22.so       [.] malloc
     0.84%  du       [kernel.kallsyms]  [k] ext4fs_dirhash
     0.84%  du       [kernel.kallsyms]  [k] __slab_free
     0.84%  du       [kernel.kallsyms]  [k] in_group_p
     0.81%  du       [kernel.kallsyms]  [k] get_empty_filp
     0.77%  du       libc-2.22.so       [.] malloc_consolidate
[more...]

циклы: к

# perf record -e cycles:k du -sh ~
179G    /home/khouli
[ perf record: Woken up 1 times to write data ]
[ext4] with build id 0f47443e26a238299e8a5963737da23dd3530376 not found, continuing
without symbols
[ perf record: Captured and wrote 0.118 MB perf.data (2816 samples) ]
# perf report --stdio -i perf.data
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 2K of event 'cycles:k'
# Event count (approx.): 2438426748
#
# Overhead  Command  Shared Object      Symbol
# ........  .......  .................  ..............................................
#
    17.11%  du       [kernel.kallsyms]  [k] __d_lookup_rcu
     6.97%  du       [kernel.kallsyms]  [k] security_inode_getattr
     4.22%  du       [kernel.kallsyms]  [k] half_md4_transform
     3.10%  du       [kernel.kallsyms]  [k] str2hashbuf_signed
     3.01%  du       [kernel.kallsyms]  [k] system_call_after_swapgs
     2.59%  du       [kernel.kallsyms]  [k] ext4_htree_store_dirent
     2.24%  du       [kernel.kallsyms]  [k] copy_user_enhanced_fast_string
     2.14%  du       [kernel.kallsyms]  [k] lockref_get_not_dead
     1.86%  du       [kernel.kallsyms]  [k] ext4_getattr
     1.85%  du       [kernel.kallsyms]  [k] kfree
     1.68%  du       [kernel.kallsyms]  [k] __ext4_check_dir_entry
     1.53%  du       [kernel.kallsyms]  [k] __fget_light
     1.34%  du       [kernel.kallsyms]  [k] link_path_walk
     1.34%  du       [kernel.kallsyms]  [k] path_init
     1.22%  du       [kernel.kallsyms]  [k] __kmalloc
     1.22%  du       [kernel.kallsyms]  [k] kmem_cache_alloc
     1.14%  du       [kernel.kallsyms]  [k] do_dentry_open
     1.11%  du       [kernel.kallsyms]  [k] ext4_readdir
     1.07%  du       [kernel.kallsyms]  [k] __find_get_block_slow
     1.07%  du       libc-2.22.so       [.] do_fcntl
     1.04%  du       [kernel.kallsyms]  [k] _raw_spin_lock
     0.99%  du       [kernel.kallsyms]  [k] _raw_read_lock
     0.95%  du       libc-2.22.so       [.] __fxstatat64
     0.94%  du       [kernel.kallsyms]  [k] rb_insert_color
     0.94%  du       [kernel.kallsyms]  [k] generic_fillattr
     0.93%  du       [kernel.kallsyms]  [k] ext4fs_dirhash
     0.93%  du       [kernel.kallsyms]  [k] find_get_entry
     0.89%  du       [kernel.kallsyms]  [k] rb_next
     0.89%  du       [kernel.kallsyms]  [k] is_dx_dir
     0.89%  du       [kernel.kallsyms]  [k] in_group_p
     0.89%  du       [kernel.kallsyms]  [k] cp_new_stat
   [more...]

perf_event_paranoid

$ cat /proc/sys/kernel/perf_event_paranoid
1

конфиг ядра для перф

$ cat /proc/config.gz | gunzip | grep -A70 'Kernel Perf'
# Kernel Performance Events And Counters
#
CONFIG_PERF_EVENTS=y
# CONFIG_DEBUG_PERF_USE_VMALLOC is not set
CONFIG_VM_EVENT_COUNTERS=y
CONFIG_SLUB_DEBUG=y
# CONFIG_COMPAT_BRK is not set
# CONFIG_SLAB is not set
CONFIG_SLUB=y
CONFIG_SLUB_CPU_PARTIAL=y
CONFIG_SYSTEM_TRUSTED_KEYRING=y
CONFIG_PROFILING=y
CONFIG_TRACEPOINTS=y
CONFIG_OPROFILE=m
# CONFIG_OPROFILE_EVENT_MULTIPLEX is not set
CONFIG_HAVE_OPROFILE=y
CONFIG_OPROFILE_NMI_TIMER=y
CONFIG_KPROBES=y
CONFIG_JUMP_LABEL=y
CONFIG_KPROBES_ON_FTRACE=y
CONFIG_UPROBES=y
# CONFIG_HAVE_64BIT_ALIGNED_ACCESS is not set
CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS=y
CONFIG_ARCH_USE_BUILTIN_BSWAP=y
CONFIG_KRETPROBES=y
CONFIG_USER_RETURN_NOTIFIER=y
CONFIG_HAVE_IOREMAP_PROT=y
CONFIG_HAVE_KPROBES=y
CONFIG_HAVE_KRETPROBES=y
CONFIG_HAVE_OPTPROBES=y
CONFIG_HAVE_KPROBES_ON_FTRACE=y
CONFIG_HAVE_ARCH_TRACEHOOK=y
CONFIG_HAVE_DMA_ATTRS=y
CONFIG_HAVE_DMA_CONTIGUOUS=y
CONFIG_GENERIC_SMP_IDLE_THREAD=y
CONFIG_HAVE_REGS_AND_STACK_ACCESS_API=y
CONFIG_HAVE_CLK=y
CONFIG_HAVE_DMA_API_DEBUG=y
CONFIG_HAVE_HW_BREAKPOINT=y
CONFIG_HAVE_MIXED_BREAKPOINTS_REGS=y
CONFIG_HAVE_USER_RETURN_NOTIFIER=y
CONFIG_HAVE_PERF_EVENTS_NMI=y
CONFIG_HAVE_PERF_REGS=y
CONFIG_HAVE_PERF_USER_STACK_DUMP=y
CONFIG_HAVE_ARCH_JUMP_LABEL=y
CONFIG_ARCH_HAVE_NMI_SAFE_CMPXCHG=y
CONFIG_HAVE_ALIGNED_STRUCT_PAGE=y
CONFIG_HAVE_CMPXCHG_LOCAL=y
CONFIG_HAVE_CMPXCHG_DOUBLE=y
CONFIG_ARCH_WANT_COMPAT_IPC_PARSE_VERSION=y
CONFIG_ARCH_WANT_OLD_COMPAT_IPC=y
CONFIG_HAVE_ARCH_SECCOMP_FILTER=y
CONFIG_SECCOMP_FILTER=y
CONFIG_HAVE_CC_STACKPROTECTOR=y
CONFIG_CC_STACKPROTECTOR=y
# CONFIG_CC_STACKPROTECTOR_NONE is not set
# CONFIG_CC_STACKPROTECTOR_REGULAR is not set
CONFIG_CC_STACKPROTECTOR_STRONG=y
CONFIG_HAVE_CONTEXT_TRACKING=y
CONFIG_HAVE_VIRT_CPU_ACCOUNTING_GEN=y
CONFIG_HAVE_IRQ_TIME_ACCOUNTING=y
CONFIG_HAVE_ARCH_TRANSPARENT_HUGEPAGE=y
CONFIG_HAVE_ARCH_HUGE_VMAP=y
CONFIG_HAVE_ARCH_SOFT_DIRTY=y
CONFIG_MODULES_USE_ELF_RELA=y
CONFIG_HAVE_IRQ_EXIT_ON_IRQ_STACK=y
CONFIG_ARCH_HAS_ELF_RANDOMIZE=y
CONFIG_OLD_SIGSUSPEND3=y
CONFIG_COMPAT_OLD_SIGACTION=y

2 ответа

Я понимаю, что ваш вопрос таков: почему perf для записи в пользовательском режиме показывает значения внутри ядра? Ну, он делает именно то, что должен делать, с точки зрения "системного учета".

Ты сделал: perf record -e cycles:u du -sh ~ и вы получили статистику system_call а также page_fault и вы задаетесь вопросом, почему это произошло?

Когда ты сделал du, он должен был пройти через файловую систему. При этом он отправлял системные вызовы для необходимых ему вещей (например, open, readdir и т. Д.). Ду инициировал эти вещи для вас, так что они были "возвращены" для них. Точно так же du page несколько раз выходил из строя.

perf отслеживает любую активность, вызванную данным процессом / программой, даже если она происходит внутри адресного пространства ядра. Другими словами, программа запросила действие, и ядро ​​выполнило его по поручению программы, поэтому оно получает соответствующую плату. Ядро должно было выполнить "реальную работу", чтобы выполнить ввод-вывод FS и / или устранить ошибки страниц, поэтому вы должны "заплатить за работу, которую вы заказали". Все, что делает данная программа, которая потребляет системные ресурсы, учитывается.

Это стандартная модель учета для компьютерных систем, восходящая к 1960-м годам, когда люди фактически арендовали время на мэйнфреймах. Вы получили плату за все, что вы делали [прямо как юрист:-)], прямо или косвенно.
* плата за минуту соединения
* плата за цикл, потребляемый в пользовательской программе
* плата за цикл, выполняемый для программы в пространстве ядра
* плата за каждый отправленный / полученный сетевой пакет
* плата за любой сбой страницы, вызванный вашей программой
* плата за каждый блок чтения / записи диска, либо в файл, либо на диск подкачки / подкачки
В конце месяца они отправили вам по почте подробный счет [точно так же, как счет за коммунальные услуги], и вам пришлось заплатить:
Реальные деньги

Обратите внимание, что есть некоторые вещи, за которые не будет взиматься плата. Например, давайте предположим, что ваша программа связана с вычислениями, но не выполняет [много] операций ввода-вывода и использует относительно небольшой объем памяти (то есть она сама по себе не вызывает ошибку страницы). Программа будет взиматься плата за использование процессора в пользовательском пространстве.

ОС, возможно, придется поменять (то есть украсть) одну или несколько ваших страниц, чтобы освободить место для какой-нибудь другой программы по загрузке памяти. После запуска свиньи ваша программа снова запустится. Ваша программа должна будет вернуться к странице или страницам, которые были украдены с нее.

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

Кроме того, при попытке запустить другой процесс ядро не загружает процессорное время, затраченное его планировщиком процесса, на какой-либо процесс. Это считается "накладными" и / или стандартными эксплуатационными расходами. Например, если у вас есть текущий счет в банке, они не будут взимать с вас плату за содержание в местном филиале, который вы посещаете.

Поэтому, хотя и полезно для измерения производительности, он использует модель учета для получения данных.

Это как машина. Вы можете доехать на машине до магазина и забрать что-нибудь, и вы будете потреблять бензин. Или вы можете попросить друга отвезти вашу машину в магазин. В любом случае вам придется платить за бензин, потому что вы управляли автомобилем или потому, что [когда друг управлял автомобилем] бензин расходуется, когда вы что-то делаете для вас. В этом случае ядро ​​вашего друга:-)

ОБНОВИТЬ:

Мой источник для этого - источник [источник ядра]. И я занимаюсь программированием ядра в течение 40 лет.

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

Другое время - "микро" или "нано" тип. Они взяты из архива PMC в x86 и содержат счетчики для таких вещей, как "промах кэша", "неверный прогноз ветки", "неправильный выбор данных" и т. Д., Которые ядро ​​не может вычислить.

Счетчики PMC просто бесплатны. Вот почему вы получаете свою глобальную статистику, независимо от того, какой режим записи вы делаете. Ядро может периодически их опрашивать, но оно не может получить контроль при каждом увеличении PMC. Вам нужны глобальные / общесистемные значения и / или значения для каждого процессора? Просто выполните соответствующую инструкцию RDPMC.

Чтобы отслеживать PMC для процесса, при запуске процесса выполните RDPMC и сохраните значение в структуре задачи [для всех, которые отмечены как "представляющие интерес"] как "Значение PMC при запуске". Когда заданное ядро ​​ЦП перепланировано, планировщик вычисляет "следующую" задачу, планировщик получает текущее значение PMC, берет разницу между ним и единицей, которая была сохранена в "старом" блоке задач, когда он запускал эту задачу, и поднимает "общее количество" этой задачи для этого PMC. "Текущее значение" становится "значением PMC новой задачи при запуске"

В Linux, когда происходит переключение задачи / контекста, он генерирует два события perf, одно для "ввода новой задачи в CPU X" и "остановки старой задачи в CPU X".

Ваш вопрос был, почему мониторинг "пользовательского режима" производил адреса ядра. Это связано с тем, что при записи (а это не программа perf) она сохраняет временные данные [как упомянуто выше] в текущем блоке задачи / контекста, пока фактически не произойдет переключение задачи.

Главное, на что следует обратить внимание, это то, что этот контекст не изменяется просто потому, что был выполнен системный вызов - только когда происходит переключение контекста. Например, системный вызов gettimeofday justs получает время настенных часов и возвращает его в пространство пользователя. Он не выполняет переключение контекста, поэтому любое событие perf, которое оно запускает, будет отнесено к активному / текущему контексту. Неважно, исходит ли оно из пространства ядра или из пространства пользователя.

В качестве дальнейшего примера, предположим, что процесс выполняет системный вызов чтения файла. При обходе данных дескриптора файла, inode и т. Д. Он может генерировать несколько перфектных событий. Кроме того, это, вероятно, вызовет еще несколько промахов кэша и других ударов счетчика PMC. Если нужный блок уже находится в кэше блоков FS, системный вызов просто сделает copy_to_user, а затем снова войдет в пространство пользователя. Нет дорогого переключения контекста с вышеупомянутыми вычислениями разности PMC, поскольку pmc_value_at_start все еще допустим.

Одной из причин, по которой это делается таким образом, является производительность [механизма perf]. Если бы вы выполняли сохранение / восстановление PMC сразу после перехода в пространство ядра после запуска системного вызова [чтобы отделить статистику ядра от статистики пользователя для данного процесса, как вам хотелось бы], издержки были бы огромными. Вы не будете измерять производительность базового ядра. Вы будете измерять производительность ядра + много лишних затрат.

Когда мне пришлось провести анализ производительности коммерческой системы реального времени на базе Linux, я разработал собственную систему регистрации производительности. Система имела 8 процессорных ядер, взаимодействующих с несколькими нестандартными аппаратными платами на шине PCIe с несколькими FPGA. У FPGA также была специальная прошивка, работающая внутри Microblaze. Журналы событий из пользовательского пространства, пространства ядра и микроблэйза могут быть согласованы по времени с наносекундным разрешением, а время хранения записи о событии составляет 70 нс.

Для меня механизм Perf в Linux немного грубоватый и раздутый. Если бы кто-то использовал его, чтобы попытаться устранить ошибку производительности / синхронизации, которая включала условия гонки, возможные проблемы блокировки / разблокировки и т. Д., Это могло бы быть проблематично. То есть, запустив систему без перфорации, вы получите ошибку. Включите перфорацию, а вы - нет, потому что вы изменили основную характеристику синхронизации системы. Выключите перфорацию, и ошибка времени появится снова.

Что тут происходит? Это ожидаемое поведение? Я неправильно понимаю язык, используемый в связанном документе?

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

В разделе введения в ссылке https://perf.wiki.kernel.org/index.php/Tutorial говорится, что "Вывод получен в системе Ubuntu 11.04 с общими результатами ядра 2.6.38-8, работающими на HP 6710b с двойным -core Intel Core2 T7100 CPU)"тогда как текущая оценка выше Intel Haswell(i7-5820K - 6 ядер) в дистрибутиве Arch Linux с ядром 4.1.6.

Одним из вариантов исключения различий в поведении и документации является тестирование в системе с эквивалентной конфигурацией, которая упоминается в разделе введения по ссылке https://perf.wiki.kernel.org/index.php/Tutorial.

Другие вопросы по тегам