Hi all My environment Machine: intel-x86-64 with 4 cores Linux Kernel: 5.10.0 Rootfs: using yocto(kirkstone) plus meta-intel layer, build a rootfs with xfce Lttng : lttng (LTTng Trace Control) 2.13.8 rt-tests: v2.7 [https://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git/] My steps: prepare 1. isolate the cpu 3 (form 0-3) 2. kernel boot: [ isolcpus=3 skew_tick=1 rcu_nocbs=3 idle=poll irqaffinity=0,1 nowatchdog nohz_full=3 rcu_nocb_poll=3 processor.max_cstate=0 ] 3. lttng lttng create lttng enable-event --kernel --all lttng add-context --kernel --type=pid lttng start 4. cyclictest -a3 -p90 -i1000 --policy=fifo --latency=0 -d0 -D 30m [running on cpu 3] at first, the output was： ------------------------------------------------------------------------------------------------------------------ root@wanghuo:~# cyclictest -a3 -p90 -i1000 --policy=fifo --latency=0 -d0 -D 30m # /dev/cpu_dma_latency set to 0us policy: fifo: loadavg: 0.28 0.06 0.02 1/275 3560 T: 0 ( 3559) P:90 I:1000 C: 3940 Min: 3 Act: 3 Avg: 3 Max: 5 ------------------------------------------------------------------------------------------------------------------ 5. on other side, before switch graphic windows, record time: root@wanghuo:~# date +"%H:%M:%S.%N" 13:27:45.066881975 ** On keyboard: Alt+tab switch graphic window [in my case: two xfce terminal window] ** Above cyclictest become the following: ------------------------------------------------------------------------------------------------------------------ root@wanghuo:~# cyclictest -a3 -p90 -i1000 --policy=fifo --latency=0 -d0 -D 30m # /dev/cpu_dma_latency set to 0us policy: fifo: loadavg: 1.82 0.65 0.24 2/278 3580 T: 0 ( 3559) P:90 I:1000 C: 106182 Min: 3 Act: 3 Avg: 3 Max: 19 ------------------------------------------------------------------------------------------------------------------ Ctrl + C terminal the the cyclictest, record time: root@wanghuo:~# date +"%H:%M:%S.%N" 13:27:50.352793751 So the cyclictest latency become high between: 13:27:45.066881975 - 13:27:50.352793751 6. lttng stop 7. lttng-schedtop analyse the result： lttng-schedtop --cpu 3 --limit 15 --procname cyclictest lttng-traces/auto-20240718-132132/ output: ------------------------------------------------------------------------------------------------------------------ root@wanghuo:~# lttng-schedtop --cpu 3 --limit 15 --procname cyclictest lttng-traces/auto-20240718-132132/ Checking the trace for lost events... Warning: progressbar module not available, using --no-progress. Timerange: [2024-07-18 13:25:56.676039486, 2024-07-18 13:28:10.507314182] Scheduling top Wakeup Switch Latency (us) Priority CPU Wakee Waker [13:26:08.547304577, 13:26:08.547339024] 34.447 20 3 cyclictest (3559) cyclictest (3558) [13:27:48.027388352, 13:27:48.027401140] 12.788 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:45.496388132, 13:27:45.496398962] 10.830 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:52.724388253, 13:27:52.724398485] 10.232 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:47.892391804, 13:27:47.892400202] 8.398 -91 3 cyclictest (3559) Unknown (N/A) [13:27:46.363171892, 13:27:46.363179359] 7.467 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:46.646020129, 13:27:46.646027581] 7.452 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:47.926391872, 13:27:47.926397774] 5.902 -91 3 cyclictest (3559) cyclictest (3558) [13:26:55.787340266, 13:26:55.787345656] 5.390 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:47.976880846, 13:27:47.976886138] 5.292 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:26:11.349340471, 13:26:11.349345733] 5.262 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:35.911339881, 13:27:35.911345135] 5.254 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:28:00.132341317, 13:28:00.132346562] 5.245 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:00.000341299, 13:27:00.000346504] 5.205 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:46.444124979, 13:27:46.444129682] 4.703 20 3 cyclictest (3558) ksoftirqd/3 (30) ------------------------------------------------------------------------------------------------------------------ 8. according to above operation time interval ： 13:27:45.066881975 - 13:27:50.352793751 the bigger latency 12.788, 10.830, 8.398 shotted ------------------------------------------------------------------------------------------------------------------ [13:27:48.027388352, 13:27:48.027401140] 12.788 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:45.496388132, 13:27:45.496398962] 10.830 20 3 cyclictest (3558) ksoftirqd/3 (30) [13:27:47.892391804, 13:27:47.892400202] 8.398 -91 3 cyclictest (3559) Unknown (N/A) ------------------------------------------------------------------------------------------------------------------ The third was cyclictest child process [pid: 3559 ]: 8.398 [13:27:47.892391804, 13:27:47.892400202], print the kernel event between that time: ------------------------------------------------------------------------------------------------------------------ [13:27:47.892391804] (+0.000000922) wanghuo sched_waking: { cpu_id = 3 }, { pid = 0 }, { comm = "cyclictest", tid = 3559, prio = -91, target_cpu = 3 } [13:27:47.892394602] (+0.000000989) wanghuo sched_wakeup: { cpu_id = 3 }, { pid = 0 }, { comm = "cyclictest", tid = 3559, prio = -91, target_cpu = 3 } [13:27:47.892394927] (+0.000000325) wanghuo timer_hrtimer_expire_exit: { cpu_id = 3 }, { pid = 0 }, { hrtimer = 0xFFFFAC844128FE78 } [13:27:47.892395159] (+0.000000232) wanghuo x86_irq_vectors_local_timer_exit: { cpu_id = 3 }, { pid = 0 }, { vector = 236 } [13:27:47.892396194] (+0.000001035) wanghuo power_cpu_idle: { cpu_id = 3 }, { pid = 0 }, { state = 4294967295, cpu_id = 3 } [13:27:47.892398345] (+0.000002151) wanghuo rcu_utilization: { cpu_id = 3 }, { pid = 0 }, { s = "Start context switch" } [13:27:47.892398828] (+0.000000483) wanghuo rcu_utilization: { cpu_id = 3 }, { pid = 0 }, { s = "End context switch" } [13:27:47.892400202] (+0.000001374) wanghuo sched_switch: { cpu_id = 3 }, { pid = 0 }, { prev_comm = "swapper/3", prev_tid = 0, prev_prio = 20, prev_state = 0, next_comm = "cyclictest", next_tid = 3559, next_prio = -91 } ------------------------------------------------------------------------------------------------------------------ compare a normal low latency cyclictest child process ------------------------------------------------------------------------------------------------------------------ [13:26:13.630390278] (+0.000000209) wanghuo sched_waking: { cpu_id = 3 }, { pid = 0 }, { comm = "cyclictest", tid = 3559, prio = -91, target_cpu = 3 } [13:26:13.630390610] (+0.000000332) wanghuo sched_wakeup: { cpu_id = 3 }, { pid = 0 }, { comm = "cyclictest", tid = 3559, prio = -91, target_cpu = 3 } [13:26:13.630390839] (+0.000000229) wanghuo timer_hrtimer_expire_exit: { cpu_id = 3 }, { pid = 0 }, { hrtimer = 0xFFFFAC844128FE78 } [13:26:13.630391080] (+0.000000241) wanghuo x86_irq_vectors_local_timer_exit: { cpu_id = 3 }, { pid = 0 }, { vector = 236 } [13:26:13.630392852] (+0.000001772) wanghuo power_cpu_idle: { cpu_id = 3 }, { pid = 0 }, { state = 4294967295, cpu_id = 3 } [13:26:13.630393057] (+0.000000205) wanghuo rcu_utilization: { cpu_id = 3 }, { pid = 0 }, { s = "Start context switch" } [13:26:13.630393245] (+0.000000188) wanghuo rcu_utilization: { cpu_id = 3 }, { pid = 0 }, { s = "End context switch" } [13:26:13.630393524] (+0.000000279) wanghuo sched_switch: { cpu_id = 3 }, { pid = 0 }, { prev_comm = "swapper/3", prev_tid = 0, prev_prio = 20, prev_state = 0, next_comm = "cyclictest", next_tid = 3559, next_prio = -91 } ------------------------------------------------------------------------------------------------------------------ The two compare show : when switch graphic windows case sched_waking 209 to 922 sched_wakeup 332 to 989 rcu_utilization 205 to 2151 sched_switch 279 to 1374 increasing high. Is my thinking right? If I am right, the cyclictest runing on core 3 , which isolate form irq, userspace application, why above function affected? Thanks dengke
