Perf пересчет простого цикла с привязкой к процессору: загадочная работа ядра?
Некоторое время я использовал Linux perf для профилирования приложений. Как правило, профилированное приложение является довольно сложным, поэтому обычно просто принимают значения счетчиков, представленные в отчете, по номиналу, при условии, что нет никаких серьезных расхождений с тем, что вы можете ожидать, основываясь на первых принципах.
Однако недавно я профилировал некоторые тривиальные 64-битные программы сборки - достаточно триалиально, чтобы можно было почти точно рассчитать ожидаемое значение различных счетчиков, и кажется, что perf stat это пересчет.
Возьмите следующий цикл, например:
.loop:
nop
dec rax
nop
jne .loop
Это будет просто петля n раз, где n это начальное значение rax, Каждая итерация цикла выполняет 4 инструкции, так что вы ожидаете 4 * n Выполненные инструкции, плюс небольшие фиксированные накладные расходы на запуск и завершение процесса и небольшой кусочек кода, который устанавливает n перед входом в цикл.
Вот (типичный) perf stat выход для n = 1,000,000,000:
~/dev/perf-test$ perf stat ./perf-test-nop 1
Performance counter stats for './perf-test-nop 1':
301.795151 task-clock (msec) # 0.998 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
2 page-faults # 0.007 K/sec
1,003,144,430 cycles # 3.324 GHz
4,000,410,032 instructions # 3.99 insns per cycle
1,000,071,277 branches # 3313.742 M/sec
1,649 branch-misses # 0.00% of all branches
0.302318532 seconds time elapsed
Да. Вместо 4000 000 000 инструкций и 1000 000 000 веток мы видим загадочные дополнительные 40 032 инструкции и 71 277 ветвей. Всегда есть "дополнительные" инструкции, но их количество немного варьируется - например, последующие запуски содержали 421K, 563K и 464K дополнительных инструкций соответственно. Вы можете запустить это самостоятельно в своей системе, создав мой простой проект на github.
Итак, вы можете догадаться, что эти несколько сотен тысяч дополнительных инструкций являются просто фиксированными настройками приложения и затратами на демонтаж (настройка пользовательского пространства очень мала, но могут быть скрытые вещи). Давай попробуем для n=10 billion затем:
~/dev/perf-test$ perf stat ./perf-test-nop 10
Performance counter stats for './perf-test-nop 10':
2907.748482 task-clock (msec) # 1.000 CPUs utilized
3 context-switches # 0.001 K/sec
0 cpu-migrations # 0.000 K/sec
2 page-faults # 0.001 K/sec
10,012,820,060 cycles # 3.443 GHz
40,004,878,385 instructions # 4.00 insns per cycle
10,001,036,040 branches # 3439.443 M/sec
4,960 branch-misses # 0.00% of all branches
2.908176097 seconds time elapsed
Теперь есть ~4,9 миллиона дополнительных инструкций, примерно в 10 раз больше, чем прежде, пропорционально увеличению числа циклов в 10 раз.
Вы можете попробовать различные счетчики - все связанные с CPU показывают одинаковые пропорциональные увеличения. Давайте сосредоточимся на подсчете команд, чтобы все было просто. С использованием :u а также :k Суффиксы для измерения количества пользователей и ядра, соответственно, показывают, что подсчеты, произведенные в ядре, учитывают почти все дополнительные события:
~/dev/perf-test$ perf stat -e instructions:u,instructions:k ./perf-test-nop 1
Performance counter stats for './perf-test-nop 1':
4,000,000,092 instructions:u
388,958 instructions:k
0.301323626 seconds time elapsed
Бинго. Из 389 050 дополнительных инструкций полностью 99,98% из них (388 958) были получены в ядре.
Хорошо, но где это нас покидает? Это тривиальный цикл, связанный с процессором. Он не выполняет никаких системных вызовов и не обращается к памяти (что может косвенно вызывать ядро через механизм сбоя страницы). Почему ядро выполняет инструкции от имени моего приложения?
Похоже, что это не вызвано переключением контекста или миграцией процессора, поскольку они равны нулю или близки к нему, и в любом случае дополнительный счетчик команд не коррелирует с запусками, в которых произошло больше этих событий.
Количество дополнительных инструкций ядра на самом деле очень гладкое с количеством циклов. Вот диаграмма (миллиарды) итераций цикла в сравнении с инструкциями ядра:
Вы можете видеть, что отношения в значительной степени идеально линейны - фактически до 15e9 итераций есть только один выброс. После этого, кажется, есть две отдельные строки, предполагающие некоторое квантование того, что вызывает избыточное время. В любом случае вы получаете около 350K инструкций ядра для каждых 1e9 инструкций, выполняемых в основном цикле.
Наконец, я заметил, что количество выполненных инструкций ядра кажется пропорциональным времени выполнения 1 (или времени ЦП), а не выполненным инструкциям. Чтобы проверить это, я использую аналогичную программу, но с одним из nop инструкции заменены на idiv с задержкой около 40 циклов (некоторые неинтересные строки удалены):
~/dev/perf-test$ perf stat ./perf-test-div 10
Performance counter stats for './perf-test-div 10':
41,768,314,396 cycles # 3.430 GHz
4,014,826,989 instructions # 0.10 insns per cycle
1,002,957,543 branches # 82.369 M/sec
12.177372636 seconds time elapsed
Здесь нам потребовалось ~42e9 циклов для выполнения 1e9 итераций, и у нас было ~14 800 000 дополнительных инструкций. Это сопоставимо только с ~400 000 дополнительных инструкций для тех же циклов 1e9 с nop, Если мы сравним с nop цикл, который занимает примерно столько же cycles (40e9 итераций) мы видим почти такое же количество дополнительных инструкций:
~/dev/perf-test$ perf stat ./perf-test-nop 41
Performance counter stats for './perf-test-nop 41':
41,145,332,629 cycles # 3.425
164,013,912,324 instructions # 3.99 insns per cycle
41,002,424,948 branches # 3412.968 M/sec
12.013355313 seconds time elapsed
Что за таинственная работа, происходящая в ядре?
1 Здесь я использую термины "время" и "циклы" более или менее взаимозаменяемо. Во время этих тестов процессор не работает, поэтому по модулю некоторых тепловых эффектов, связанных с турбонаддувом, циклы прямо пропорциональны времени.
1 ответ
TL;DR
Ответ довольно прост. Ваши счетчики настроены на счет как в режиме пользователя, так и в режиме ОС , а ваши измерения периодически нарушаются планировщиком квантования времени в Linux, который работает несколько раз в секунду.
К счастью для вас, во время исследования несвязанной проблемы с @PeterCordes 5 дней назад я опубликовал очищенную версию своего собственного программного обеспечения для доступа к счетчику производительности, libpfc,
libpfc
libpfc является библиотекой очень низкого уровня и загружаемым модулем ядра Linux, которую я сам кодировал, используя только полное руководство Intel для разработчиков программного обеспечения в качестве справочного материала. Функция подсчета производительности описана в томе 3 главы 18-19 SDM. Он настраивается путем записи определенных значений в конкретные MSR (регистры, зависящие от модели), присутствующие в некоторых процессорах x86.
На моем процессоре Intel Haswell можно настроить счетчики двух типов:
Счетчики с фиксированной функцией. Они ограничены подсчетом события определенного типа. Их можно включить или отключить, но то, что они отслеживают, изменить нельзя. На 2,4 ГГц Haswell i7-4700MQ их 3:
- Выпущенные инструкции: что написано на банке.
- Unhalted Core Cycles: количество тактов, которые действительно произошли. Если частота процессора увеличивается или уменьшается, этот счетчик начнет считать быстрее или медленнее, соответственно, за единицу времени.
- Unhalted Reference Cycles: количество тактов, тикающих с постоянной частотой, не зависящих от динамического масштабирования частоты. На моем процессоре 2,4 ГГц он работает точно на частоте 2,4 ГГц. Следовательно,
Unhalted Reference / 2.4e9дает точность с точностью до наносекунды, иUnhalted Core / Unhalted Referenceдает средний коэффициент ускорения, который вы получили от Turbo Boost.
Счетчики общего назначения. Обычно их можно настроить для отслеживания любого события (с несколькими ограничениями), которое указано в SDM для вашего конкретного процессора. Что касается Haswell, они в настоящее время перечислены в томе 3, §19.4 тома SDM, а мой репозиторий содержит демонстрацию:
pfcdemo, который обращается к большому подмножеству из них. Они перечислены вpfcdemo.c:169, На моем процессоре Haswell, когда включена поддержка HyperThreading, каждое ядро имеет 4 таких счетчика.
Правильная настройка счетчиков
Чтобы настроить счетчики, я взял на себя бремя программирования каждой MSR в своем LKM, pfc.ko, чей исходный код включен в мой репозиторий.
Программирование MSR должно выполняться очень тщательно, иначе процессор накажет вас паникой ядра. По этой причине я ознакомился с каждым битом из 5 различных типов MSR, в дополнение к самим счетчикам общего назначения и счетчикам с фиксированными функциями. Мои записи об этих регистрах pfckmod.c:750 и воспроизводятся здесь:
/** 186+x IA32_PERFEVTSELx - Performance Event Selection, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {................................################################}
* | |||||||||| || |
* Counter Mask -----------------------------------^^^^^^^^||||||||| || |
* Invert Counter Mask ------------------------------------^|||||||| || |
* Enable Counter ------------------------------------------^||||||| || |
* AnyThread ------------------------------------------------^|||||| || |
* APIC Interrupt Enable -------------------------------------^||||| || |
* Pin Control ------------------------------------------------^|||| || |
* Edge Detect -------------------------------------------------^||| || |
* Operating System Mode ----------------------------------------^|| || |
* User Mode -----------------------------------------------------^| || |
* Unit Mask (UMASK) ----------------------------------------------^^^^^^^^| |
* Event Select -----------------------------------------------------------^^^^^^^^
*/
/** 309+x IA32_FIXED_CTRx - Fixed-Function Counter, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {????????????????????????????????????????????????????????????????}
* | |
* Counter Value --^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
*
* NB: Number of FF counters determined by CPUID.0x0A.EDX[ 4: 0]
* NB: ???? FF counter bitwidth determined by CPUID.0x0A.EDX[12: 5]
*/
/** 38D IA32_FIXED_CTR_CTRL - Fixed Counter Controls, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {....................................................############}
* | || |||||
* IA32_FIXED_CTR2 controls ------------------------------------------^^^^| |||||
* IA32_FIXED_CTR1 controls ----------------------------------------------^^^^||||
* ||||
* IA32_FIXED_CTR0 controls: ||||
* IA32_FIXED_CTR0 PMI --------------------------------------------------------^|||
* IA32_FIXED_CTR0 AnyThread ---------------------------------------------------^||
* IA32_FIXED_CTR0 enable (0:Disable 1:OS 2:User 3:All) -------------------------^^
*/
/** 38E IA32_PERF_GLOBAL_STATUS - Global Overflow Status, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {###..........................###............................####}
* ||| ||| ||||
* CondChgd ----^|| ||| ||||
* OvfDSBuffer --^| ||| ||||
* OvfUncore -----^ ||| ||||
* IA32_FIXED_CTR2 Overflow -----------------^|| ||||
* IA32_FIXED_CTR1 Overflow ------------------^| ||||
* IA32_FIXED_CTR0 Overflow -------------------^ ||||
* IA32_PMC(N-1) Overflow ------------------------------------------------^|||
* .... -------------------------------------------------^||
* IA32_PMC1 Overflow --------------------------------------------------^|
* IA32_PMC0 Overflow ---------------------------------------------------^
*/
/** 38F IA32_PERF_GLOBAL_CTRL - Global Enable Controls, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {.............................###............................####}
* ||| ||||
* IA32_FIXED_CTR2 enable ----------------------^|| ||||
* IA32_FIXED_CTR1 enable -----------------------^| ||||
* IA32_FIXED_CTR0 enable ------------------------^ ||||
* IA32_PMC(N-1) enable -----------------------------------------------------^|||
* .... ------------------------------------------------------^||
* IA32_PMC1 enable -------------------------------------------------------^|
* IA32_PMC0 enable --------------------------------------------------------^
*/
/** 390 IA32_PERF_GLOBAL_OVF_CTRL - Global Overflow Control, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {###..........................###............................####}
* ||| ||| ||||
* ClrCondChgd ----^|| ||| ||||
* ClrOvfDSBuffer --^| ||| ||||
* ClrOvfUncore -----^ ||| ||||
* IA32_FIXED_CTR2 ClrOverflow -----------------^|| ||||
* IA32_FIXED_CTR1 ClrOverflow ------------------^| ||||
* IA32_FIXED_CTR0 ClrOverflow -------------------^ ||||
* IA32_PMC(N-1) ClrOverflow ------------------------------------------------^|||
* .... -------------------------------------------------^||
* IA32_PMC1 ClrOverflow --------------------------------------------------^|
* IA32_PMC0 ClrOverflow ---------------------------------------------------^
*/
/** 4C1+x IA32_A_PMCx - General-Purpose Counter, ArchPerfMon v3
*
* /63/60 /56 /48 /40 /32 /24 /16 /08 /00
* {????????????????????????????????????????????????????????????????}
* | |
* Counter Value --^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
*
* NB: Number of GP counters determined by CPUID.0x0A.EAX[15: 8]
* NB: ???? GP counter bitwidth determined by CPUID.0x0A.EAX[23:16]
*/
В частности, соблюдайте IA32_PERFEVTSELx, биты 16 (режим пользователя) и 17 (режим ОС) и IA32_FIXED_CTR_CTRL биты IA32_FIXED_CTRx enable, IA32_PERFEVTSELx настраивает счетчик общего назначения x в то время как каждая группа из 4 бит начинается с бита 4*x считая от LSB в IA32_FIXED_CTR_CTRL настраивает счетчик фиксированных функций x,
В мср IA32_PERFEVTSELx, если бит ОС очищается, пока бит пользователя установлен, счетчик будет накапливать события только в режиме пользователя и исключать события режима ядра. В мср IA32_FIXED_CTRL_CTRL каждая группа из 4 бит содержит два бита enable поле, которое, если установлено 2 (0b10) включит подсчет событий в режиме пользователя, но не в режиме ядра.
Мой LKM обеспечивает подсчет только в пользовательском режиме для счетчиков как с фиксированной, так и с общей функцией на pfckmod.c:296 а также pfckmod.c:330 соответственно.
User-Space
В пространстве пользователя пользователь настраивает счетчики (пример процесса, начиная с pfcdemo.c:98), а затем помещает код, который будет синхронизирован, используя макросы PFCSTART() а также PFCEND(), Это очень специфичные кодовые последовательности, но они имеют свою стоимость и, следовательно, дают смещенный результат, который переоценивает количество событий от таймеров. Таким образом, вы также должны позвонить pfcRemoveBias() который раз PFCSTART()/PFCEND() когда они окружают 0 инструкций, и удаляют смещение из накопленного количества.
Ваш код, под libpfc
Я взял ваш код и поместил его в pfcdemo.c:130 так, что это сейчас читаешь
/************** Hot section **************/
PFCSTART(CNT);
asm volatile(
".intel_syntax noprefix\n\t"
"mov rax, 1000000000\n\t"
".loop:\n\t"
"nop\n\t"
"dec rax\n\t"
"nop\n\t"
"jne .loop\n\t"
".att_syntax noprefix\n\t"
: /* No outputs we care about */
: /* No inputs we care about */
: "rax", "memory", "cc"
);
PFCEND (CNT);
/************ End Hot section ************/
, Я получил следующее:
Instructions Issued : 4000000086
Unhalted core cycles : 1001668898
Unhalted reference cycles : 735432000
uops_issued.any : 4000261487
uops_issued.any<1 : 2445188
uops_issued.any>=1 : 1000095148
uops_issued.any>=2 : 1000070454
Instructions Issued : 4000000084
Unhalted core cycles : 1002792358
Unhalted reference cycles : 741096720
uops_issued.any>=3 : 1000057533
uops_issued.any>=4 : 1000044117
uops_issued.any>=5 : 0
uops_issued.any>=6 : 0
Instructions Issued : 4000000082
Unhalted core cycles : 1011149969
Unhalted reference cycles : 750048048
uops_executed_port.port_0 : 374577796
uops_executed_port.port_1 : 227762669
uops_executed_port.port_2 : 1077
uops_executed_port.port_3 : 2271
Instructions Issued : 4000000088
Unhalted core cycles : 1006474726
Unhalted reference cycles : 749845800
uops_executed_port.port_4 : 3436
uops_executed_port.port_5 : 438401716
uops_executed_port.port_6 : 1000083071
uops_executed_port.port_7 : 1255
Instructions Issued : 4000000082
Unhalted core cycles : 1009164617
Unhalted reference cycles : 756860736
resource_stalls.any : 1365
resource_stalls.rs : 0
resource_stalls.sb : 0
resource_stalls.rob : 0
Instructions Issued : 4000000083
Unhalted core cycles : 1007578976
Unhalted reference cycles : 755945832
uops_retired.all : 4000097703
uops_retired.all<1 : 8131817
uops_retired.all>=1 : 1000053694
uops_retired.all>=2 : 1000023800
Instructions Issued : 4000000088
Unhalted core cycles : 1015267723
Unhalted reference cycles : 756582984
uops_retired.all>=3 : 1000021575
uops_retired.all>=4 : 1000011412
uops_retired.all>=5 : 1452
uops_retired.all>=6 : 0
Instructions Issued : 4000000086
Unhalted core cycles : 1013085918
Unhalted reference cycles : 758116368
inst_retired.any_p : 4000000086
inst_retired.any_p<1 : 13696825
inst_retired.any_p>=1 : 1000002589
inst_retired.any_p>=2 : 1000000132
Instructions Issued : 4000000083
Unhalted core cycles : 1004281248
Unhalted reference cycles : 745031496
inst_retired.any_p>=3 : 999997926
inst_retired.any_p>=4 : 999997925
inst_retired.any_p>=5 : 0
inst_retired.any_p>=6 : 0
Instructions Issued : 4000000086
Unhalted core cycles : 1018752394
Unhalted reference cycles : 764101152
idq_uops_not_delivered.core : 71912269
idq_uops_not_delivered.core<1 : 1001512943
idq_uops_not_delivered.core>=1 : 17989688
idq_uops_not_delivered.core>=2 : 17982564
Instructions Issued : 4000000081
Unhalted core cycles : 1007166725
Unhalted reference cycles : 755495952
idq_uops_not_delivered.core>=3 : 6848823
idq_uops_not_delivered.core>=4 : 6844506
rs_events.empty : 0
idq.empty : 6940084
Instructions Issued : 4000000088
Unhalted core cycles : 1012633828
Unhalted reference cycles : 758772576
idq.mite_uops : 87578573
idq.dsb_uops : 56640
idq.ms_dsb_uops : 0
idq.ms_mite_uops : 168161
Instructions Issued : 4000000088
Unhalted core cycles : 1013799250
Unhalted reference cycles : 758772144
idq.mite_all_uops : 101773478
idq.mite_all_uops<1 : 988984583
idq.mite_all_uops>=1 : 25470706
idq.mite_all_uops>=2 : 25443691
Instructions Issued : 4000000087
Unhalted core cycles : 1009164246
Unhalted reference cycles : 758774400
idq.mite_all_uops>=3 : 16246335
idq.mite_all_uops>=4 : 16239687
move_elimination.int_not_eliminated : 0
move_elimination.simd_not_eliminated : 0
Instructions Issued : 4000000089
Unhalted core cycles : 1018530294
Unhalted reference cycles : 763961712
lsd.uops : 3863703268
lsd.uops<1 : 53262230
lsd.uops>=1 : 965925817
lsd.uops>=2 : 965925817
Instructions Issued : 4000000082
Unhalted core cycles : 1012124380
Unhalted reference cycles : 759399384
lsd.uops>=3 : 978583021
lsd.uops>=4 : 978583021
ild_stall.lcp : 0
ild_stall.iq_full : 863
Instructions Issued : 4000000087
Unhalted core cycles : 1008976349
Unhalted reference cycles : 758008488
br_inst_exec.all_branches : 1000009401
br_inst_exec.0x81 : 1000009400
br_inst_exec.0x82 : 0
icache.misses : 168
Instructions Issued : 4000000084
Unhalted core cycles : 1010302763
Unhalted reference cycles : 758333856
br_misp_exec.all_branches : 2
br_misp_exec.0x81 : 1
br_misp_exec.0x82 : 0
fp_assist.any : 0
Instructions Issued : 4000000082
Unhalted core cycles : 1008514841
Unhalted reference cycles : 757761792
cpu_clk_unhalted.core_clk : 1008510494
cpu_clk_unhalted.ref_xclk : 31573233
baclears.any : 0
idq.ms_uops : 164093
Больше никаких накладных расходов! Из счетчиков фиксированных функций (например, последнего набора распечаток) вы можете видеть, что МПК 4000000082 / 1008514841, что составляет около 4 МПК, от 757761792 / 2.4e9 что код занял 0,31573408 секунд, а из 1008514841 / 757761792 = 1.330912763941521, что ядро было Turbo Boosting до 133% от 2,4 ГГц или 3,2 ГГц.