[BUG] Boot hangs at clocksource_done_booting on large configs

[BUG] Boot hangs at clocksource_done_booting on large configs

[Alex Thorlton]

Hey guys,

We've been hitting issues with machines with 4096 or more logical cores
hanging up at clocksource_done_booting, seemingly forever.  The problem
occurs somewhat intermittently, though it hits more consistently as you
increase the core count.  We've observed this problem on kernels
starting at 3.10, all the way up through 4.2.

We initially thought there was some issue with the stop_machine code,
but Thomas G. cleared that up for us with a thorough explanation of the
stop_machine mechanism.  After ruling out issues in stop_machine, we
started investigating possible hardware related scaling issues.

I was able to hit this issue on 4.2-rc1 with our RTC disabled, to rule
out any scaling issues related to multiple concurrent reads to our
RTC's MMR.  We start getting hung task timeouts during
clocksource_done_booting:

8<----
 calling  clocksource_done_booting+0x0/0x42 @ 1
 INFO: task swapper/0:1 blocked for more than 480 seconds.
       Not tainted 4.2.0-rc1-nortc+ #384
 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
 swapper/0       D ffff881efa933b48     0     1      0 0x00000000
  ffff881efa933b48 ffff881ef45e0000 ffffb5de7a130000 000000fdfa933b38
  ffff881efa934000 7fffffffffffffff ffff881efa933ca0 ffffb5de7a130000
  0000000000000000 ffff881efa933b68 ffffffff8158eae7 ffff881efa933b68
 Call Trace:
  [<ffffffff8158eae7>] schedule+0x37/0x80
  [<ffffffff81591707>] schedule_timeout+0x1e7/0x270
  [<ffffffff812ee9b9>] ? _find_next_bit.part.0+0x19/0x70
  [<ffffffff8158fdb0>] wait_for_completion+0xa0/0x100
  [<ffffffff8108d490>] ? wake_up_q+0x70/0x70
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff810fa2a0>] __stop_cpus+0x50/0x70
  [<ffffffff810b8f7d>] ? console_unlock+0x2dd/0x4a0
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff810fa525>] stop_cpus+0x35/0x50
  [<ffffffff810d18f0>] ? tk_setup_internals.constprop.10+0x140/0x140
  [<ffffffff810fa652>] __stop_machine+0xb2/0xe0
  [<ffffffff810d18f0>] ? tk_setup_internals.constprop.10+0x140/0x140
  [<ffffffff810d18f0>] ? tk_setup_internals.constprop.10+0x140/0x140
  [<ffffffff810fa6ae>] stop_machine+0x2e/0x50
  [<ffffffff810d1fad>] timekeeping_notify+0x2d/0x50
  [<ffffffff810d3d4b>] __clocksource_select+0xcb/0x120
  [<ffffffff81b77cfa>] ? boot_override_clock+0x4d/0x4d
  [<ffffffff81b77d2c>] clocksource_done_booting+0x32/0x42
  [<ffffffff810003a9>] do_one_initcall+0x169/0x1d0
  [<ffffffff81b5613c>] kernel_init_freeable+0x1bb/0x248
  [<ffffffff81582560>] ? rest_init+0x80/0x80
  [<ffffffff8158256e>] kernel_init+0xe/0xe0
  [<ffffffff81592c5f>] ret_from_fork+0x3f/0x70
  [<ffffffff81582560>] ? rest_init+0x80/0x80
---->8

After this I NMId the machine to get backtraces for the other CPUs.
Most are stuck around here:

