[Bug runtime/19954] New: "suspicious RCU usage" message on rawhide

["dsmith at redhat dot com" <sourceware-bugzilla at sourceware dot org>]

https://sourceware.org/bugzilla/show_bug.cgi?id=19954

            Bug ID: 19954
           Summary: "suspicious RCU usage" message on rawhide
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: dsmith at redhat dot com
  Target Milestone: ---

While running the testsuite on rawhide (4.6.0-0.rc2.git4.1.fc25.x86_64), I see
the following on the console:

====
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: 
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: ===============================
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [ INFO: suspicious RCU usage. ]
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: 4.6.0-0.rc2.git4.1.fc25.x86_64 #1
Tainted: G           OE  
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: -------------------------------
Apr 15 09:33:27 kvm-rawhide-64-1 kernel:
/usr/local/share/systemtap/runtime/transport/symbols.c:252 suspicious
rcu_dereference_check() usage!
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: #012other info that might help us
debug this:
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: #012rcu_scheduler_active = 1,
debug_locks = 0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: no locks held by staprun/26128.
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: #012stack backtrace:
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: CPU: 0 PID: 26128 Comm: staprun
Tainted: G           OE   4.6.0-0.rc2.git4.1.fc25.x86_64 #1
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: Hardware name: Bochs Bochs, BIOS Bochs
01/01/2011
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: 0000000000000286 00000000bbaf54bd
ffff880079417bf0 ffffffff8145a015
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: ffff88006ff88000 0000000000000001
ffff880079417c20 ffffffff8110f5e7
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: ffff88000a6667b8 0000000000000000
ffff88000a666080 0000000000000000
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: Call Trace:
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8145a015>]
dump_stack+0x86/0xc1
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8110f5e7>]
lockdep_rcu_suspicious+0xd7/0x110
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffffc080ccf5>]
init_module+0x7e5/0xbc0 [stap_b679093e40b76d76682637a57d36403_26128]
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffffc080c510>] ?
_stp_linenumber_lookup+0x9e0/0x9e0 [stap_b679093e40b76d76682637a57d36403_26128]
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff81002123>]
do_one_initcall+0xb3/0x1f0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff81131285>] ?
rcu_read_lock_sched_held+0x45/0x80
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8126b09c>] ?
kmem_cache_alloc_trace+0x2ac/0x310
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff811f35be>] ?
do_init_module+0x27/0x1da
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff811f35f6>]
do_init_module+0x5f/0x1da
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8115d9df>]
load_module+0x21df/0x2940
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff81159fa0>] ?
__symbol_put+0x70/0x70
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff818c6846>] ?
__schedule+0x856/0xbc0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff81158fa0>] ?
show_coresize+0x30/0x30
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff810eef50>] ?
sched_clock_cpu+0x90/0xc0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8123117d>] ?
__might_fault+0x4d/0xa0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8115e2b2>]
SYSC_init_module+0x172/0x1b0
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff8115e41e>]
SyS_init_module+0xe/0x10
Apr 15 09:33:27 kvm-rawhide-64-1 kernel: [<ffffffff818cd1fc>]
entry_SYSCALL_64_fastpath+0x1f/0xbd
====

Here's the odd thing. runtime/transport/symbols.c:252 looks like this:

====
     struct mod_kallsyms *kallsyms = rcu_dereference_sched(mod->kallsyms);
====

Here's the definition of the kallsyms field in struct module from the kernel
source (include/linux/module.h):

====
        /* Protected by RCU and/or module_mutex: use rcu_dereference() */       
        struct mod_kallsyms *kallsyms;                                          
        struct mod_kallsyms core_kallsyms;                                      
====

So, the comment says we should be using 'rcu_dereference()' and systemtap code
is using 'rcu_derefence_sched()'. But, that isn't the problem. Nowhere in the
kernel source is rcu_derefence() used to access mod->kallsyms. Instead
rcu_dereference_sched is used:

====
# fgrep kallsyms kernel/module.c | fgrep rcu
        rcu_assign_pointer(mod->kallsyms, &mod->core_kallsyms);
        struct mod_kallsyms *kallsyms = rcu_dereference_sched(mod->kallsyms);
                kallsyms = rcu_dereference_sched(mod->kallsyms);
        struct mod_kallsyms *kallsyms = rcu_dereference_sched(mod->kallsyms);
====

So, at this point it looks like systemtap code and kernel/module.c are
accessing mod->kallsyms similarly.

So, I'm confused as to what is "suspicious" about our usage.

-- 
You are receiving this mail because:
You are the assignee for the bug.