4.9.33-rt23 latency under high load

4.9.33-rt23 latency under high load

[Carol Wong]

Hi,

On my test setup, cyclictest is reporting max latency > 500 us in 4.9.33-rt23 and 4.9.35-rt25. Max latency is small in 4.9.33-rt22 and 4.9.33-rt21 (< 50 us) under the same conditions. 

My test setup uses a Core i7 (3.4GHz 3rd gen) with hyper-threading disabled. The system is under heavy load (60-90% each core) servicing network traffic and performing arithmetic on the packet payloads. Interrupt rate is approximately 60K intr/s. I've tried a few different NICs (e1000, e1000e, and ixgbe) with the same result. Occasional big hits start occurring within 30 minutes.

I tried a modified 4.9.33-rt23 kernel with the following commit removed: 
<https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-stable-rt.git/commit/kernel/sched/core.c?h=v4.9-rt&id=1dc89be37874bfc7bb4a0ea7c45492d7db39f62b>
The big latency hits do not happen with this commit backed out.

I've not yet had a chance to try a 4.11 kernel, but it looks like there's been recent work on migrate_disable/enable in that branch. Maybe a backport to 4.9 is needed?
	
Cheers,
Carol

Re: 4.9.33-rt23 latency under high load

[Sebastian Andrzej Siewior]

On 2017-07-27 22:45:38 [+0000], Carol Wong wrote:
> Hi,
Hi,

> On my test setup, cyclictest is reporting max latency > 500 us in 4.9.33-rt23 and 4.9.35-rt25. Max latency is small in 4.9.33-rt22 and 4.9.33-rt21 (< 50 us) under the same conditions. 
> 
> My test setup uses a Core i7 (3.4GHz 3rd gen) with hyper-threading disabled. The system is under heavy load (60-90% each core) servicing network traffic and performing arithmetic on the packet payloads. Interrupt rate is approximately 60K intr/s. I've tried a few different NICs (e1000, e1000e, and ixgbe) with the same result. Occasional big hits start occurring within 30 minutes.
> 
> I tried a modified 4.9.33-rt23 kernel with the following commit removed: 
> <https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-stable-rt.git/commit/kernel/sched/core.c?h=v4.9-rt&id=1dc89be37874bfc7bb4a0ea7c45492d7db39f62b>
> The big latency hits do not happen with this commit backed out.

so you say with this change is responsible for 450us of latency?
This change should be a nop if you don't change the task's CPU-mask
while the task is in a migrate-disable section. Do I miss something? Is
part of your workload changing cpu-affinity mask?

> I've not yet had a chance to try a 4.11 kernel, but it looks like there's been recent work on migrate_disable/enable in that branch. Maybe a backport to 4.9 is needed?

v4.11 should have the same change you just pointed out.

> Cheers,
> Carol
> 
Sebastian

RE: 4.9.33-rt23 latency under high load

[Carol Wong]

Hi Sebastian,

> -----Original Message-----
> From: Sebastian Andrzej Siewior [mailto:bigeasy@linutronix.de]
> Sent: Monday, August 07, 2017 6:46 AM
> To: Carol Wong
> Cc: linux-rt-users@vger.kernel.org
> Subject: Re: 4.9.33-rt23 latency under high load
> 
> On 2017-07-27 22:45:38 [+0000], Carol Wong wrote:
> > Hi,
> Hi,
> 
> > On my test setup, cyclictest is reporting max latency > 500 us in
> 4.9.33-rt23 and 4.9.35-rt25. Max latency is small in 4.9.33-rt22 and
> 4.9.33-rt21 (< 50 us) under the same conditions.
> >
> > My test setup uses a Core i7 (3.4GHz 3rd gen) with hyper-threading
> disabled. The system is under heavy load (60-90% each core) servicing
> network traffic and performing arithmetic on the packet payloads.
> Interrupt rate is approximately 60K intr/s. I've tried a few
> different NICs (e1000, e1000e, and ixgbe) with the same result.
> Occasional big hits start occurring within 30 minutes.
> >
> > I tried a modified 4.9.33-rt23 kernel with the following commit
> removed:
> > <https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-stable-
> rt.gi
> > t/commit/kernel/sched/core.c?h=v4.9-
> rt&id=1dc89be37874bfc7bb4a0ea7c454
> > 92d7db39f62b> The big latency hits do not happen with this commit
> > backed out.
> 
> so you say with this change is responsible for 450us of latency?

I can't say that this change is responsible, but I see a dramatic difference when this patch is removed. Perhaps this is a red herring. For sure in my test case, 4.9.30-rt21 reports small latency and 4.9.33-rt23 reports large latency.

> This change should be a nop if you don't change the task's CPU-mask
> while the task is in a migrate-disable section. Do I miss something?
> Is part of your workload changing cpu-affinity mask?
> 

The test program does not alter affinity masks. 

> > I've not yet had a chance to try a 4.11 kernel, but it looks like
> there's been recent work on migrate_disable/enable in that branch.
> Maybe a backport to 4.9 is needed?
> 
> v4.11 should have the same change you just pointed out.
> 

I performed the same test with 4.11.12-rt9 and observed large latencies under heavy cpu & net load.

[localhost:~]# cyclictest -S -p98 --policy=rr
# /dev/cpu_dma_latency set to 0us
policy: rr: loadavg: 0.65 0.61 0.56 1/204 2206

T: 0 ( 2131) P:98 I:1000 C:11132138 Min:      1 Act:    1 Avg:    1 Max:     375
T: 1 ( 2132) P:98 I:1500 C:7421425 Min:      1 Act:    1 Avg:    1 Max:     105
T: 2 ( 2133) P:98 I:2000 C:5566069 Min:      1 Act:    1 Avg:    1 Max:      68
T: 3 ( 2134) P:98 I:2500 C:4452855 Min:      1 Act:    2 Avg:    1 Max:      64


Cheers,
Carol

> > Cheers,
> > Carol
> >
> Sebastian

Re: 4.9.33-rt23 latency under high load

[Sebastian Andrzej Siewior]

On 2017-08-11 22:15:02 [+0000], Carol Wong wrote:
> Hi Sebastian,
Hi Carol,

> I can't say that this change is responsible, but I see a dramatic difference when this patch is removed. Perhaps this is a red herring. For sure in my test case, 4.9.30-rt21 reports small latency and 4.9.33-rt23 reports large latency.
> 
> > This change should be a nop if you don't change the task's CPU-mask
> > while the task is in a migrate-disable section. Do I miss something?
> > Is part of your workload changing cpu-affinity mask?
> > 
> 
> The test program does not alter affinity masks. 

interesting. Could you add a trace-printk to check if it gets into that
inner-loop if the mask changes and it needs to do the fixup? Other than
that I don't see anything that could make any difference.

> I performed the same test with 4.11.12-rt9 and observed large latencies under heavy cpu & net load.
> 
> [localhost:~]# cyclictest -S -p98 --policy=rr
> # /dev/cpu_dma_latency set to 0us
> policy: rr: loadavg: 0.65 0.61 0.56 1/204 2206
> 
> T: 0 ( 2131) P:98 I:1000 C:11132138 Min:      1 Act:    1 Avg:    1 Max:     375
> T: 1 ( 2132) P:98 I:1500 C:7421425 Min:      1 Act:    1 Avg:    1 Max:     105
> T: 2 ( 2133) P:98 I:2000 C:5566069 Min:      1 Act:    1 Avg:    1 Max:      68
> T: 3 ( 2134) P:98 I:2500 C:4452855 Min:      1 Act:    2 Avg:    1 Max:      64
> 
> 
> Cheers,
> Carol

Sebastian