8<----
 CPU: 4867 PID: 19730 Comm: migration/4867 Tainted: G      D         4.2.0-rc1-nortc+ #384
 Hardware name: SGI UV2000/ROMLEY, BIOS SGI UV 2000/3000 series BIOS 01/15/2013
 task: ffffad5e798cc500 ti: ffffad5e798d4000 task.ti: ffffad5e798d4000
 RIP: 0010:[<ffffffff8105e879>]  [<ffffffff8105e879>] uv_handle_nmi+0x19/0x790
 RSP: 0000:ffffc90020156da8  EFLAGS: 00010092
 RAX: 000002fe65b95384 RBX: 000000000000002d RCX: ffffc90020162a98
 RDX: 000002fe65b95384 RSI: ffffc90020156ef8 RDI: 0000000000000001
 RBP: ffffc90020156e18 R08: 0000000000000001 R09: 0000000000000000
 R10: 0000000000000003 R11: 0000000000000020 R12: 000002fe65b95384
 R13: 0000000000000000 R14: ffffffff81a38880 R15: ffffc90020156ef8
 FS:  0000000000000000(0000) GS:ffffc90020151000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 000000000000da80 CR3: 0000000001a0b000 CR4: 00000000001406e0
 Stack:
  0000000000000000 0000000000000000 0000000000000000 0000000000000000
  0000000000000000 0000000000000000 0000000000000000 0000000000000000
  0000000000000000 000000000000002d 000002fe65b95384 0000000000000000
 Call Trace:
  <NMI>
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff81007869>] nmi_handle+0x79/0x100
  [<ffffffff81007873>] ? nmi_handle+0x83/0x100
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff81007c6c>] unknown_nmi_error+0x1c/0x90
  [<ffffffff81007e48>] default_do_nmi+0xd8/0xf0
  [<ffffffff81007ee3>] do_nmi+0x83/0xb0
  [<ffffffff815948bf>] end_repeat_nmi+0x1e/0x2e
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff810486c6>] ? read_hpet+0x16/0x20
  [<ffffffff810486c6>] ? read_hpet+0x16/0x20
  [<ffffffff810486c6>] ? read_hpet+0x16/0x20
  <<EOE>>
  <IRQ>
  [<ffffffff810d1b97>] ktime_get+0x37/0xb0
  [<ffffffff810d819b>] clockevents_program_event+0x4b/0x130
  [<ffffffff810d8737>] tick_handle_periodic+0x57/0x70
  [<ffffffff8103b46c>] local_apic_timer_interrupt+0x3c/0x70
  [<ffffffff815952c1>] smp_apic_timer_interrupt+0x41/0x60
  [<ffffffff815936ab>] apic_timer_interrupt+0x6b/0x70
  <EOI>
  [<ffffffff81097b41>] ? update_blocked_averages+0x381/0x860
  [<ffffffff810f9f98>] ? multi_cpu_stop+0x98/0xf0
  [<ffffffff8100272a>] ? __switch_to+0x26a/0x590
  [<ffffffff810f9f00>] ? cpu_stop_should_run+0x50/0x50
  [<ffffffff810fa1c8>] cpu_stopper_thread+0x88/0x110
  [<ffffffff8158e4e8>] ? __schedule+0x338/0x900
  [<ffffffff81085575>] smpboot_thread_fn+0x135/0x190
  [<ffffffff81085440>] ? sort_range+0x30/0x30
  [<ffffffff810820cb>] kthread+0xdb/0x100
  [<ffffffff81081ff0>] ? kthread_create_on_node+0x180/0x180
  [<ffffffff81592c5f>] ret_from_fork+0x3f/0x70
  [<ffffffff81081ff0>] ? kthread_create_on_node+0x180/0x180
 Code: 31 c0 e8 a0 c2 52 00 e9 39 ff ff ff 66 0f 1f 44 00 00 0f 1f 44 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 49 89 f7 53 48 83 ec 48 <48> 8b 1d 00 f2 fa 7e 65 44 8b 2d 70 b8 fa 7e 9c 58 0f 1f 44 00
---->8

I can provide full logs if desired.

Anyways, based on my limited understanding of what's going on here, I
tried disabling interrupts a bit further out in the cpu_stopper_thread
code, to try and avoid that apic_timer_interrupt during the clocksource
change.  change_clocksource already disables interrupts, but, from the
backtraces, it appears that we're taking an interrupt after the stopper
thread wakes up, but before change_clocksource actually gets called.

I used this patch to try and avoid taking a apic_timer_interrupt at any
point during the clocksource change.:

