Skip site navigation (1)Skip section navigation (2)
Date:      Thu, 04 Aug 2016 10:34:48 -0700
From:      John Baldwin <jhb@freebsd.org>
To:        gljennjohn@gmail.com
Cc:        current@freebsd.org
Subject:   Re: EARLY_AP_STARTUP hangs during boot
Message-ID:  <3133061.id72CNzR69@ralph.baldwin.cx>
In-Reply-To: <20160804085906.2228aa0b@ernst.home>
References:  <20160516122242.39249a54@ernst.home> <4473265.DhpanzHFA4@ralph.baldwin.cx> <20160804085906.2228aa0b@ernst.home>

next in thread | previous in thread | raw e-mail | index | archive | help
On Thursday, August 04, 2016 08:59:06 AM Gary Jennejohn wrote:
> On Tue, 02 Aug 2016 10:41:23 -0700
> John Baldwin <jhb@freebsd.org> wrote:
> 
> > On Tuesday, August 02, 2016 09:03:10 AM Gary Jennejohn wrote:
> > > On Mon, 01 Aug 2016 13:19:16 -0700
> > > John Baldwin <jhb@freebsd.org> wrote:
> > >   
> > > > On Monday, August 01, 2016 03:31:11 PM Gary Jennejohn wrote:  
> > > > > On Mon, 1 Aug 2016 09:34:34 +0200
> > > > > Gary Jennejohn <gljennjohn@gmail.com> wrote:
> > > > >     
> > > > > > On Sun, 31 Jul 2016 14:22:35 -0700
> > > > > > John Baldwin <jhb@freebsd.org> wrote:
> > > > > >     
> > > > > > > On Sunday, July 31, 2016 11:29:14 AM Gary Jennejohn wrote:      
> > > > > > > > On Sat, 30 Jul 2016 12:03:59 -0700
> > > > > > > > John Baldwin <jhb@freebsd.org> wrote:
> > > > > > > >         
> > > > > > > > > On Saturday, July 30, 2016 09:44:22 AM Gary Jennejohn wrote:        
> > > > > > > > > > On Fri, 29 Jul 2016 13:17:42 -0700
> > > > > > > > > > John Baldwin <jhb@freebsd.org> wrote:
> > > > > > > > > >           
> > > > > > > > > > > On Thursday, July 28, 2016 12:31:31 AM Gary Jennejohn wrote:          
> > > > > > > > > > > > Well, now I know that ULE is a prerequiste for EARLY_AP_STARTUP!  I
> > > > > > > > > > > > wasn't aware of that.  I prefer BSD and that's the scheduler I did
> > > > > > > > > > > > the first tests with.
> > > > > > > > > > > > 
> > > > > > > > > > > > But with the ULE scheduler the system comes up all the way.
> > > > > > > > > > > > 
> > > > > > > > > > > > It would be nice if the BSD scheduler could also be modified to
> > > > > > > > > > > > work with EARLY_AP_STARTUP.            
> > > > > > > > > > > 
> > > > > > > > > > > I wasn't able to reproduce your hang with 4BSD, but I think I see a
> > > > > > > > > > > possible problem.  Try this:
> > > > > > > > > > > 
> > > > > > > > > > > diff --git a/sys/kern/sched_4bsd.c b/sys/kern/sched_4bsd.c
> > > > > > > > > > > index 7de56b6..d53331a 100644
> > > > > > > > > > > --- a/sys/kern/sched_4bsd.c
> > > > > > > > > > > +++ b/sys/kern/sched_4bsd.c
> > > > > > > > > > > @@ -327,7 +327,6 @@ maybe_preempt(struct thread *td)
> > > > > > > > > > >  	 *  - The current thread has a higher (numerically lower) or
> > > > > > > > > > >  	 *    equivalent priority.  Note that this prevents curthread from
> > > > > > > > > > >  	 *    trying to preempt to itself.
> > > > > > > > > > > -	 *  - It is too early in the boot for context switches (cold is set).
> > > > > > > > > > >  	 *  - The current thread has an inhibitor set or is in the process of
> > > > > > > > > > >  	 *    exiting.  In this case, the current thread is about to switch
> > > > > > > > > > >  	 *    out anyways, so there's no point in preempting.  If we did,
> > > > > > > > > > > @@ -348,7 +347,7 @@ maybe_preempt(struct thread *td)
> > > > > > > > > > >  			("maybe_preempt: trying to run inhibited thread"));
> > > > > > > > > > >  	pri = td->td_priority;
> > > > > > > > > > >  	cpri = ctd->td_priority;
> > > > > > > > > > > -	if (panicstr != NULL || pri >= cpri || cold /* || dumping */ ||
> > > > > > > > > > > +	if (panicstr != NULL || pri >= cpri /* || dumping */ ||
> > > > > > > > > > >  	    TD_IS_INHIBITED(ctd))
> > > > > > > > > > >  		return (0);
> > > > > > > > > > >  #ifndef FULL_PREEMPTION
> > > > > > > > > > > @@ -1127,7 +1126,7 @@ forward_wakeup(int cpunum)
> > > > > > > > > > >  	if ((!forward_wakeup_enabled) ||
> > > > > > > > > > >  	     (forward_wakeup_use_mask == 0 && forward_wakeup_use_loop == 0))
> > > > > > > > > > >  		return (0);
> > > > > > > > > > > -	if (!smp_started || cold || panicstr)
> > > > > > > > > > > +	if (!smp_started || panicstr)
> > > > > > > > > > >  		return (0);
> > > > > > > > > > >  
> > > > > > > > > > >  	forward_wakeups_requested++;
> > > > > > > > > > >           
> > > > > > > > > > 
> > > > > > > > > > Thanks, but with this patch the kernel hangs in exactly the same
> > > > > > > > > > place as before - after the HPET output.
> > > > > > > > > > 
> > > > > > > > > > Maybe I'm missing some kernel option which ULE works around, or
> > > > > > > > > > something like that.          
> > > > > > > > > 
> > > > > > > > > Hmm, ok.  Please add KTR_RUNQ and KTR_SMP to the KTR masks, that is
> > > > > > > > > 'options KTR_COMPILE=(KTR_PROC|KTR_RUNQ|KTR_SMP)' and
> > > > > > > > > 'options KTR_MASK=(KTR_PROC|KTR_RUNQ|KTR_SMP)'
> > > > > > > > > 
> > > > > > > > > Please also add this patch (on top of the previous patch):
> > > > > > > > > 
> > > > > > > > > diff --git a/sys/kern/sched_4bsd.c b/sys/kern/sched_4bsd.c
> > > > > > > > > index 2973a23..bab2278 100644
> > > > > > > > > --- a/sys/kern/sched_4bsd.c
> > > > > > > > > +++ b/sys/kern/sched_4bsd.c
> > > > > > > > > @@ -1278,6 +1278,8 @@ sched_add(struct thread *td, int flags)
> > > > > > > > >         KASSERT(td->td_flags & TDF_INMEM,
> > > > > > > > >             ("sched_add: thread swapped out"));
> > > > > > > > >  
> > > > > > > > > +       CTR2(KTR_PROC, "sched_add: thread %d (%s)", td->td_tid,
> > > > > > > > > +           sched_tdname(td));
> > > > > > > > >         KTR_STATE2(KTR_SCHED, "thread", sched_tdname(td), "runq add",
> > > > > > > > >             "prio:%d", td->td_priority, KTR_ATTR_LINKED,
> > > > > > > > >             sched_tdname(curthread));
> > > > > > > > > diff --git a/sys/x86/x86/cpu_machdep.c b/sys/x86/x86/cpu_machdep.c
> > > > > > > > > index f07b97e..1f418f1 100644
> > > > > > > > > --- a/sys/x86/x86/cpu_machdep.c
> > > > > > > > > +++ b/sys/x86/x86/cpu_machdep.c
> > > > > > > > > @@ -440,6 +440,7 @@ cpu_idle_wakeup(int cpu)
> > > > > > > > >                 return (0);
> > > > > > > > >         if (*state == STATE_MWAIT)
> > > > > > > > >                 *state = STATE_RUNNING;
> > > > > > > > > +       CTR1(KTR_PROC, "cpu_idle_wakeup: wokeup CPU %d", cpu);
> > > > > > > > >         return (1);
> > > > > > > > >  }
> > > > > > > > > 
> > > > > > > > > (I haven't tried compiling it, you might have to add the sys/ktr.h
> > > > > > > > > header to cpu_machdep.c if it doesn't build.)
> > > > > > > > > 
> > > > > > > > > Hopefully we will get some better trace messages before it hangs
> > > > > > > > > with this added info.  The root issue seems to be that 4BSD is
> > > > > > > > > pinning thread0 to some other CPU (due to sched_bind that happens
> > > > > > > > > inside of bus_bind_intr() when the HPET driver pins IRQs to CPUs)
> > > > > > > > > and that other CPU isn't waking up to realize it needs to run thread0.
> > > > > > > > >         
> > > > > > > > 
> > > > > > > > It compiled with no changes needed.
> > > > > > > > 
> > > > > > > > Even though I set MAXCPU to a mere 2, the boot still hadn't
> > > > > > > > completed after 90 minutes and I broke it off.  I still have
> > > > > > > > the kernel, so I can try it another time when I have less need
> > > > > > > > for my FreeBSD box.        
> > > > > > > 
> > > > > > > Did you have the KTR options enabled from before?  I don't expect this
> > > > > > > to fix the issue, this is more about getting better debug info when it
> > > > > > > hangs.
> > > > > > >       
> > > > > > 
> > > > > > Yes, all the options from before were enabled.  Maybe I should have
> > > > > > disabled KTR_VERBOSE=1?  I'll try it without that.
> > > > > >     
> > > > > 
> > > > > KTR_VERBOSE=1 is necessary.    
> > > > 
> > > > Yes.
> > > >   
> > > > > OK, after about 5 hours it landed in an infinite loop emitting:
> > > > > 
> > > > > cpu_0 ipi_cpu: cpu: 1 to 5 ipi: 2 (my CPU has 6 cores)    
> > > > 
> > > > Humm, can you capture a picture right when it hangs?  Those interrupts
> > > > are due to clock interrupts (IPI_HARDCLOCK) and are noise.  More what
> > > > I'm trying to see is if we send IPI_AST/IPI_PREEMPT to the CPU after
> > > > binding to it.
> > > >   
> > > 
> > > I can't tell when it hangs due to the amount of trace coming out. 
> > > The hang is hidden in the noise and I have no way to suppress the
> > > trace that I'm aware of.  The trace is coming so fast that even
> > > a photo of the screen looks smeared.
> > > 
> > > Is there a way to limit the trace to IPI_AST/IPI_PREEMPT?  
> > 
> > Yes:
> > 
> > diff --git a/sys/x86/x86/mp_x86.c b/sys/x86/x86/mp_x86.c
> > index 91c119a..6c57b20 100644
> > --- a/sys/x86/x86/mp_x86.c
> > +++ b/sys/x86/x86/mp_x86.c
> > @@ -1160,7 +1160,8 @@ ipi_cpu(int cpu, u_int ipi)
> >  	if (ipi == IPI_STOP_HARD)
> >  		CPU_SET_ATOMIC(cpu, &ipi_stop_nmi_pending);
> >  
> > -	CTR3(KTR_SMP, "%s: cpu: %d ipi: %x", __func__, cpu, ipi);
> > +	if (ipi == IPI_AST || ipi == IPI_PREEMPT)
> > +		CTR3(KTR_SMP, "%s: cpu: %d ipi: %x", __func__, cpu, ipi);
> >  	ipi_send_cpu(cpu, ipi);
> >  }
> >  
> > 
> 
> I limited output to KTR_SMP and used only the patch above.
> 
> The last lines which appear are:
> hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff irq 0,8
> on acpi0
> cpu0: smp_targeted_tlb_shootdown: cpu: 1 ipi: f6
> cpu0: smp_targeted_tlb_shootdown: cpu: 2 ipi: f6
> cpu0: smp_targeted_tlb_shootdown: cpu: 3 ipi: f6
> cpu0: smp_targeted_tlb_shootdown: cpu: 4 ipi: f6
> cpu0: smp_targeted_tlb_shootdown: cpu: 5 ipi: f6
> Timecounter "HPET" frequency 14318180 Hz qualty 950

Hmm, no lines with mi_switch like you saw before?

-- 
John Baldwin



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?3133061.id72CNzR69>