On Mon, Jun 15, 2015 at 03:24:29PM -0700, Alexei Starovoitov wrote:
> Hi Paul,
>
> I've been debugging the issue reported by Daniel:
> http://thread.gmane.org/gmane.linux.kernel/1974304/focus=1974304
> and it seems I narrowed it down to recursive call_rcu.
By "recursive call_rcu()", you mean invoking call_rcu() twice in a row
on the same memory, like this?
call_rcu(&p->rh, some_callback_function);
do_something_quick();
call_rcu(&p->rh, another_callback_function);
Because this is perfectly legal:
void recirculating_callback_function(struct rcu_head *p)
{
struct foo *fp = container_of(p, struct foo, rh);
kfree(fp);
}
void recirculating_callback_function(struct rcu_head *p)
{
call_rcu(p, endpoint_callback_function);
}
...
call_rcu(&fp->rh, recirculating_callback_function);
This sort of thing is actually used in some situations involving
RCU and reference counters.
> From trace_preempt_on() I'm doing:
> e = kmalloc(sizeof(struct elem), GFP_ATOMIC)
> kfree_rcu(e, rcu)
As written, this should be OK, assuming that "rcu" is a field of type
"struct rcu_head" (not a pointer!) within "struct elem".
> which causing all sorts of corruptions like:
> [ 2.074175] WARNING: CPU: 0 PID: 3 at ../lib/debugobjects.c:263
> debug_print_object+0x8c/0xb0()
> [ 2.075567] ODEBUG: active_state not available (active state 0)
> object type: rcu_head hint: (null)
>
> [ 2.102141] WARNING: CPU: 0 PID: 3 at ../lib/debugobjects.c:263
> debug_print_object+0x8c/0xb0()
> [ 2.103547] ODEBUG: deactivate not available (active state 0)
> object type: rcu_head hint: (null)
>
> [ 2.253995] WARNING: CPU: 0 PID: 7 at ../kernel/rcu/tree.c:2976
> __call_rcu.constprop.67+0x1e5/0x350()
> [ 2.255510] __call_rcu(): Leaked duplicate callback
>
> Sometimes stack looks like:
> [ 2.145163] WARNING: CPU: 0 PID: 102 at ../lib/debugobjects.c:263
> debug_print_object+0x8c/0xb0()
> [ 2.147465] ODEBUG: active_state not available (active state 0)
> object type: rcu_head hint: (null)
> [ 2.148022] Modules linked in:
> [ 2.148022] CPU: 0 PID: 102 Comm: systemd-udevd Not tainted
> 4.1.0-rc7+ #653
> [ 2.148022] Hardware name: QEMU Standard PC (i440FX + PIIX,
> 1996), BIOS
> rel-1.7.5-rc1-0-gb1d4dc9-20140515_140003-nilsson.home.kraxel.org
> 04/01/2014
> [ 2.148022] ffffffff81a34f77 ffff88000fc03d18 ffffffff81781ed4
> 0000000000000105
> [ 2.148022] ffff88000fc03d68 ffff88000fc03d58 ffffffff81064e57
> 0000000000000000
> [ 2.148022] ffff88000fc03e20 ffffffff81c50f00 ffffffff81a34fdf
> 0000000000000286
> [ 2.148022] Call Trace:
> [ 2.148022] <IRQ> [<ffffffff81781ed4>] dump_stack+0x4f/0x7b
> [ 2.148022] [<ffffffff81064e57>] warn_slowpath_common+0x97/0xe0
> [ 2.148022] [<ffffffff81064f56>] warn_slowpath_fmt+0x46/0x50
> [ 2.148022] [<ffffffff813d305c>] debug_print_object+0x8c/0xb0
> [ 2.148022] [<ffffffff813d3cf6>] ? debug_object_active_state+0x66/0x160
> [ 2.148022] [<ffffffff813d3d81>] debug_object_active_state+0xf1/0x160
> [ 2.148022] [<ffffffff810e33b1>] rcu_process_callbacks+0x301/0xae0
> [ 2.148022] [<ffffffff810e3397>] ? rcu_process_callbacks+0x2e7/0xae0
> [ 2.148022] [<ffffffff810e9f28>] ? run_timer_softirq+0x218/0x4c0
> [ 2.148022] [<ffffffff81069dff>] __do_softirq+0x14f/0x670
> [ 2.148022] [<ffffffff8106a5f5>] irq_exit+0xa5/0xb0
> [ 2.148022] [<ffffffff8178ea6a>] smp_apic_timer_interrupt+0x4a/0x60
> [ 2.148022] [<ffffffff8178cea0>] apic_timer_interrupt+0x70/0x80
> [ 2.148022] <EOI> [<ffffffff813d363c>] ?
> debug_object_activate+0x9c/0x1e0
> [ 2.148022] [<ffffffff8178bd47>] ? _raw_spin_unlock_irqrestore+0x67/0x80
> [ 2.148022] [<ffffffff813d36f6>] debug_object_activate+0x156/0x1e0
> [ 2.148022] [<ffffffff810de037>] rcuhead_fixup_activate+0x37/0x40
> [ 2.148022] [<ffffffff813d36a1>] debug_object_activate+0x101/0x1e0
> [ 2.148022] [<ffffffff8178bd2b>] ? _raw_spin_unlock_irqrestore+0x4b/0x80
> [ 2.148022] [<ffffffff810e2d26>] __call_rcu.constprop.67+0x46/0x350
> [ 2.148022] [<ffffffff813d3524>] ? __debug_object_init+0x3f4/0x430
> [ 2.148022] [<ffffffff8178bd2b>] ? _raw_spin_unlock_irqrestore+0x4b/0x80
> [ 2.148022] [<ffffffff810e308a>] kfree_call_rcu+0x1a/0x20
> [ 2.148022] [<ffffffff8115e230>] trace_preempt_on+0x180/0x290
> [ 2.148022] [<ffffffff8115e17e>] ? trace_preempt_on+0xce/0x290
> [ 2.148022] [<ffffffff810991c3>] preempt_count_sub+0x73/0xf0
> [ 2.148022] [<ffffffff8178bd2b>] _raw_spin_unlock_irqrestore+0x4b/0x80
> [ 2.148022] [<ffffffff813d3524>] __debug_object_init+0x3f4/0x430
> [ 2.148022] [<ffffffff8115e23c>] ? trace_preempt_on+0x18c/0x290
> [ 2.148022] [<ffffffff813d357b>] debug_object_init+0x1b/0x20
> [ 2.148022] [<ffffffff810de028>] rcuhead_fixup_activate+0x28/0x40
> [ 2.148022] [<ffffffff813d36a1>] debug_object_activate+0x101/0x1e0
> [ 2.148022] [<ffffffff812036b0>] ? get_max_files+0x20/0x20
> [ 2.148022] [<ffffffff810e2d26>] __call_rcu.constprop.67+0x46/0x350
> [ 2.148022] [<ffffffff810e30a7>] call_rcu+0x17/0x20
> [ 2.148022] [<ffffffff81203903>] __fput+0x183/0x200
> [ 2.148022] [<ffffffff812039ce>] ____fput+0xe/0x10
> [ 2.148022] [<ffffffff81088dd5>] task_work_run+0xb5/0xe0
> [ 2.148022] [<ffffffff81002c74>] do_notify_resume+0x64/0x80
> [ 2.148022] [<ffffffff8178c26c>] int_signal+0x12/0x17
>
> My reading of the code is debug_object_*() bits are reporting real
> problem. In the above trace the call
> debug_rcu_head_unqueue(list);
> from rcu_do_batch() is not finding 'list' in tracked objects.
>
> I know that doing call_rcu() from trace_preempt is ill advised,
> but I still want to understand why call_rcu corrupts the memory.
Hmmm... This is what I would expect if you invoked call_rcu()
(or kfree_rcu(), for that matter) on some memory, then freed it
before the grace period ended. This would cause the same problems
as any other use-after-free error. Might this be happening?
> Attaching a patch that I'm using for debugging.
> It's doing recursion preemption check, so number of nested call_rcu
> is no more than 2.
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.
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()?
> Also if I replace kfree_rcu is this patch with a regular kfree,
> all works fine.
>
> I'm seeing this crashes in VM with _single_ cpu.
> Kernel is built with CONFIG_PREEMPT, CONFIG_PREEMPT_TRACER and
> CONFIG_DEBUG_OBJECTS_RCU_HEAD.
No surprise -- when you have lists hanging off of per-CPU variables,
it only takes one CPU to tangle the lists.
> Also interesting that size of
> struct elem {
> u64 pad[32];
> struct rcu_head rcu;
> };
> that I'm using in kmalloc/kfree_rcu changes the crash.
> If padding is zero, kernel just locksup, if pad[1] I see
> one type of odebug warnings, if pad[32] - another.
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.
> 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!
Or am I missing the point of the code below?
Thanx, Paul
> Thanks!
>
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 8523ea345f2b..89433a83dd2d 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -13,6 +13,7 @@
> #include <linux/uaccess.h>
> #include <linux/module.h>
> #include <linux/ftrace.h>
> +#include <linux/slab.h>
>
> #include "trace.h"
>
> @@ -510,8 +511,42 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
> #endif /* CONFIG_IRQSOFF_TRACER */
>
> #ifdef CONFIG_PREEMPT_TRACER
> +struct elem {
> + u64 pad[32];
> + struct rcu_head rcu;
> +};
> +
> +static DEFINE_PER_CPU(int, prog_active);
> +static void * test_alloc(void)
> +{
> + struct elem *e = NULL;
> +
> + if (in_nmi())
> + return e;
> +
> + preempt_disable_notrace();
> + if (unlikely(__this_cpu_inc_return(prog_active) != 1))
> + goto out;
> +
> + rcu_read_lock();
> + e = kmalloc(sizeof(struct elem), GFP_ATOMIC);
> + rcu_read_unlock();
> + if (!e)
> + goto out;
> +
> + kfree_rcu(e, rcu);
> +out:
> + __this_cpu_dec(prog_active);
> + preempt_enable_no_resched_notrace();
> + return e;
> +}
> +
> void trace_preempt_on(unsigned long a0, unsigned long a1)
> {
> + void * buf = 0;
> + static int cnt = 0;
> + if (cnt++ > 3000000)
> + buf = test_alloc();
> if (preempt_trace() && !irq_trace())
> stop_critical_timing(a0, a1);
> }
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