8<---
diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
index fd643d8..8502521 100644
--- a/kernel/stop_machine.c
+++ b/kernel/stop_machine.c
@@ -417,8 +417,11 @@ static void cpu_stopper_thread(unsigned int cpu)
 {
        struct cpu_stopper *stopper = &per_cpu(cpu_stopper, cpu);
        struct cpu_stop_work *work;
+       unsigned long flags;
        int ret;

+       local_irq_save(flags);
+
 repeat:
        work = NULL;
        spin_lock_irq(&stopper->lock);
@@ -452,6 +455,8 @@ repeat:
                cpu_stop_signal_done(done, true);
                goto repeat;
        }
+
+       local_irq_restore(flags);
 }

 extern void sched_set_stop_task(int cpu, struct task_struct *stop);
--->8

This was a bit of a shot in the dark, but it has worked on every kernel
and every machine we've tried it on so far.

I'm hoping to get some input from the experts in this area, first of
all, on whether the problem I'm seeing is actually what I think it is,
and, if so, if I've solved it in the correct way.

Any input is greatly appreciated!

- Alex

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Alex Thorlton]

On Mon, Aug 31, 2015 at 01:04:33PM -0500, Alex Thorlton wrote:
> I can provide full logs if desired.

Full log is here:

http://oss.sgi.com/projects/athorlton/harp50-6144-nortc

I'd use wget to download it.  Probably don't want to try to open the 15M
file in your browser :)

Also, I've filed a kernel BugZilla for the same issue, in case anyone
would rather use BugZilla:

https://bugzilla.kernel.org/show_bug.cgi?id=103821

- Alex

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Peter Zijlstra]

On Mon, Aug 31, 2015 at 01:04:33PM -0500, Alex Thorlton wrote:
q
> diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
> index fd643d8..8502521 100644
> --- a/kernel/stop_machine.c
> +++ b/kernel/stop_machine.c
> @@ -417,8 +417,11 @@ static void cpu_stopper_thread(unsigned int cpu)
>  {
>         struct cpu_stopper *stopper = &per_cpu(cpu_stopper, cpu);
>         struct cpu_stop_work *work;
> +       unsigned long flags;
>         int ret;
> 
> +       local_irq_save(flags);
> +
>  repeat:
>         work = NULL;
>         spin_lock_irq(&stopper->lock);
> @@ -452,6 +455,8 @@ repeat:
>                 cpu_stop_signal_done(done, true);
>                 goto repeat;
>         }
> +
> +       local_irq_restore(flags);
>  }
> 

So I should probably just go sleep and not say anything.. _but_
*confused*.

That local_irq_save() will disable IRQs over:

	work = NULL;

But that is _all_. The spin_unlock_irq() will re-enable IRQs, after
which things will run as usual.

That local_irq_restore() is a total NOP, IRQs are guaranteed enabled at
the irq_local_save() (otherwise lockdep would've complained about
spin_unlock_irq() unconditionally enabling them) and by the time we get
to the restore that same unlock_irq will have enabled them already.

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Alex Thorlton]

On Mon, Aug 31, 2015 at 10:32:50PM +0200, Peter Zijlstra wrote:
> On Mon, Aug 31, 2015 at 01:04:33PM -0500, Alex Thorlton wrote:
> q
> > diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
> > index fd643d8..8502521 100644
> > --- a/kernel/stop_machine.c
> > +++ b/kernel/stop_machine.c
> > @@ -417,8 +417,11 @@ static void cpu_stopper_thread(unsigned int cpu)
> >  {
> >         struct cpu_stopper *stopper = &per_cpu(cpu_stopper, cpu);
> >         struct cpu_stop_work *work;
> > +       unsigned long flags;
> >         int ret;
> > 
> > +       local_irq_save(flags);
> > +
> >  repeat:
> >         work = NULL;
> >         spin_lock_irq(&stopper->lock);
> > @@ -452,6 +455,8 @@ repeat:
> >                 cpu_stop_signal_done(done, true);
> >                 goto repeat;
> >         }
> > +
> > +       local_irq_restore(flags);
> >  }
> > 
> 
> So I should probably just go sleep and not say anything.. _but_
> *confused*.
> 
> That local_irq_save() will disable IRQs over:
> 
> 	work = NULL;
> 
> But that is _all_. The spin_unlock_irq() will re-enable IRQs, after
> which things will run as usual.
> 
> That local_irq_restore() is a total NOP, IRQs are guaranteed enabled at
> the irq_local_save() (otherwise lockdep would've complained about
> spin_unlock_irq() unconditionally enabling them) and by the time we get
> to the restore that same unlock_irq will have enabled them already.

