sched/fair: Long delays starting RT processes on idle cpu.

sched/fair: Long delays starting RT processes on idle cpu.

[David Laight]

I'm seeing long delays (eg up to 90us) between a process being scheduled on an idle cpu
and the process actually executing.

This is an ivy bridge cpu:
model name      : Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz

[    0.583178] intel_idle: MWAIT substates: 0x1120
[    0.583178] intel_idle: v0.4.1 model 0x3A
[    0.583293] intel_idle: lapic_timer_reliable_states 0xffffffff

I picked one wakeup out of some ftrace data.
A short extract:
Process 10318 (the one that is woken) goes to sleep.
...
          <idle>-0     [003] d... 945687.207448: sched_idle_set_state <-cpuidle_enter_state
          <idle>-0     [003] d... 945687.207449: intel_idle <-cpuidle_enter_state
          <idle>-0     [003] d... 945687.207449: leave_mm <-intel_idle
          <idle>-0     [003] d... 945687.207449: switch_mm <-intel_idle
          <idle>-0     [003] d... 945687.207449: switch_mm_irqs_off <-switch_mm

I think cpu-3 is now executing the MWAIT from mwait_idle_with_hints()
called from intel_idle() in drivers/idle/intel_idle.c.

Not much happens on any of the cpu for 10ms until a process wakes up from a timed delay
and then tries to wake up the other threads.

    ProsodySServ-10319 [000] d... 945687.217414: sched_wakeup: comm=ProsodySServ pid=10318 prio=3 target_cpu=003
    ProsodySServ-10319 [000] d... 945687.217414: task_woken_rt <-ttwu_do_wakeup
    ProsodySServ-10319 [000] d... 945687.217414: _raw_spin_unlock_irqrestore <-try_to_wake_up
    ProsodySServ-10319 [000] .... 945687.217414: drop_futex_key_refs.isra.14 <-futex_wake

I presume the above is supposed to have done a memory write that wakes the MWAIT.

There is now a long delay (26us here) before anything happens.
          <idle>-0     [003] dN.. 945687.217440: sched_idle_set_state <-cpuidle_enter_state
...
          <idle>-0     [003] d... 945687.217447: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ProsodySServ next_pid=10318 next_prio=3

I'd have thought that the processor should wake up much faster than that.
I can't see the memory write that is paired with the monitor/mwait.
Does it need a strong barrier?

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)

Re: sched/fair: Long delays starting RT processes on idle cpu.

[Steven Rostedt]

On Mon, 27 Jan 2020 15:39:24 +0000
David Laight <David.Laight@ACULAB.COM> wrote:

> I'd have thought that the processor should wake up much faster than that.
> I can't see the memory write that is paired with the monitor/mwait.
> Does it need a strong barrier?

You may want to prevent the CPU from going into a deep C state. 90us is
something I would expect if the CPU is in a deep C state (I've seen
much longer wake up times due to deep C state).

Boot the kernel with idle=poll and see if you can trigger the same
latency. If not, then you know it's the CPU going into a deep C state
that is causing your latency.

-- Steve

RE: sched/fair: Long delays starting RT processes on idle cpu.

[David Laight]

From Steven Rostedt
> Sent: 27 January 2020 15:50
> On Mon, 27 Jan 2020 15:39:24 +0000
> David Laight <David.Laight@ACULAB.COM> wrote:
> 
> > I'd have thought that the processor should wake up much faster than that.
> > I can't see the memory write that is paired with the monitor/mwait.
> > Does it need a strong barrier?
> 
> You may want to prevent the CPU from going into a deep C state. 90us is
> something I would expect if the CPU is in a deep C state (I've seen
> much longer wake up times due to deep C state).
> 
> Boot the kernel with idle=poll and see if you can trigger the same
> latency. If not, then you know it's the CPU going into a deep C state
> that is causing your latency.

With idle=poll the delays seem to be minimal.

Is there any way to limit the C state entered by mwait?
Or to try the check that monitor/mwait is being triggered properly.
Is there a clfulsh() in the writing side?
If not, might one help??

