* Kernel 4.9: strange behavior with fifo scheduler
@ 2019-02-05 10:47 Frédéric Mathieu
2019-02-06 10:55 ` Dietmar Eggemann
0 siblings, 1 reply; 4+ messages in thread
From: Frédéric Mathieu @ 2019-02-05 10:47 UTC (permalink / raw)
To: linux-kernel
Hi,
on an X86_64 architecture (Intel(R) Core(TM) i3-6100U CPU @ 2.30GHz), I use
the linux kernel 4.9.146 with patch rt 125.
uname –a: Linux 4.9.146-rt125 #1 SMP PREEMPT RT Tue Jan 29 14:17:55 CET 2019
x86_64 GNU/Linux
I observed a strange behavior of the scheduler when several tasks are
executed in FIFO mode on a CPU core and a significant CPU activity.
first test (reference: cpu load=0%):
cyclictest -m -D 5 -i 1000 -p 50 -a 0
# / dev / cpu_dma_latency set to 0us
policy: fifo: loadavg: 1.95 1.06 0.43 1/159 14305
T: 0 (14145) P: 50 I: 1000 C: 4997 Min: 7 Act: 7 Avg: 7 Max: 18
work fine
now, i'm loading the system on the cpu core 0 with a homemade process:
cpu load 60%, sched FIFO prio 1, cpu 0
code snippet
active_time = 6000;
sleep_time = 4000;
do {
clock_gettime(CLOCK_MONOTONIC, &start_time);
// active loop
do {
for( cptdelay=0; cptdelay <
100; cptdelay++ );
clock_gettime(CLOCK_MONOTONIC, &now);
diff = timespec_diff_us(
&start_time, &now );
} while (diff < active_time);
// sleep : suspend time
usleep(sleep_time);
} while( 1 );
In this case cyclictest detects very long latencies
cyclictest -m -D 5 -i 1000 -p 50 -a 0 -v
Max CPUs = 2
# /dev/cpu_dma_latency set to 0us
Thread 0 Interval: 1500
0: 0: 13
0: 1: 8
0: 2: 7
0: 3: 5648
0: 4: 8
0: 5: 7
0: 6: 7
0: 7: 7
0: 8: 5649
0: 9: 7
0: 10: 7
0: 11: 7
0: 12: 7
0: 13: 5651
0: 14: 7
0: 15: 7
0: 16: 7
0: 17: 7
0: 18: 5655
0: 19: 7
0: 20: 7
0: 21: 7
0: 22: 7
0: 23: 5658
0: 24: 7
0: 25: 7
0: 26: 7
0: 27: 7
0: 28: 5663
0: 29: 7
0: 30: 7
0: 31: 7
0: 32: 7
0: 33: 5664
0: 34: 7
0: 35: 7
0: 36: 7
0: 37: 7
0: 38: 5667
0: 39: 7
0: 40: 7
0: 41: 7
0: 42: 7
0: 43: 5671
0: 44: 8
0: 45: 7
0: 46: 7
0: 47: 7
0: 48: 5673
0: 49: 7
0: 50: 7
0: 51: 7
0: 52: 7
0: 53: 5676
0: 54: 7
0: 55: 7
0: 56: 7
0: 57: 7
0: 58: 5679
0: 59: 7
0: 60: 7
0: 61: 7
0: 62: 7
0: 63: 5682
0: 64: 7
0: 65: 7
0: 66: 7
0: 67: 7
0: 68: 5685
After verification, although no other process is running with real time
scheduler, I see a latency of about 5.6 ms at regular intervals.
it seems that the priority task 1 (fifo) is not pre-empted by the cyclictest
process with a priority of 50 (fifo) when the low priority task is active.
This corresponds to the cycle recorded in the file: 6 ms of latency
followed by 4 "normal" latencies of 7 us.
Does anyone have any idea of this problem?
Best regards
Frederic MATHIEU
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Kernel 4.9: strange behavior with fifo scheduler
2019-02-05 10:47 Kernel 4.9: strange behavior with fifo scheduler Frédéric Mathieu
@ 2019-02-06 10:55 ` Dietmar Eggemann
2019-02-06 13:25 ` Frédéric Mathieu
0 siblings, 1 reply; 4+ messages in thread
From: Dietmar Eggemann @ 2019-02-06 10:55 UTC (permalink / raw)
To: Frédéric Mathieu, linux-kernel
Hi Frédéric,
On 2/5/19 11:47 AM, Frédéric Mathieu wrote:
> Hi,
>
> on an X86_64 architecture (Intel(R) Core(TM) i3-6100U CPU @ 2.30GHz), I use
> the linux kernel 4.9.146 with patch rt 125.
> uname -a: Linux 4.9.146-rt125 #1 SMP PREEMPT RT Tue Jan 29 14:17:55 CET 2019
> x86_64 GNU/Linux
>
> I observed a strange behavior of the scheduler when several tasks are
> executed in FIFO mode on a CPU core and a significant CPU activity.
>
> first test (reference: cpu load=0%):
> cyclictest -m -D 5 -i 1000 -p 50 -a 0
> # / dev / cpu_dma_latency set to 0us
> policy: fifo: loadavg: 1.95 1.06 0.43 1/159 14305
> T: 0 (14145) P: 50 I: 1000 C: 4997 Min: 7 Act: 7 Avg: 7 Max: 18
> work fine
>
> now, i'm loading the system on the cpu core 0 with a homemade process:
> cpu load 60%, sched FIFO prio 1, cpu 0
Are you sure that your test app runs with prio 1? Is this in the range
of the SCHED_FIFO (userspace) priorities shown by chrt -m?
...
SCHED_FIFO min/max priority : 1/99
...
If I run your setup (test and cyclictest affine to CPU0) on 4.15.0-43
(i7-4750HQ) with:
(1) test prio > cyclictest prio
# chrt -p $PID_TEST
pid 28489's current scheduling policy: SCHED_FIFO
pid 28489's current scheduling priority: 51
# cat /proc/$PID_TEST/stat
28489 (test) R 28488 28487 8664 34828 28487 4194304 86 0 0 0 0 0 0 0 -52
I get your behaviour:
# /dev/cpu_dma_latency set to 0us
Thread 0 Interval: 1500
0: 0: 6
0: 1: 5
0: 2: 2
0: 3: 5419
0: 4: 3
0: 5: 2
0: 6: 2
0: 7: 2
0: 8: 5422
0: 9: 3
...
whereas with:
(2) test prio < cyclictest prio
# chrt -p $PID_TEST
pid 28811's current scheduling policy: SCHED_FIFO
pid 28811's current scheduling priority: 49
# cat /proc/$PID_TEST/stat
28811 (test) S 28810 28809 8664 34828 28809 1077936128 90 0 0 0 0 0 0 0 -50
I get:
# /dev/cpu_dma_latency set to 0us
Thread 0 Interval: 1500
0: 0: 7
0: 1: 4
0: 2: 3
0: 3: 5
0: 4: 4
0: 5: 2
0: 6: 2
0: 7: 2
0: 8: 2
0: 9: 3
...
[...]
> In this case cyclictest detects very long latencies
> cyclictest -m -D 5 -i 1000 -p 50 -a 0 -v
>
> Max CPUs = 2
> # /dev/cpu_dma_latency set to 0us
> Thread 0 Interval: 1500
> 0: 0: 13
> 0: 1: 8
> 0: 2: 7
> 0: 3: 5648
> 0: 4: 8
> 0: 5: 7
> 0: 6: 7
> 0: 7: 7
> 0: 8: 5649
[...]
> After verification, although no other process is running with real time
> scheduler, I see a latency of about 5.6 ms at regular intervals.
>
> it seems that the priority task 1 (fifo) is not pre-empted by the cyclictest
> process with a priority of 50 (fifo) when the low priority task is active.
> This corresponds to the cycle recorded in the file: 6 ms of latency
> followed by 4 "normal" latencies of 7 us.
>
> Does anyone have any idea of this problem?
>
> Best regards
> Frederic MATHIEU
^ permalink raw reply [flat|nested] 4+ messages in thread
* RE: Kernel 4.9: strange behavior with fifo scheduler
2019-02-06 10:55 ` Dietmar Eggemann
@ 2019-02-06 13:25 ` Frédéric Mathieu
2019-02-07 11:27 ` Dietmar Eggemann
0 siblings, 1 reply; 4+ messages in thread
From: Frédéric Mathieu @ 2019-02-06 13:25 UTC (permalink / raw)
To: 'Dietmar Eggemann', linux-kernel
Hi Dietmar,
Attention !, these tests were executed on a kernel with the patch RT and the option CONFIG_PREEMPT_RT_FULL = y. I confirm the truth of my priority settings
On a vanilla kernel, I get the same results as you.
After talking with mike Galbraith, I turned my attention to the priority of kernel threads. The following link explains in the behavior of the scheduler :
https://wiki.linuxfoundation.org/realtime/documentation/technical_details/hr_timers
Contrary to what I thought, there is no dynamic adjustment of the priority according to the priority of the calling task.
-----Message d'origine-----
De : linux-kernel-owner@vger.kernel.org [mailto:linux-kernel-owner@vger.kernel.org] De la part de Dietmar Eggemann
Envoyé : mercredi 6 février 2019 11:55
À : Frédéric Mathieu <frederic.mathieu@dualis.com>; linux-kernel@vger.kernel.org
Objet : Re: Kernel 4.9: strange behavior with fifo scheduler
Hi Frédéric,
On 2/5/19 11:47 AM, Frédéric Mathieu wrote:
> Hi,
>
> on an X86_64 architecture (Intel(R) Core(TM) i3-6100U CPU @ 2.30GHz),
> I use the linux kernel 4.9.146 with patch rt 125.
> uname -a: Linux 4.9.146-rt125 #1 SMP PREEMPT RT Tue Jan 29 14:17:55
> CET 2019
> x86_64 GNU/Linux
>
> I observed a strange behavior of the scheduler when several tasks are
> executed in FIFO mode on a CPU core and a significant CPU activity.
>
> first test (reference: cpu load=0%):
> cyclictest -m -D 5 -i 1000 -p 50 -a 0
> # / dev / cpu_dma_latency set to 0us
> policy: fifo: loadavg: 1.95 1.06 0.43 1/159 14305
> T: 0 (14145) P: 50 I: 1000 C: 4997 Min: 7 Act: 7 Avg: 7 Max:
> 18 work fine
>
> now, i'm loading the system on the cpu core 0 with a homemade process:
> cpu load 60%, sched FIFO prio 1, cpu 0
Are you sure that your test app runs with prio 1? Is this in the range of the SCHED_FIFO (userspace) priorities shown by chrt -m?
...
SCHED_FIFO min/max priority : 1/99
...
If I run your setup (test and cyclictest affine to CPU0) on 4.15.0-43
(i7-4750HQ) with:
(1) test prio > cyclictest prio
# chrt -p $PID_TEST
pid 28489's current scheduling policy: SCHED_FIFO pid 28489's current scheduling priority: 51
# cat /proc/$PID_TEST/stat
28489 (test) R 28488 28487 8664 34828 28487 4194304 86 0 0 0 0 0 0 0 -52
I get your behaviour:
# /dev/cpu_dma_latency set to 0us
Thread 0 Interval: 1500
0: 0: 6
0: 1: 5
0: 2: 2
0: 3: 5419
0: 4: 3
0: 5: 2
0: 6: 2
0: 7: 2
0: 8: 5422
0: 9: 3
...
whereas with:
(2) test prio < cyclictest prio
# chrt -p $PID_TEST
pid 28811's current scheduling policy: SCHED_FIFO pid 28811's current scheduling priority: 49
# cat /proc/$PID_TEST/stat
28811 (test) S 28810 28809 8664 34828 28809 1077936128 90 0 0 0 0 0 0 0 -50
I get:
# /dev/cpu_dma_latency set to 0us
Thread 0 Interval: 1500
0: 0: 7
0: 1: 4
0: 2: 3
0: 3: 5
0: 4: 4
0: 5: 2
0: 6: 2
0: 7: 2
0: 8: 2
0: 9: 3
...
[...]
> In this case cyclictest detects very long latencies
> cyclictest -m -D 5 -i 1000 -p 50 -a 0 -v
>
> Max CPUs = 2
> # /dev/cpu_dma_latency set to 0us
> Thread 0 Interval: 1500
> 0: 0: 13
> 0: 1: 8
> 0: 2: 7
> 0: 3: 5648
> 0: 4: 8
> 0: 5: 7
> 0: 6: 7
> 0: 7: 7
> 0: 8: 5649
[...]
> After verification, although no other process is running with real
> time scheduler, I see a latency of about 5.6 ms at regular intervals.
>
> it seems that the priority task 1 (fifo) is not pre-empted by the
> cyclictest process with a priority of 50 (fifo) when the low priority task is active.
> This corresponds to the cycle recorded in the file: 6 ms of latency
> followed by 4 "normal" latencies of 7 us.
>
> Does anyone have any idea of this problem?
>
> Best regards
> Frederic MATHIEU
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Kernel 4.9: strange behavior with fifo scheduler
2019-02-06 13:25 ` Frédéric Mathieu
@ 2019-02-07 11:27 ` Dietmar Eggemann
0 siblings, 0 replies; 4+ messages in thread
From: Dietmar Eggemann @ 2019-02-07 11:27 UTC (permalink / raw)
To: Frédéric Mathieu, linux-kernel
On 2/6/19 2:25 PM, Frédéric Mathieu wrote:
> Hi Dietmar,
>
> Attention !, these tests were executed on a kernel with the patch RT and the option CONFIG_PREEMPT_RT_FULL = y. I confirm the truth of my priority settings
> On a vanilla kernel, I get the same results as you.
>
> After talking with mike Galbraith, I turned my attention to the priority of kernel threads. The following link explains in the behavior of the scheduler :
> https://wiki.linuxfoundation.org/realtime/documentation/technical_details/hr_timers
>
> Contrary to what I thought, there is no dynamic adjustment of the priority according to the priority of the calling task.
>
> -----Message d'origine-----
> De : linux-kernel-owner@vger.kernel.org [mailto:linux-kernel-owner@vger.kernel.org] De la part de Dietmar Eggemann
> Envoyé : mercredi 6 février 2019 11:55
> À : Frédéric Mathieu <frederic.mathieu@dualis.com>; linux-kernel@vger.kernel.org
> Objet : Re: Kernel 4.9: strange behavior with fifo scheduler
>
> Hi Frédéric,
>
> On 2/5/19 11:47 AM, Frédéric Mathieu wrote:
>> Hi,
>>
>> on an X86_64 architecture (Intel(R) Core(TM) i3-6100U CPU @ 2.30GHz),
>> I use the linux kernel 4.9.146 with patch rt 125.
>> uname -a: Linux 4.9.146-rt125 #1 SMP PREEMPT RT Tue Jan 29 14:17:55
>> CET 2019
>> x86_64 GNU/Linux
Ah, OK, I should have read it more carefully! So you're talking about
the ktimersoftd/0 thread in this case which makes cyclictest show the
latency of ~6ms every 5th time.
v4.9 + rt 125 on ARM64 Juno: (test prio (49) > cyclictest prio (50)
...
ktimersoftd/0-4 [000] 54.948862: sched_pi_setprio:
comm=ktimersoftd/0 pid=4 oldprio=49 newprio=98
ktimersoftd/0-4 [000] 54.948867: sched_waking:
comm=cyclictest pid=2730 prio=49 target_cpu=000
ktimersoftd/0-4 [000] 54.948870: sched_wakeup:
cyclictest:2730 [49] success=1 CPU:000
ktimersoftd/0-4 [000] 54.948874: sched_switch:
ktimersoftd/0:4 [98] R ==> cyclictest:2730 [49]
cyclictest-2730 [000] 54.948890: sched_switch:
cyclictest:2730 [49] S ==> ktimersoftd/0:4 [98]
ktimersoftd/0-4 [000] 54.948906: sched_switch:
ktimersoftd/0:4 [98] S ==> swapper/0:0 [120]
<idle>-0 [000] 54.949087: sched_waking:
comm=test pid=2723 prio=50 target_cpu=000
<idle>-0 [000] 54.949090: sched_wakeup:
test:2723 [50] success=1 CPU:000
<idle>-0 [000] 54.949098: sched_switch:
swapper/0:0 [120] R ==> test:2723 [50]
test-2723 [000] 54.949784: sched_waking:
comm=ktimersoftd/0 pid=4 prio=98 target_cpu=000
test-2723 [000] 54.949787: sched_wakeup:
ktimersoftd/0:4 [98] success=1 CPU:000
test-2723 [000] 54.951979: sched_waking:
comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
test-2723 [000] 54.951983: sched_wakeup:
ksoftirqd/0:3 [120] success=1 CPU:000
test-2723 [000] 54.955111: sched_switch:
test:2723 [50] S ==> ktimersoftd/0:4 [98]
ktimersoftd/0-4 [000] 54.955125: sched_waking:
comm=cyclictest pid=2730 prio=49 target_cpu=000
ktimersoftd/0-4 [000] 54.955128: sched_wakeup:
cyclictest:2730 [49] success=1 CPU:000
ktimersoftd/0-4 [000] 54.955132: sched_switch:
ktimersoftd/0:4 [98] R ==> cyclictest:2730 [49]
cyclictest-2730 [000] 54.955138: sched_pi_setprio:
comm=ktimersoftd/0 pid=4 oldprio=98 newprio=49
cyclictest-2730 [000] 54.955145: sched_switch:
cyclictest:2730 [49] D ==> ktimersoftd/0:4 [49]
ktimersoftd/0-4 [000] 54.955149: sched_pi_setprio:
comm=ktimersoftd/0 pid=4 oldprio=49 newprio=98
ktimersoftd/0-4 [000] 54.955154: sched_waking:
comm=cyclictest pid=2730 prio=49 target_cpu=000
ktimersoftd/0-4 [000] 54.955157: sched_wakeup:
cyclictest:2730 [49] success=1 CPU:000
...
[...]
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-02-07 11:27 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-02-05 10:47 Kernel 4.9: strange behavior with fifo scheduler Frédéric Mathieu
2019-02-06 10:55 ` Dietmar Eggemann
2019-02-06 13:25 ` Frédéric Mathieu
2019-02-07 11:27 ` Dietmar Eggemann
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®