Ahh, right.  Well that code is worthless then :)

Either way though, I guess that means that slight change just fudged the
timing enough in that area to avoid the lockup we're seeing.  Ignoring
my useless code change, does anything else jump out at you as
interesting, here?

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Thomas Gleixner]

On Mon, 31 Aug 2015, Alex Thorlton wrote:
> I was able to hit this issue on 4.2-rc1 with our RTC disabled, to rule
> out any scaling issues related to multiple concurrent reads to our
> RTC's MMR.

And to rule out scaling issues you replaced the RTC MMR with HPET. Not
a very good choice:

HPET does not scale either. It's uncached memory mapped I/O. See
below.

> I'm hoping to get some input from the experts in this area, first of
> all, on whether the problem I'm seeing is actually what I think it is,
> and, if so, if I've solved it in the correct way.

I fear both the analysis and the solution is wrong. 

Up to the point where the actual clocksource change happens there is
no reason why timer interrupts should not happen. And the code which
actually changes the clocksource is definitely called with interrupts
disabled. When that function returns the new clocksource is fully
functional and interrupts can happen again.

Now looking at your backtraces. Most CPUs are in the migration thread
and a few (3073,3078,3079,3082) are in the idle task.

>From the trace artifacts (? read_hpet) it looks like the clock source
change has been done and the cpus are on the way back from stop
machine.

But they are obviously held off by something. And that something looks
like the timekeeper sequence lock. Too bad, that we don't have a
backtrace for CPU0 in the log.

I really wonder how a machine that large works with HPET as
clocksource at all. hpet_read() is uncached memory mapped IO which
takes thousands of CPU cycles. Last time I looked it was around
1us. Let's take that number to do some math.

If all CPUs do that access at the same time, then it takes NCPUS
microseconds to complete if the memory mapped I/O scheduling is
completely fair, which I doubt. So with 4k CPUs thats whopping 4.096ms
and it gets worse if you go larger. That's more than a tick with
HZ=250.

I'm quite sure that you are staring at the HPET scalability bottleneck
and not at some actual kernel bug.

Your patch shifts some timing around so the issue does not happen, but
that's certainly not a solution.

Thanks,

	tglx

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Alex Thorlton]

On Mon, Aug 31, 2015 at 11:12:12PM +0200, Thomas Gleixner wrote:
> On Mon, 31 Aug 2015, Alex Thorlton wrote:
> > I was able to hit this issue on 4.2-rc1 with our RTC disabled, to rule
> > out any scaling issues related to multiple concurrent reads to our
> > RTC's MMR.
> 
> And to rule out scaling issues you replaced the RTC MMR with HPET. Not
> a very good choice:
> 
> HPET does not scale either. It's uncached memory mapped I/O. See
> below.

Ahhh.  I wondered if there might be an issue there.  I can say that I've
seen it hit a very similar issue with some other possible solutions that
we've tried, but this was the most recent, fairly unmodified kernel that
I've played with, so I went with this.

> > I'm hoping to get some input from the experts in this area, first of
> > all, on whether the problem I'm seeing is actually what I think it is,
> > and, if so, if I've solved it in the correct way.
> 
> I fear both the analysis and the solution is wrong.
> 
> Up to the point where the actual clocksource change happens there is
> no reason why timer interrupts should not happen. And the code which
> actually changes the clocksource is definitely called with interrupts
> disabled. When that function returns the new clocksource is fully
> functional and interrupts can happen again.
> 
> Now looking at your backtraces. Most CPUs are in the migration thread
> and a few (3073,3078,3079,3082) are in the idle task.
> 
> From the trace artifacts (? read_hpet) it looks like the clock source
> change has been done and the cpus are on the way back from stop
> machine.