I see almost repeatable delays eg for 6 processes being scheduled (more or less in sequence).
10us waking cpu 2.
60us waking cpu 1.
40us waking cpu 0 and 40us waking cpu3.
20us waking cpu 2.
20us waking cpu 0.
None of the processes runs for anything like the delays.
The whole thing repeats every 10ms.
Note that the first process is actually signalling a CV that 4 of the other 5
are waiting on.
So there are cumulative delays of around 140us before the 4th is woken.

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)

Re: sched/fair: Long delays starting RT processes on idle cpu.

[Steven Rostedt]

On Mon, 27 Jan 2020 16:56:12 +0000
David Laight <David.Laight@ACULAB.COM> wrote:

> >From Steven Rostedt
> > Sent: 27 January 2020 15:50
> > On Mon, 27 Jan 2020 15:39:24 +0000
> > David Laight <David.Laight@ACULAB.COM> wrote:
> >   
> > > I'd have thought that the processor should wake up much faster than that.
> > > I can't see the memory write that is paired with the monitor/mwait.
> > > Does it need a strong barrier?  
> > 
> > You may want to prevent the CPU from going into a deep C state. 90us is
> > something I would expect if the CPU is in a deep C state (I've seen
> > much longer wake up times due to deep C state).
> > 
> > Boot the kernel with idle=poll and see if you can trigger the same
> > latency. If not, then you know it's the CPU going into a deep C state
> > that is causing your latency.  
> 
> With idle=poll the delays seem to be minimal.
> 
> Is there any way to limit the C state entered by mwait?

I believe you can dynamically change C state. There's a pdf about it:

  https://wiki.ntb.ch/infoportal/_media/embedded_systems/ethercat/controlling_processor_c-state_usage_in_linux_v1.1_nov2013.pdf

-- Steve

RE: sched/fair: Long delays starting RT processes on idle cpu.

[David Laight]

From: linux-kernel-owner@vger.kernel.org <linux-kernel-owner@vger.kernel.org> On Behalf Of Steven Rostedt
> Sent: 27 January 2020 17:16
> On Mon, 27 Jan 2020 16:56:12 +0000
> David Laight <David.Laight@ACULAB.COM> wrote:
> 
> > >From Steven Rostedt
> > > Sent: 27 January 2020 15:50
> > > On Mon, 27 Jan 2020 15:39:24 +0000
> > > David Laight <David.Laight@ACULAB.COM> wrote:
> > >
> > > > I'd have thought that the processor should wake up much faster than that.
> > > > I can't see the memory write that is paired with the monitor/mwait.
> > > > Does it need a strong barrier?
> > >
> > > You may want to prevent the CPU from going into a deep C state. 90us is
> > > something I would expect if the CPU is in a deep C state (I've seen
> > > much longer wake up times due to deep C state).
> > >
> > > Boot the kernel with idle=poll and see if you can trigger the same
> > > latency. If not, then you know it's the CPU going into a deep C state
> > > that is causing your latency.
> >
> > With idle=poll the delays seem to be minimal.
> >
> > Is there any way to limit the C state entered by mwait?
> 
> I believe you can dynamically change C state. There's a pdf about it:
> 
>   https://wiki.ntb.ch/infoportal/_media/embedded_systems/ethercat/controlling_processor_c-state_usage_in_linux_v1.1_nov2013.pdf

Writing 20 to /dev/cpu_dma_latency (and holding the fd open) removes the excessive latency.
The latency values (for my system) seem to be 0, 1, 10, 59, 80.
I suspect the '10' - C1E (halt + energy saving) is not as bad as expected.

While it may well be that the cpu doesn't enter the C3/C6/C7 states if we
are doing a reasonable amount of work, they are a PITA when you are
trying to look at how a system behaves.

While searching for 'cpu_dma_latency' in Documentation does give some info,
it isn't entirely obvious that is what you need to look for.
Even finding the intel_idle.c code doesn't help much.
A reference from 'man setpriority'  might be a hint....

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)