* [Question] Possible scheduler regression: occasional ~3ms wake-up to sched-switch delay in cyclictest on kernel 6.6 and 6.12
@ 2026-04-30 2:56 Jiping Ma
2026-04-30 3:20 ` K Prateek Nayak
0 siblings, 1 reply; 3+ messages in thread
From: Jiping Ma @ 2026-04-30 2:56 UTC (permalink / raw)
To: peterz, vincent.guittot
Cc: bsegall, dietmar.eggemann, juri.lelli, kprateek.nayak,
linux-kernel, mgorman, mingo, qyousef, rostedt, vschneid
Hi,
We are running cyclictest on x86 boards with standard (non-RT) kernels and observed an occasional but significant latency spike on kernel version 6.6 and 6.12.
Issue:
During cyclictest under CPU contention, we occasionally see a ~3ms delay from wake-up to sched-switch ion kernel 6.6 and kernel 6.12. Most of the time the latency is comparable to kernel 5.15, but these sporadic spikes significantly impact the max latency. This behavior is not observed on kernel 5.15 under the same conditions.
Test setup:
Platform: x86
Kernel type: std (non-RT)
Cyclictest command: ./cyclictest -m -N --policy=SCHED_OTHER -t 1 -D 30m -a 3
CPU load: 6 instances of a pure CPU calculation shell script (cal.sh) bound to CPU 3, running in background to create contention
cal.sh (CPU stress script):
#!/bin/sh
x=1
while :; do
i=0
while [ $i -lt 100000 ]; do
x=$(( (x * 1103515245 + 12345) & 0x7fffffff ))
i=$((i + 1))
done
done
Results (max latency, ns):
Kernel cyclictest max (ns)
5.15 53,461
6.6 251,926
6.12 110,861
Key observation:
The majority of cyclictest samples show latency similar to kernel 5.15. However, there are occasional spikes where the wake-up to sched-switch gap reaches ~3ms. This suggests the scheduler is intermittently failing to preempt the running tasks promptly when the cyclictest thread wakes up. Since all tasks (cyclictest + 6x cal.sh) are SCHED_OTHER on the same CPU, this may be related to changes in the EEVDF scheduler introduced in kernel 6.6.
Questions:
1. Is this occasional preemption delay a known side effect of the EEVDF scheduler replacing CFS in kernel 6.6+?
2. Is this by design, or should it be considered a scheduler bug?
3ms delay kernel trace log:
cal.sh-917 [003] d.h2. 1667.138647: sched_waking: comm=cyclictest pid=943 prio=120 target_cpu=003
cal.sh-917 [003] d.h3. 1667.138648: sched_stat_runtime: comm=cal.sh pid=917 runtime=101740 [ns]
cal.sh-917 [003] d.h3. 1667.138649: sched_wakeup: comm=cyclictest pid=943 prio=120 target_cpu=003
cal.sh-917 [003] d.h.. 1667.138649: hrtimer_expire_exit: hrtimer=00000000c56c84b4
cal.sh-917 [003] d.h.. 1667.138649: write_msr: 6e0, value 42dd8d2cf32
cal.sh-917 [003] d.h.. 1667.138649: local_timer_exit: vector=236
cal.sh-917 [003] d.h.. 1667.139540: local_timer_entry: vector=236
cal.sh-917 [003] d.h.. 1667.139540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665335000684
cal.sh-917 [003] d.h1. 1667.139541: notifier_run: pvclock_gtod_notify [kvm]
cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: Start scheduler-tick
cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: End scheduler-tick
cal.sh-917 [003] d.h.. 1667.139542: read_msr: e8, value 4892b7c3d38
cal.sh-917 [003] d.h.. 1667.139542: read_msr: e7, value 38088ff481e
cal.sh-917 [003] d.h1. 1667.139542: sched_stat_runtime: comm=cal.sh pid=917 runtime=894430 [ns]
cal.sh-917 [003] d.h.. 1667.139543: hrtimer_expire_exit: hrtimer=000000007fd337f4
cal.sh-917 [003] d.h1. 1667.139543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665336000000 softexpires=1665336000000 mode=ABS
cal.sh-917 [003] d.h.. 1667.139543: write_msr: 6e0, value 42dd8fc30e4
cal.sh-917 [003] d.h.. 1667.139543: local_timer_exit: vector=236
cal.sh-917 [003] d.h.. 1667.140540: local_timer_entry: vector=236
cal.sh-917 [003] d.h.. 1667.140540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665336000925
cal.sh-917 [003] d.h1. 1667.140541: notifier_run: pvclock_gtod_notify [kvm]
cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: Start scheduler-tick
cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: End scheduler-tick
cal.sh-917 [003] d.h.. 1667.140542: read_msr: e8, value 4892bb18743
cal.sh-917 [003] d.h.. 1667.140542: read_msr: e7, value 380892863df
cal.sh-917 [003] d.h1. 1667.140542: sched_stat_runtime: comm=cal.sh pid=917 runtime=1000134 [ns]
cal.sh-917 [003] d.h.. 1667.140543: hrtimer_expire_exit: hrtimer=000000007fd337f4
cal.sh-917 [003] d.h1. 1667.140543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665337000000 softexpires=1665337000000 mode=ABS
cal.sh-917 [003] d.h.. 1667.140543: write_msr: 6e0, value 42dd92592a6
cal.sh-917 [003] d.h.. 1667.140544: local_timer_exit: vector=236
cal.sh-917 [003] d.h.. 1667.141540: local_timer_entry: vector=236
cal.sh-917 [003] d.h.. 1667.141540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665337000748
cal.sh-917 [003] d.h1. 1667.141541: notifier_run: pvclock_gtod_notify [kvm]
cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: Start scheduler-tick
cal.sh-917 [003] d.h.. 1667.141541: softirq_raise: vec=9 [action=RCU]
cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: End scheduler-tick
cal.sh-917 [003] d.h.. 1667.141542: read_msr: e8, value 4892be6cf1e
cal.sh-917 [003] d.h.. 1667.141542: read_msr: e7, value 38089517df9
cal.sh-917 [003] dNh1. 1667.141542: sched_stat_runtime: comm=cal.sh pid=917 runtime=999991 [ns]
cal.sh-917 [003] dNh.. 1667.141543: hrtimer_expire_exit: hrtimer=000000007fd337f4
cal.sh-917 [003] dNh1. 1667.141543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665338000000 softexpires=1665338000000 mode=ABS
cal.sh-917 [003] dNh.. 1667.141543: write_msr: 6e0, value 42dd94ef44f
cal.sh-917 [003] dNh.. 1667.141543: local_timer_exit: vector=236
cal.sh-917 [003] .Ns.. 1667.141544: softirq_entry: vec=9 [action=RCU]
cal.sh-917 [003] .Ns.. 1667.141544: rcu_utilization: Start RCU core
cal.sh-917 [003] dNs1. 1667.141544: rcu_grace_period: rcu_preempt 589121 cpuend
cal.sh-917 [003] dNs.. 1667.141544: rcu_batch_start: rcu_preempt CBs=1 bl=10
cal.sh-917 [003] dNs.. 1667.141545: rcu_segcb_stats: SegCbDequeued seglen: (DONE=0, WAIT=0, NEXT_READY=0, NEXT=0) gp_seq: (DONE=0, WAIT=589124, NEXT_READY=589124, NEXT=0)
cal.sh-917 [003] .Ns.. 1667.141545: rcu_invoke_callback: rcu_preempt rhp=00000000be314949 func=file_free_rcu
cal.sh-917 [003] .Ns.. 1667.141545: kmem_cache_free: call_site=file_free_rcu+0x35/0x60 ptr=00000000be314949 name=kmalloc-cg-256
cal.sh-917 [003] dNs.. 1667.141545: rcu_batch_end: rcu_preempt CBs-invoked=1 idle=.S..
cal.sh-917 [003] .Ns.. 1667.141545: rcu_utilization: End RCU core
cal.sh-917 [003] .Ns.. 1667.141546: softirq_exit: vec=9 [action=RCU]
cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: Start context switch
cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: End context switch
cal.sh-917 [003] dN.2. 1667.141546: sched_stat_runtime: comm=cal.sh pid=917 runtime=4083 [ns]
cal.sh-917 [003] d..2. 1667.141547: sched_switch: prev_comm=cal.sh prev_pid=917 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=943 next_prio=120
Thanks,
Jiping Ma
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: [Question] Possible scheduler regression: occasional ~3ms wake-up to sched-switch delay in cyclictest on kernel 6.6 and 6.12
2026-04-30 2:56 [Question] Possible scheduler regression: occasional ~3ms wake-up to sched-switch delay in cyclictest on kernel 6.6 and 6.12 Jiping Ma
@ 2026-04-30 3:20 ` K Prateek Nayak
2026-04-30 4:35 ` Jiping Ma
0 siblings, 1 reply; 3+ messages in thread
From: K Prateek Nayak @ 2026-04-30 3:20 UTC (permalink / raw)
To: Jiping Ma, peterz, vincent.guittot
Cc: bsegall, dietmar.eggemann, juri.lelli, linux-kernel, mgorman,
mingo, qyousef, rostedt, vschneid
Hello Jiping,
On 4/30/2026 8:26 AM, Jiping Ma wrote:
> [You don't often get email from jiping.ma2@windriver.com. Learn why this is important at https://aka.ms/LearnAboutSenderIdentification ]
>
> Hi,
>
> We are running cyclictest on x86 boards with standard (non-RT) kernels and observed an occasional but significant latency spike on kernel version 6.6 and 6.12.
>
> Issue:
> During cyclictest under CPU contention, we occasionally see a ~3ms delay from wake-up to sched-switch ion kernel 6.6 and kernel 6.12. Most of the time the latency is comparable to kernel 5.15, but these sporadic spikes significantly impact the max latency. This behavior is not observed on kernel 5.15 under the same conditions.
That seems equivalent of a base_slice so the cyclictest is perhaps
waking up with positive lag (time owed to the scheduler) and that is
the reason for that large tail latency.
>
> Test setup:
>
> Platform: x86
> Kernel type: std (non-RT)
> Cyclictest command: ./cyclictest -m -N --policy=SCHED_OTHER -t 1 -D 30m -a 3
> CPU load: 6 instances of a pure CPU calculation shell script (cal.sh) bound to CPU 3, running in background to create contention
> cal.sh (CPU stress script):
>
> #!/bin/sh
> x=1
> while :; do
> i=0
> while [ $i -lt 100000 ]; do
> x=$(( (x * 1103515245 + 12345) & 0x7fffffff ))
> i=$((i + 1))
> done
> done
>
> Results (max latency, ns):
> Kernel cyclictest max (ns)
> 5.15 53,461
> 6.6 251,926
Can you try running with:
echo NO_RUN_TO_PARITY > /sys/kernel/debug/sched/features
That should make preemption faster on v6.6.
> 6.12 110,861
At v6.12, the DELAY_DEQUEUE feature seems to have improved the tail
by decaying lag while keeping the task on the runqueue. You can
still try NO_RUN_TO_PARITY but the delay might still be close to the
granularity of the 1ms tick.
In v6.12, there is also PREEMPT_SHORT which would selectively disable
RUN_TO_PARITY if a task of shorter slice wakes up - you can also try
playing with that where you align the slice of cyclictest close to
its actual runtime.
Vincent was working on this exact same problem and there should be
a bunch of fixes lined up in v7.1-rc1 + few more being discussed in
the mailing list. In no particular order:
https://lore.kernel.org/lkml/177583163838.801717.18173795801708799547.tip-bot2@tip-bot2/
https://lore.kernel.org/lkml/177521940443.1647592.2249539659928731910.tip-bot2@tip-bot2/
https://lore.kernel.org/lkml/177736116339.3521451.16868557879769343251.tip-bot2@tip-bot2/
https://lore.kernel.org/lkml/20260429164102.1388139-1-vincent.guittot@linaro.org/
https://lore.kernel.org/lkml/20260417171642.3539914-1-vincent.guittot@linaro.org/
The commit log from first few patches should have the slice values
that Vincent was testing with.
>
> Key observation:
> The majority of cyclictest samples show latency similar to kernel 5.15. However, there are occasional spikes where the wake-up to sched-switch gap reaches ~3ms. This suggests the scheduler is intermittently failing to preempt the running tasks promptly when the cyclictest thread wakes up. Since all tasks (cyclictest + 6x cal.sh) are SCHED_OTHER on the same CPU, this may be related to changes in the EEVDF scheduler introduced in kernel 6.6.
>
> Questions:
> 1. Is this occasional preemption delay a known side effect of the EEVDF scheduler replacing CFS in kernel 6.6+?
> 2. Is this by design, or should it be considered a scheduler bug?
This is by design but there are workarounds to get around this by
setting a slice value and disabling RUN_TO_PARITY.
>
> 3ms delay kernel trace log:
> cal.sh-917 [003] d.h2. 1667.138647: sched_waking: comm=cyclictest pid=943 prio=120 target_cpu=003
> cal.sh-917 [003] d.h3. 1667.138648: sched_stat_runtime: comm=cal.sh pid=917 runtime=101740 [ns]
> cal.sh-917 [003] d.h3. 1667.138649: sched_wakeup: comm=cyclictest pid=943 prio=120 target_cpu=003
> cal.sh-917 [003] d.h.. 1667.138649: hrtimer_expire_exit: hrtimer=00000000c56c84b4
> cal.sh-917 [003] d.h.. 1667.138649: write_msr: 6e0, value 42dd8d2cf32
> cal.sh-917 [003] d.h.. 1667.138649: local_timer_exit: vector=236
> cal.sh-917 [003] d.h.. 1667.139540: local_timer_entry: vector=236
> cal.sh-917 [003] d.h.. 1667.139540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665335000684
> cal.sh-917 [003] d.h1. 1667.139541: notifier_run: pvclock_gtod_notify [kvm]
> cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: Start scheduler-tick
> cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: End scheduler-tick
> cal.sh-917 [003] d.h.. 1667.139542: read_msr: e8, value 4892b7c3d38
> cal.sh-917 [003] d.h.. 1667.139542: read_msr: e7, value 38088ff481e
> cal.sh-917 [003] d.h1. 1667.139542: sched_stat_runtime: comm=cal.sh pid=917 runtime=894430 [ns]
> cal.sh-917 [003] d.h.. 1667.139543: hrtimer_expire_exit: hrtimer=000000007fd337f4
> cal.sh-917 [003] d.h1. 1667.139543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665336000000 softexpires=1665336000000 mode=ABS
> cal.sh-917 [003] d.h.. 1667.139543: write_msr: 6e0, value 42dd8fc30e4
> cal.sh-917 [003] d.h.. 1667.139543: local_timer_exit: vector=236
> cal.sh-917 [003] d.h.. 1667.140540: local_timer_entry: vector=236
> cal.sh-917 [003] d.h.. 1667.140540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665336000925
> cal.sh-917 [003] d.h1. 1667.140541: notifier_run: pvclock_gtod_notify [kvm]
> cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: Start scheduler-tick
> cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: End scheduler-tick
> cal.sh-917 [003] d.h.. 1667.140542: read_msr: e8, value 4892bb18743
> cal.sh-917 [003] d.h.. 1667.140542: read_msr: e7, value 380892863df
> cal.sh-917 [003] d.h1. 1667.140542: sched_stat_runtime: comm=cal.sh pid=917 runtime=1000134 [ns]
> cal.sh-917 [003] d.h.. 1667.140543: hrtimer_expire_exit: hrtimer=000000007fd337f4
> cal.sh-917 [003] d.h1. 1667.140543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665337000000 softexpires=1665337000000 mode=ABS
> cal.sh-917 [003] d.h.. 1667.140543: write_msr: 6e0, value 42dd92592a6
> cal.sh-917 [003] d.h.. 1667.140544: local_timer_exit: vector=236
> cal.sh-917 [003] d.h.. 1667.141540: local_timer_entry: vector=236
> cal.sh-917 [003] d.h.. 1667.141540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665337000748
> cal.sh-917 [003] d.h1. 1667.141541: notifier_run: pvclock_gtod_notify [kvm]
> cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: Start scheduler-tick
> cal.sh-917 [003] d.h.. 1667.141541: softirq_raise: vec=9 [action=RCU]
> cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: End scheduler-tick
> cal.sh-917 [003] d.h.. 1667.141542: read_msr: e8, value 4892be6cf1e
> cal.sh-917 [003] d.h.. 1667.141542: read_msr: e7, value 38089517df9
> cal.sh-917 [003] dNh1. 1667.141542: sched_stat_runtime: comm=cal.sh pid=917 runtime=999991 [ns]
^
Since NEED_RESCHED is only set here, it is safe to assume cal.sh was
likely kept running by RUN_TO_PARITY for 3ms after it was selected which
corresponds to the default base_slice.
> cal.sh-917 [003] dNh.. 1667.141543: hrtimer_expire_exit: hrtimer=000000007fd337f4
> cal.sh-917 [003] dNh1. 1667.141543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665338000000 softexpires=1665338000000 mode=ABS
> cal.sh-917 [003] dNh.. 1667.141543: write_msr: 6e0, value 42dd94ef44f
> cal.sh-917 [003] dNh.. 1667.141543: local_timer_exit: vector=236
> cal.sh-917 [003] .Ns.. 1667.141544: softirq_entry: vec=9 [action=RCU]
> cal.sh-917 [003] .Ns.. 1667.141544: rcu_utilization: Start RCU core
> cal.sh-917 [003] dNs1. 1667.141544: rcu_grace_period: rcu_preempt 589121 cpuend
> cal.sh-917 [003] dNs.. 1667.141544: rcu_batch_start: rcu_preempt CBs=1 bl=10
> cal.sh-917 [003] dNs.. 1667.141545: rcu_segcb_stats: SegCbDequeued seglen: (DONE=0, WAIT=0, NEXT_READY=0, NEXT=0) gp_seq: (DONE=0, WAIT=589124, NEXT_READY=589124, NEXT=0)
> cal.sh-917 [003] .Ns.. 1667.141545: rcu_invoke_callback: rcu_preempt rhp=00000000be314949 func=file_free_rcu
> cal.sh-917 [003] .Ns.. 1667.141545: kmem_cache_free: call_site=file_free_rcu+0x35/0x60 ptr=00000000be314949 name=kmalloc-cg-256
> cal.sh-917 [003] dNs.. 1667.141545: rcu_batch_end: rcu_preempt CBs-invoked=1 idle=.S..
> cal.sh-917 [003] .Ns.. 1667.141545: rcu_utilization: End RCU core
> cal.sh-917 [003] .Ns.. 1667.141546: softirq_exit: vec=9 [action=RCU]
> cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: Start context switch
> cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: End context switch
> cal.sh-917 [003] dN.2. 1667.141546: sched_stat_runtime: comm=cal.sh pid=917 runtime=4083 [ns]
> cal.sh-917 [003] d..2. 1667.141547: sched_switch: prev_comm=cal.sh prev_pid=917 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=943 next_prio=120
--
Thanks and Regards,
Prateek
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: [Question] Possible scheduler regression: occasional ~3ms wake-up to sched-switch delay in cyclictest on kernel 6.6 and 6.12
2026-04-30 3:20 ` K Prateek Nayak
@ 2026-04-30 4:35 ` Jiping Ma
0 siblings, 0 replies; 3+ messages in thread
From: Jiping Ma @ 2026-04-30 4:35 UTC (permalink / raw)
To: kprateek.nayak
Cc: bsegall, dietmar.eggemann, jiping.ma2, juri.lelli, linux-kernel,
mgorman, mingo, peterz, qyousef, rostedt, vincent.guittot,
vschneid
Thanks quickly reply. The test results get well after the up command.
./cyclictest -m -N --policy=SCHED_OTHER -t 1 -D 30m -a 3
T: 0 ( 736) P: 0 I:1000 C:1776085 Min: 3135 Act: 53535 Avg: 77421 Max: 6946557
Thanks,
Jiping
>
>That should make preemption faster on v6.6.
>
>> 6.12 110,861
>
>At v6.12, the DELAY_DEQUEUE feature seems to have improved the tail
>by decaying lag while keeping the task on the runqueue. You can
>still try NO_RUN_TO_PARITY but the delay might still be close to the
>granularity of the 1ms tick.
>
>In v6.12, there is also PREEMPT_SHORT which would selectively disable
>RUN_TO_PARITY if a task of shorter slice wakes up - you can also try
>playing with that where you align the slice of cyclictest close to
>its actual runtime.
>
>Vincent was working on this exact same problem and there should be
>a bunch of fixes lined up in v7.1-rc1 + few more being discussed in
>the mailing list. In no particular order:
>
>https://lore.kernel.org/lkml/177583163838.801717.18173795801708799547.tip-bot2@tip-bot2/
>https://lore.kernel.org/lkml/177521940443.1647592.2249539659928731910.tip-bot2@tip-bot2/
>https://lore.kernel.org/lkml/177736116339.3521451.16868557879769343251.tip-bot2@tip-bot2/
>https://lore.kernel.org/lkml/20260429164102.1388139-1-vincent.guittot@linaro.org/
>https://lore.kernel.org/lkml/20260417171642.3539914-1-vincent.guittot@linaro.org/
>
>The commit log from first few patches should have the slice values
>that Vincent was testing with.
>
>>
>> Key observation:
>> The majority of cyclictest samples show latency similar to kernel 5.15. However, there are occasional spikes where the wake-up to sched-switch gap reaches ~3ms. This suggests the scheduler is intermittently failing to preempt the running tasks promptly when the cyclictest thread wakes up. Since all tasks (cyclictest + 6x cal.sh) are SCHED_OTHER on the same CPU, this may be related to changes in the EEVDF scheduler introduced in kernel 6.6.
>>
>> Questions:
>> 1. Is this occasional preemption delay a known side effect of the EEVDF scheduler replacing CFS in kernel 6.6+?
>> 2. Is this by design, or should it be considered a scheduler bug?
>
>This is by design but there are workarounds to get around this by
>setting a slice value and disabling RUN_TO_PARITY.
>
>>
>> 3ms delay kernel trace log:
>> cal.sh-917 [003] d.h2. 1667.138647: sched_waking: comm=cyclictest pid=943 prio=120 target_cpu=003
>> cal.sh-917 [003] d.h3. 1667.138648: sched_stat_runtime: comm=cal.sh pid=917 runtime=101740 [ns]
>> cal.sh-917 [003] d.h3. 1667.138649: sched_wakeup: comm=cyclictest pid=943 prio=120 target_cpu=003
>> cal.sh-917 [003] d.h.. 1667.138649: hrtimer_expire_exit: hrtimer=00000000c56c84b4
>> cal.sh-917 [003] d.h.. 1667.138649: write_msr: 6e0, value 42dd8d2cf32
>> cal.sh-917 [003] d.h.. 1667.138649: local_timer_exit: vector=236
>> cal.sh-917 [003] d.h.. 1667.139540: local_timer_entry: vector=236
>> cal.sh-917 [003] d.h.. 1667.139540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665335000684
>> cal.sh-917 [003] d.h1. 1667.139541: notifier_run: pvclock_gtod_notify [kvm]
>> cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: Start scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.139541: rcu_utilization: End scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.139542: read_msr: e8, value 4892b7c3d38
>> cal.sh-917 [003] d.h.. 1667.139542: read_msr: e7, value 38088ff481e
>> cal.sh-917 [003] d.h1. 1667.139542: sched_stat_runtime: comm=cal.sh pid=917 runtime=894430 [ns]
>> cal.sh-917 [003] d.h.. 1667.139543: hrtimer_expire_exit: hrtimer=000000007fd337f4
>> cal.sh-917 [003] d.h1. 1667.139543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665336000000 softexpires=1665336000000 mode=ABS
>> cal.sh-917 [003] d.h.. 1667.139543: write_msr: 6e0, value 42dd8fc30e4
>> cal.sh-917 [003] d.h.. 1667.139543: local_timer_exit: vector=236
>> cal.sh-917 [003] d.h.. 1667.140540: local_timer_entry: vector=236
>> cal.sh-917 [003] d.h.. 1667.140540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665336000925
>> cal.sh-917 [003] d.h1. 1667.140541: notifier_run: pvclock_gtod_notify [kvm]
>> cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: Start scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.140541: rcu_utilization: End scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.140542: read_msr: e8, value 4892bb18743
>> cal.sh-917 [003] d.h.. 1667.140542: read_msr: e7, value 380892863df
>> cal.sh-917 [003] d.h1. 1667.140542: sched_stat_runtime: comm=cal.sh pid=917 runtime=1000134 [ns]
>> cal.sh-917 [003] d.h.. 1667.140543: hrtimer_expire_exit: hrtimer=000000007fd337f4
>> cal.sh-917 [003] d.h1. 1667.140543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665337000000 softexpires=1665337000000 mode=ABS
>> cal.sh-917 [003] d.h.. 1667.140543: write_msr: 6e0, value 42dd92592a6
>> cal.sh-917 [003] d.h.. 1667.140544: local_timer_exit: vector=236
>> cal.sh-917 [003] d.h.. 1667.141540: local_timer_entry: vector=236
>> cal.sh-917 [003] d.h.. 1667.141540: hrtimer_expire_entry: hrtimer=000000007fd337f4 function=tick_sched_timer now=1665337000748
>> cal.sh-917 [003] d.h1. 1667.141541: notifier_run: pvclock_gtod_notify [kvm]
>> cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: Start scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.141541: softirq_raise: vec=9 [action=RCU]
>> cal.sh-917 [003] d.h.. 1667.141541: rcu_utilization: End scheduler-tick
>> cal.sh-917 [003] d.h.. 1667.141542: read_msr: e8, value 4892be6cf1e
>> cal.sh-917 [003] d.h.. 1667.141542: read_msr: e7, value 38089517df9
>> cal.sh-917 [003] dNh1. 1667.141542: sched_stat_runtime: comm=cal.sh pid=917 runtime=999991 [ns]
> ^
>Since NEED_RESCHED is only set here, it is safe to assume cal.sh was
>likely kept running by RUN_TO_PARITY for 3ms after it was selected which
>corresponds to the default base_slice.
>
>> cal.sh-917 [003] dNh.. 1667.141543: hrtimer_expire_exit: hrtimer=000000007fd337f4
>> cal.sh-917 [003] dNh1. 1667.141543: hrtimer_start: hrtimer=000000007fd337f4 function=tick_sched_timer expires=1665338000000 softexpires=1665338000000 mode=ABS
>> cal.sh-917 [003] dNh.. 1667.141543: write_msr: 6e0, value 42dd94ef44f
>> cal.sh-917 [003] dNh.. 1667.141543: local_timer_exit: vector=236
>> cal.sh-917 [003] .Ns.. 1667.141544: softirq_entry: vec=9 [action=RCU]
>> cal.sh-917 [003] .Ns.. 1667.141544: rcu_utilization: Start RCU core
>> cal.sh-917 [003] dNs1. 1667.141544: rcu_grace_period: rcu_preempt 589121 cpuend
>> cal.sh-917 [003] dNs.. 1667.141544: rcu_batch_start: rcu_preempt CBs=1 bl=10
>> cal.sh-917 [003] dNs.. 1667.141545: rcu_segcb_stats: SegCbDequeued seglen: (DONE=0, WAIT=0, NEXT_READY=0, NEXT=0) gp_seq: (DONE=0, WAIT=589124, NEXT_READY=589124, NEXT=0)
>> cal.sh-917 [003] .Ns.. 1667.141545: rcu_invoke_callback: rcu_preempt rhp=00000000be314949 func=file_free_rcu
>> cal.sh-917 [003] .Ns.. 1667.141545: kmem_cache_free: call_site=file_free_rcu+0x35/0x60 ptr=00000000be314949 name=kmalloc-cg-256
>> cal.sh-917 [003] dNs.. 1667.141545: rcu_batch_end: rcu_preempt CBs-invoked=1 idle=.S..
>> cal.sh-917 [003] .Ns.. 1667.141545: rcu_utilization: End RCU core
>> cal.sh-917 [003] .Ns.. 1667.141546: softirq_exit: vec=9 [action=RCU]
>> cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: Start context switch
>> cal.sh-917 [003] dN.1. 1667.141546: rcu_utilization: End context switch
>> cal.sh-917 [003] dN.2. 1667.141546: sched_stat_runtime: comm=cal.sh pid=917 runtime=4083 [ns]
>> cal.sh-917 [003] d..2. 1667.141547: sched_switch: prev_comm=cal.sh prev_pid=917 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=943 next_prio=120
>--
>Thanks and Regards,
>Prateek
>
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2026-04-30 4:42 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2026-04-30 2:56 [Question] Possible scheduler regression: occasional ~3ms wake-up to sched-switch delay in cyclictest on kernel 6.6 and 6.12 Jiping Ma
2026-04-30 3:20 ` K Prateek Nayak
2026-04-30 4:35 ` Jiping Ma
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®