That's good to note.  I'll keep that in mind as I continue gathering
info.

> But they are obviously held off by something. And that something looks
> like the timekeeper sequence lock. 

Ok.  IIRC, that lock prevents reads to the clocksource until all
necessary write operations have finished, correct?  i.e. tk_core.seq?

I looked at that as being a possible place to get stuck in ktime_get:

        do {
                seq = read_seqcount_begin(&tk_core.seq);
                base = tk->tkr_mono.base;
                nsecs = timekeeping_get_ns(&tk->tkr_mono);

        } while (read_seqcount_retry(&tk_core.seq, seq));

But I don't have enough evidence to point there for sure.

> Too bad, that we don't have a backtrace for CPU0 in the log.

I think that may have gotten swallowed up with all the lost printks that
you'll notice in there.  Does the hung task backtrace not cover that
though?

> I really wonder how a machine that large works with HPET as
> clocksource at all. hpet_read() is uncached memory mapped IO which
> takes thousands of CPU cycles. Last time I looked it was around
> 1us. Let's take that number to do some math.
> 
> If all CPUs do that access at the same time, then it takes NCPUS
> microseconds to complete if the memory mapped I/O scheduling is
> completely fair, which I doubt. So with 4k CPUs thats whopping 4.096ms
> and it gets worse if you go larger. That's more than a tick with
> HZ=250.
> 
> I'm quite sure that you are staring at the HPET scalability bottleneck
> and not at some actual kernel bug.

That could well be the case.

> Your patch shifts some timing around so the issue does not happen, but
> that's certainly not a solution.

I was fairly sure of that, but it's good to know that you agree.

I'll try and get a backtrace from a completely unmodified kernel here in
the next few days.  Unfortunately, as mentioned, we only hit the issue
intermittently.  I was able to reproduce pretty regularly on kernels
from 4.0 and before, but it seems to be less common on newer kernels,
though we definitely still manage to hit it from time to time.

Thanks for all the help!

- Alex

Re: [BUG] Boot hangs at clocksource_done_booting on large configs

[Thomas Gleixner]

On Tue, 1 Sep 2015, Alex Thorlton wrote:
> On Mon, Aug 31, 2015 at 11:12:12PM +0200, Thomas Gleixner wrote:
> > But they are obviously held off by something. And that something looks
> > like the timekeeper sequence lock. 
> 
> Ok.  IIRC, that lock prevents reads to the clocksource until all
> necessary write operations have finished, correct?  i.e. tk_core.seq?
> 
> I looked at that as being a possible place to get stuck in ktime_get:
> 
>         do {
>                 seq = read_seqcount_begin(&tk_core.seq);
>                 base = tk->tkr_mono.base;
>                 nsecs = timekeeping_get_ns(&tk->tkr_mono);
> 
>         } while (read_seqcount_retry(&tk_core.seq, seq));
> 
> But I don't have enough evidence to point there for sure.

Right and it might be a red herring. If the access to HPET takes long
enough for each CPU then you get into a situation where you never get
out of those timer interrupts anymore.
 
> > Your patch shifts some timing around so the issue does not happen, but
> > that's certainly not a solution.
> 
> I was fairly sure of that, but it's good to know that you agree.
> 
> I'll try and get a backtrace from a completely unmodified kernel here in
> the next few days.  Unfortunately, as mentioned, we only hit the issue
> intermittently.  I was able to reproduce pretty regularly on kernels
> from 4.0 and before, but it seems to be less common on newer kernels,
> though we definitely still manage to hit it from time to time.

Well, I doubt that backtraces will tell us much. Some moderate form of
tracing (a few tracepoints enabled) and a trace_dump(DUMP_ALL); call
before or instead of the NMI backtrace stuff might give us the really
interesting information. i.e. what the cpus have been doing for the
last second or such. The backtraces are just momentary snapshots and
not necessarily helpful.

You might have to hack the trace dump code to limit the output to a
few cpus if you don't want to wait a day or two until the information
has spilled out over serial :)

Thanks,

	tglx