Re: call_rcu from trace_preempt

Paul E. McKenney
2015-06-16T02:15:07Z

On Mon, Jun 15, 2015 at 06:09:56PM -0700, Alexei Starovoitov wrote:
> On 6/15/15 4:07 PM, Paul E. McKenney wrote:
> >
> >Oh... One important thing is that both call_rcu() and kfree_rcu()
> >use per-CPU variables, managing a per-CPU linked list. This is why
> >they disable interrupts. If you do another call_rcu() in the middle
> >of the first one in just the wrong place, you will have two entities
> >concurrently manipulating the same linked list, which will not go well.
>
> yes. I'm trying to find that 'wrong place'.
> The trace.patch is doing kmalloc/kfree_rcu for every preempt_enable.
> So any spin_unlock called by first call_rcu will be triggering
> 2nd recursive to call_rcu.
> But as far as I could understand rcu code that looks ok everywhere.
> call_rcu
> debug_rcu_head_[un]queue
> debug_object_activate
> spin_unlock
>
> and debug_rcu_head* seems to be called from safe places
> where local_irq is enabled.

I do sympathize, but your own testing does demonstrate that it is
very much not OK. ;-)

> >Maybe mark call_rcu() and the things it calls as notrace? Or you
> >could maintain a separate per-CPU linked list that gathered up the
> >stuff to be kfree()ed after a grace period, and some time later
> >feed them to kfree_rcu()?
>
> yeah, I can think of this or 10 other ways to fix it within
> kprobe+bpf area, but I think something like call_rcu_notrace()
> may be a better solution.
> Or may be single generic 'fix' for call_rcu will be enough if
> it doesn't affect all other users.

Why do you believe that it is better to fix it within call_rcu()?

> >The usual consequence of racing a pair of callback insertions on the
> >same CPU would be that one of them gets leaked, and possible all
> >subsequent callbacks. So the lockup is no surprise. And there are a
> >lot of other assumptions in nearby code paths about only one execution
> >at a time from a given CPU.
>
> yes, I don't think calling 2nd call_rcu from preempt_enable violates
> this assumptions. local_irq does it job. No extra stuff is called when
> interrupts are disabled.

Perhaps you are self-deadlocking within __call_rcu_core(). If you have
not already done so, please try running with CONFIG_PROVE_LOCKING=y.
(Yes, I see your point about not calling extra stuff when interrupts
are disabled, and I remember that __call_rcu() avoids that path when
interrupts are disabled, but -something- is clearly going wrong!
Or maybe something momentarily enables interrupts somewhere, and RCU
has just been getting lucky. Or...)

> >>Any advise on where to look is greatly appreciated.
> >
> >What I don't understand is exactly what you are trying to do. Have more
> >complex tracers that dynamically allocate memory? If so, having a per-CPU
> >list that stages memory to be freed so that it can be passed to call_rcu()
> >in a safe environment might make sense. Of course, that list would need
> >to be managed carefully!
>
> yes. We tried to compute the time the kernel spends between
> preempt_disable->preempt_enable and plot a histogram of latencies.
>
> >Or am I missing the point of the code below?
>
> this trace.patch is reproducer of call_rcu crashes that doing:
> preempt_enable
> trace_preempt_on
> kfree_call_rcu
>
> The real call stack is:
> preempt_enable
> trace_preempt_on
> kprobe_int3_handler
> trace_call_bpf
> bpf_map_update_elem
> htab_map_update_elem
> kree_call_rcu

I suspect that your problem may range quite a bit further than just
call_rcu(). For example, in your stack trace, you have a recursive
call to debug_object_activate(), which might not be such good thing.

Thanx, Paul