On Wed, 2 Nov 2011, Eric Dumazet wrote:

> Le mercredi 02 novembre 2011 à 17:40 +0100, Thomas Gleixner a écrit :
> > On Mon, 31 Oct 2011, Simon Kirby wrote:
> > > On Tue, Oct 25, 2011 at 01:20:49PM -0700, Simon Kirby wrote:
> > > 
> > > > On Mon, Oct 24, 2011 at 12:02:03PM -0700, Simon Kirby wrote:
> > > > 
> > > > > Ok, hit the hang about 4 more times, but only this morning on a box with
> > > > > a serial cable attached. Yay!
> > > > 
> > > > Here's lockdep output from another box. This one looks a bit different.
> > > 
> > > One more, again a bit different. The last few lockups have looked like
> > > this. Not sure why, but we're hitting this at a few a day now. Thomas,
> > > this is without your patch, but as you said, that's right before a free
> > > and should print a separate lockdep warning.
> > > 
> > > No "huh" lines until after the trace on this one. I'll move to 3.1 with
> > 
> > That means that the lockdep warning hit in the same net_rx cycle
> > before the leak was detected by the softirq code.
> > 
> > > cherry-picked b0691c8e now.
> > 
> > Can you please add the debug patch below and try the following:
> > 
> > Enable CONFIG_FUNCTION_TRACER & CONFIG_FUNCTION_GRAPH_TRACER
> > 
> > # cd $DEBUGFSMOUNTPOINT/tracing
> > # echo sk_clone >set_ftrace_filter
> > # echo function >current_tracer
> > # echo 1 >options/func_stack_trace
> > 
> > Now wait until it reproduces (which stops the trace) and read out
> > 
> > # cat trace >/tmp/trace.txt
> > 
> > Please provide the trace file along with the lockdep splat. That
> > should tell us which callchain is responsible for the spinlock
> > leakage.
> > 
> > Thanks,
> > 
> > 	tglx
> > 
> > --------------->
> >  kernel/softirq.c |    1 +
> >  1 file changed, 1 insertion(+)
> > 
> > Index: linux-2.6/kernel/softirq.c
> > ===================================================================
> > --- linux-2.6.orig/kernel/softirq.c
> > +++ linux-2.6/kernel/softirq.c
> > @@ -238,6 +238,7 @@ restart:
> >  			h->action(h);
> >  			trace_softirq_exit(vec_nr);
> >  			if (unlikely(prev_count != preempt_count())) {
> > +				tracing_off();
> >  				printk(KERN_ERR "huh, entered softirq %u %s %p"
> >  				       "with preempt_count %08x,"
> >  				       " exited with %08x?\n", vec_nr,
> 
> 
> I believe it might come from commit 0e734419
> (ipv4: Use inet_csk_route_child_sock() in DCCP and TCP.)
> 
> In case inet_csk_route_child_sock() returns NULL, we dont release socket
> lock.

The same applies for if (__inet_inherit_port(sk, newsk) < 0) a few
lines further down, but that part was leaking the lock before that
commit already.

Just for the record, the locking in that code is mind boggling. It
took me some detective work to find even the place where the success
code path unlocks the lock :(

Thanks,

	tglx