I am debugging a program with performance problem when running with chrt -r 90.
I think(not sure) the problem lies in that the thread running with chrt -r 90 has been give less cpu cycles. And I simply the program into a simple busy loop.
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <errno.h>
int main(void)
{
// Run an endless dummy loop until the launcher kills us
while (1)
;
return 0;
}
running on isolated cpu cores with these two commands:
taskset -c 122 chrt -r 90 nice --19 ./user_loop
taskset -c 125 nice --19 ./user_loop
and I perf this two threads with
perf stat -e task-clock,cycles,instructions,cache-references,cache-misses,bus-cycles,L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores,LLC-loads,LLC-load-misses,LLC-stores,LLC-prefetches -t <tid_on_core122> sleep 20
perf stat -e task-clock,cycles,instructions,cache-references,cache-misses,bus-cycles,L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores,LLC-loads,LLC-load-misses,LLC-stores,LLC-prefetches -t <tid_on_core125> sleep 20
at the same time, and here is the results:
Performance counter stats for thread id '<tid_core122>':
18,997.41 msec task-clock # 0.950 CPUs utilized
66,387,412,459 cycles # 3.495 GHz (27.28%)
132,715,755,126 instructions # 2.00 insn per cycle (36.36%)
136,227 cache-references # 7.171 K/sec (45.46%)
45,375 cache-misses # 33.308 % of all cache refs (54.55%)
474,256,275 bus-cycles # 24.964 M/sec (63.64%)
4,975,636 L1-dcache-loads # 261.911 K/sec (72.73%)
82,838 L1-dcache-load-misses # 1.66% of all L1-dcache accesses (81.82%)
3,281,173 L1-dcache-stores # 172.717 K/sec (81.81%)
45,069 LLC-loads # 2.372 K/sec (81.82%)
11,266 LLC-load-misses # 25.00% of all LL-cache accesses (36.37%)
2,062 LLC-stores # 108.541 /sec (18.18%)
<not supported> LLC-prefetches
20.000862143 seconds time elapsed
and
Performance counter stats for thread id '<tid_core125>':
19,996.27 msec task-clock # 1.000 CPUs utilized
69,872,970,491 cycles # 3.494 GHz (27.26%)
139,674,386,688 instructions # 2.00 insn per cycle (36.36%)
169,942 cache-references # 8.499 K/sec (45.45%)
42,055 cache-misses # 24.747 % of all cache refs (54.55%)
499,168,196 bus-cycles # 24.963 M/sec (63.65%)
10,195,820 L1-dcache-loads # 509.886 K/sec (72.75%)
178,431 L1-dcache-load-misses # 1.75% of all L1-dcache accesses (81.84%)
6,456,485 L1-dcache-stores # 322.885 K/sec (81.84%)
56,191 LLC-loads # 2.810 K/sec (81.84%)
14,375 LLC-load-misses # 25.58% of all LL-cache accesses (36.33%)
2,153 LLC-stores # 107.670 /sec (18.16%)
<not supported> LLC-prefetches
20.000855824 seconds time elapsed
you can clearly see that a ratio of cycles of two tids 66,404,579,739/ 69,874,789,188 = 0.95 and this behaviour is very stable.
Isn't that chrt -r 90 give the thread a RT(real time) kernel scheduler policy thus more cpu cycles and less interrupts or context switch leading to better performance?
Why it that happenning? Or what tools can I use to debug it?
this machine has two NUMA node, 128 logical cores, 64 physical cores, isolated cpus [109,127], Ubuntu 20.04.6 LTS, nohz_full not supported. Here is the cpuinfo
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
Address sizes: 46 bits physical, 57 bits virtual
CPU(s): 128
On-line CPU(s) list: 0-127
Thread(s) per core: 2
Core(s) per socket: 32
Socket(s): 2
NUMA node(s): 2
Vendor ID: GenuineIntel
CPU family: 6
Model: 106
Model name: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
Stepping: 6
Frequency boost: enabled
CPU MHz: 3499.990
CPU max MHz: 2901.0000
CPU min MHz: 800.0000
BogoMIPS: 5800.00
Virtualization: VT-x
L1d cache: 3 MiB
L1i cache: 2 MiB
L2 cache: 80 MiB
L3 cache: 108 MiB
NUMA node0 CPU(s): 0-31,64-95
NUMA node1 CPU(s): 32-63,96-127
Vulnerability Gather data sampling: Mitigation; Microcode
Vulnerability Itlb multihit: Not affected
Vulnerability L1tf: Not affected
Vulnerability Mds: Not affected
Vulnerability Meltdown: Not affected
Vulnerability Mmio stale data: Mitigation; Clear CPU buffers; SMT vulnerable
Vulnerability Reg file data sampling: Not affected
Vulnerability Retbleed: Not affected
Vulnerability Spec rstack overflow: Not affected
Vulnerability Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl and seccomp
Vulnerability Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2: Mitigation; Enhanced / Automatic IBRS; IBPB conditional; RSB filling; PBRSB-eIBRS SW
sequence; BHI SW loop, KVM SW loop
Vulnerability Srbds: Not affected
Vulnerability Tsx async abort: Not affected
Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts
acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art ar
ch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulq
dq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4
_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm a
bm 3dnowprefetch cpuid_fault epb cat_l3 invpcid_single intel_ppin ssbd mba ibrs ibpb
stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjus
t bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a avx512f avx512dq rdseed adx smap avx512
ifma clflushopt clwb intel_pt avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xget
bv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local split_lock_detect wbnoi
nvd dtherm ida arat pln pts hwp hwp_act_window hwp_epp hwp_pkg_req avx512vbmi umip p
ku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg tme avx512_vpop
cntdq la57 rdpid fsrm md_clear pconfig flush_l1d arch_capabilities
I also trid with ftrade to monitor the scheduling and irq with
TRACING=/sys/kernel/debug/tracing/
echo 0 > $TRACING/tracing_on
echo > $TRACING/trace
echo 1 > $TRACING/events/sched/sched_switch/enable
echo 1 > $TRACING/events/irq_vectors/enable
echo 1 > $TRACING/tracing_on
sleep 20
echo 0 > $TRACING/tracing_on
cat $TRACING/per_cpu/cpu122/trace > tlog122
However, the log seems that on core122 there is less disturbance
user_loop-3532281 [122] d.h.. 3175054.401883: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.401886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.405884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.405885: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.409884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.409886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.413884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.413885: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.417884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.417885: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.421884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.421885: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.425884: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.425885: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.429885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.429888: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.433885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.433886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.437885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.437886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.441885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.441886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.445885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.445888: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.449885: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.449888: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.453886: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.453886: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.457886: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.457887: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.461886: local_timer_entry: vector=236
user_loop-3532281 [122] dNh.. 3175054.461888: local_timer_exit: vector=236
user_loop-3532281 [122] d.... 3175054.461891: sched_switch: prev_comm=user_loop prev_pid=3532281 prev_prio=9 prev_
state=R ==> next_comm=swapper/122 next_pid=0 next_prio=120
<idle>-0 [122] d.h.. 3175054.461892: irq_work_entry: vector=246
<idle>-0 [122] dNh.. 3175054.461893: irq_work_exit: vector=246
<idle>-0 [122] d.... 3175054.461894: sched_switch: prev_comm=swapper/122 prev_pid=0 prev_prio=120 prev_st
ate=R ==> next_comm=kworker/122:1 next_pid=971 next_prio=120
kworker/122:1-971 [122] d.... 3175054.461895: sched_switch: prev_comm=kworker/122:1 prev_pid=971 prev_prio=120 pre
v_state=I ==> next_comm=swapper/122 next_pid=0 next_prio=120
<idle>-0 [122] d.... 3175054.514503: sched_switch: prev_comm=swapper/122 prev_pid=0 prev_prio=120 prev_st
ate=R ==> next_comm=user_loop next_pid=3532281 next_prio=9
user_loop-3532281 [122] d.h.. 3175054.517888: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.517890: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.521888: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.521889: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.525888: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.525889: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.529889: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.529890: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.533889: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.533889: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.537889: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.537890: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.541890: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.541891: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.545889: local_timer_entry: vector=236
user_loop-3532281 [122] d.h.. 3175054.545890: local_timer_exit: vector=236
user_loop-3532281 [122] d.h.. 3175054.549889: local_timer_entry: vector=236
:
ftrace log lon core125
user_loop-3536540 [125] d.h.. 3175053.565852: irq_work_entry: vector=246
user_loop-3536540 [125] dNh.. 3175053.565852: irq_work_exit: vector=246
user_loop-3536540 [125] d.... 3175053.565853: sched_switch: prev_comm=user_loop prev_pid=3536540 prev_prio=101 prev
_state=R ==> next_comm=kworker/125:1 next_pid=974 next_prio=120
kworker/125:1-974 [125] d.... 3175053.565853: sched_switch: prev_comm=kworker/125:1 prev_pid=974 prev_prio=120 prev
_state=I ==> next_comm=user_loop next_pid=3536540 next_prio=101
user_loop-3536540 [125] d.h.. 3175053.569850: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.569851: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.573850: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.573852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.577851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.577852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.577852: irq_work_entry: vector=246
user_loop-3536540 [125] dNh.. 3175053.577853: irq_work_exit: vector=246
user_loop-3536540 [125] d.... 3175053.577854: sched_switch: prev_comm=user_loop prev_pid=3536540 prev_prio=101 prev
_state=R ==> next_comm=kworker/125:1 next_pid=974 next_prio=120
kworker/125:1-974 [125] d.... 3175053.577856: sched_switch: prev_comm=kworker/125:1 prev_pid=974 prev_prio=120 prev
_state=I ==> next_comm=user_loop next_pid=3536540 next_prio=101
user_loop-3536540 [125] d.h.. 3175053.581851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.581852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.585851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.585852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.589851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.589852: local_timer_exit: vector=236
user_loop-3536540 [125] d.H.. 3175053.589852: irq_work_entry: vector=246
user_loop-3536540 [125] dNH.. 3175053.589853: irq_work_exit: vector=246
user_loop-3536540 [125] d.... 3175053.589854: sched_switch: prev_comm=user_loop prev_pid=3536540 prev_prio=101 prev
_state=R ==> next_comm=kworker/125:1 next_pid=974 next_prio=120
kworker/125:1-974 [125] d.... 3175053.589854: sched_switch: prev_comm=kworker/125:1 prev_pid=974 prev_prio=120 prev
_state=I ==> next_comm=user_loop next_pid=3536540 next_prio=101
user_loop-3536540 [125] d.h.. 3175053.593851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.593852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.597851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.597852: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.601851: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.601853: local_timer_exit: vector=236
user_loop-3536540 [125] d.H.. 3175053.601853: irq_work_entry: vector=246
user_loop-3536540 [125] dNH.. 3175053.601854: irq_work_exit: vector=246
user_loop-3536540 [125] d.... 3175053.601854: sched_switch: prev_comm=user_loop prev_pid=3536540 prev_prio=101 prev
_state=R ==> next_comm=kworker/125:1 next_pid=974 next_prio=120
kworker/125:1-974 [125] d.... 3175053.601855: sched_switch: prev_comm=kworker/125:1 prev_pid=974 prev_prio=120 prev
_state=I ==> next_comm=user_loop next_pid=3536540 next_prio=101
user_loop-3536540 [125] d.h.. 3175053.605852: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.605854: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.609852: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.609853: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.613852: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.613853: local_timer_exit: vector=236
user_loop-3536540 [125] d.H.. 3175053.613854: irq_work_entry: vector=246
user_loop-3536540 [125] dNH.. 3175053.613854: irq_work_exit: vector=246
user_loop-3536540 [125] d.... 3175053.613855: sched_switch: prev_comm=user_loop prev_pid=3536540 prev_prio=101 prev
_state=R ==> next_comm=kworker/125:1 next_pid=974 next_prio=120
kworker/125:1-974 [125] d.... 3175053.613855: sched_switch: prev_comm=kworker/125:1 prev_pid=974 prev_prio=120 prev
_state=I ==> next_comm=user_loop next_pid=3536540 next_prio=101
user_loop-3536540 [125] d.h.. 3175053.617852: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.617855: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.621852: local_timer_entry: vector=236
user_loop-3536540 [125] d.h.. 3175053.621855: local_timer_exit: vector=236
user_loop-3536540 [125] d.h.. 3175053.625852: local_timer_entry: vector=236
:
hostnamectl:
Icon name: computer-server
Chassis: server
Machine ID:
Boot ID:
Operating System: Ubuntu 20.04.6 LTS
Kernel: Linux 5.15.0-1077-aws
Architecture: x86-64
uname -a:
Linux ip-xxxx 5.15.0-1077-aws #84~20.04.1-Ubuntu SMP Mon Jan 20 22:14:54 UTC 2025 x86_64 x86_64 x86_64 GNU/Linux