Re: [PATCH v2 6/8] kvm tools: Add rwlock wrapper

Sasha Levin
2011-06-04T06:26:24Z

On Fri, 2011-06-03 at 16:05 -0700, Paul E. McKenney wrote:
> On Sat, Jun 04, 2011 at 01:54:45AM +0300, Sasha Levin wrote:
> > On Fri, 2011-06-03 at 14:20 -0700, Paul E. McKenney wrote:
> > > On Sat, Jun 04, 2011 at 12:03:59AM +0300, Sasha Levin wrote:
> > > > On Fri, 2011-06-03 at 13:22 -0700, Paul E. McKenney wrote:
> > > > > On Fri, Jun 03, 2011 at 10:56:20PM +0300, Sasha Levin wrote:
> > > > > > On Fri, 2011-06-03 at 12:31 -0700, Paul E. McKenney wrote:
> > > > > > > On Fri, Jun 03, 2011 at 10:54:19AM +0300, Sasha Levin wrote:
> > > > > > > > On Fri, 2011-06-03 at 09:34 +0200, Ingo Molnar wrote:
> > > > > > > > > * Sasha Levin <levinsasha928@gmail.com> wrote:
> > > > > > > > >
> > > > > > > > > > > with no apparent progress being made.
> > > > > > > > > >
> > > > > > > > > > Since it's something that worked in 2.6.37, I've looked into it to
> > > > > > > > > > find what might have caused this issue.
> > > > > > > > > >
> > > > > > > > > > I've bisected guest kernels and found that the problem starts with:
> > > > > > > > > >
> > > > > > > > > > a26ac2455ffcf3be5c6ef92bc6df7182700f2114 is the first bad commit
> > > > > > > > > > commit a26ac2455ffcf3be5c6ef92bc6df7182700f2114
> > > > > > > > > > Author: Paul E. McKenney <paul.mckenney@linaro.org>
> > > > > > > > > > Date: Wed Jan 12 14:10:23 2011 -0800
> > > > > > > > > >
> > > > > > > > > > rcu: move TREE_RCU from softirq to kthread
> > > > > > > > > >
> > > > > > > > > > Ingo, could you confirm that the problem goes away for you when you
> > > > > > > > > > use an earlier commit?
> > > > > > > > >
> > > > > > > > > testing will have to wait, but there's a recent upstream fix:
> > > > > > > > >
> > > > > > > > > d72bce0e67e8: rcu: Cure load woes
> > > > > > > > >
> > > > > > > > > That *might* perhaps address this problem too.
> > > > > > > > >
> > > > > > > > I've re-tested with Linus's current git, the problem is still there.
> > > > > > > >
> > > > > > > > > If not then this appears to be some sort of RCU related livelock with
> > > > > > > > > brutally overcommitted vcpus. On native this would show up too, in a
> > > > > > > > > less drastic form, as a spurious bootup delay.
> > > > > > > >
> > > > > > > > I don't think it was overcommited by *that* much. With that commit it
> > > > > > > > usually hangs at 20-40 vcpus, while without it I can go up to 255.
> > > > > > >
> > > > > > > Here is a diagnostic patch, untested. It assumes that your system
> > > > > > > has only a few CPUs (maybe 8-16) and that timers are still running.
> > > > > > > It dumps out some RCU state if grace periods extend for more than
> > > > > > > a few seconds.
> > > > > > >
> > > > > > > To activate it, call rcu_diag_timer_start() from process context.
> > > > > > > To stop it, call rcu_diag_timer_stop(), also from process context.
> > > > > >
> > > > > > Since the hang happens in guest kernel very early during boot, I can't
> > > > > > call rcu_diag_timer_start(). What would be a good place to put the
> > > > > > _start() code instead?
> > > > >
> > > > > Assuming that the failure occurs in the host OS rather than in the guest
> > > > > OS, I suggest placing rcu_diag_timer_start() in the host code that starts
> > > > > up the guest.
> > > > >
> > > > > On the other hand, if the failure is occuring in the guest OS, then
> > > > > I suggest placing the call to rcu_diag_timer_start() just after timer
> > > > > initialization -- that is, assuming that interrupts are enabled at the
> > > > > time of the failure. If interrupts are not yet enabled at the time of
> > > > > the failure, color me clueless.
> > > >
> > > > It happens in the guest OS, the bisection was done on a guest kernel.
> > > >
> > > > I've placed the rcu debug _start() right at the end of init_timers()
> > > > which happens before the hang, but I'm not seeing any output from the
> > > > debug function.
> > >
> > > Sounds like the hang is happening before timers start? Are scheduling
> > > clock interrupts happening in the guest, as in scheduler_tick()? If so,
> > > I could just as easily put the debug there.
> >
> > Yes, scheduler_tick() is running before the hang.
> > Should I just call the handler function directly from there?
>
> I suggest calling it no more than once every few seconds, but yes.
> (Otherwise you will get a very full dmesg.)

Here is the last group of printk(), basically it just repeats itself
when it's stuck:

KVM setup async PF for cpu 19
0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc17 2/46/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc18 2/23/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc19 0/0/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
[ 0.527044] #20
0000000000000000
Call Trace:
rcu_diag: rcuc3 0/0/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc4 2/358/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc5 2/340/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc6 2/321/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc7 2/301/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc8 2/277/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc9 2/255/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc10 2/226/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc11 2/214/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc12 2/193/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc13 2/172/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc14 2/146/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc15 2/130/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc16 2/107/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc17 2/86/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc18 2/62/1
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
rcu_diag: rcuc19 2/39/0
kworker/0:1 R running task 0 0 14 0x00000008
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:

--

Sasha.