[Bug kprobes/23276] New: 'suspicious RCU usage' on rawhide 4.18.0-0.rc0

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

[Bug kprobes/23276] New: 'suspicious RCU usage' on rawhide 4.18.0-0.rc0

glaubitz at physik dot fu-berlin.de
https://sourceware.org/bugzilla/show_bug.cgi?id=23276

            Bug ID: 23276
           Summary: 'suspicious RCU usage' on rawhide 4.18.0-0.rc0
           Product: systemtap
           Version: unspecified
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: kprobes
          Assignee: systemtap at sourceware dot org
          Reporter: serhei.public at gmail dot com
  Target Milestone: ---

With Rawhide kernel 4.18.0-0.rc0, getting the following dmesg from the
autotester:

[Jun11 19:14] stap_61cee45e5765364295112bccded04275__24890: systemtap:
4.0/0.171, base:
0000000002ed075d, memory: 3460data/52text/27ctx/2063net/82alloc kb, probes: 202

[  +2.032087] =============================
[  +0.000003] WARNING: suspicious RCU usage
[  +0.000005] 4.18.0-0.rc0.git5.1.fc29.x86_64 #1 Tainted: G           OE
[  +0.000003] -----------------------------
[  +0.000004]
/notnfs/smakarov/stap-checkout/stap_install/share/systemtap/runtime/linux/runtime_context.h:76
suspicious rcu_dereference_check() usage!
[  +0.000003]
              other info that might help us debug this:

[  +0.000003]
              RCU used illegally from idle CPU!
              rcu_scheduler_active = 2, debug_locks = 1
[  +0.000003] RCU used illegally from extended quiescent state!
[  +0.000003] no locks held by swapper/2/0.
[  +0.000003]
              stack backtrace:
[  +0.000005] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G           OE    
4.18.0-0.rc0.git5.1.fc29.x86_64 #1
[  +0.000003] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000003] Call Trace:
[  +0.000004]  <IRQ>
[  +0.000012]  dump_stack+0x85/0xc0
[  +0.001138]  _stp_runtime_entryfn_get_context+0x86/0x90
[stap_61cee45e5765364295112bccded04275__24890]
[  +0.000028]  ? enter_kprobe_probe+0xb5/0x3a0
[stap_61cee45e5765364295112bccded04275__24890]
[  +0.000011]  ? irq_enter+0x1/0x70
[  +0.000008]  ? kprobe_ftrace_handler+0x97/0x100
[  +0.000009]  ? ftrace_ops_assist_func+0x75/0xf0
[  +0.000461]  ? 0xffffffffc04a80bf
[  +0.000018]  ? apic_timer_interrupt+0xa/0x20
[  +0.000007]  ? irq_enter+0x1/0x70
[  +0.000009]  ? irq_enter+0x5/0x70
[  +0.000005]  ? smp_apic_timer_interrupt+0x1c/0x2c0
[  +0.000006]  ? apic_timer_interrupt+0xf/0x20
[  +0.000004]  </IRQ>
[  +0.000020]  ? native_safe_halt+0x2/0x10
[  +0.000007]  ? default_idle+0x1f/0x180
[  +0.000010]  ? do_idle+0x1f5/0x270
[  +0.000011]  ? cpu_startup_entry+0x6f/0x80
[  +0.000008]  ? start_secondary+0x1b3/0x200
[  +0.000008]  ? secondary_startup_64+0xa5/0xb0

[  +0.000216] =============================
[  +0.000002] WARNING: suspicious RCU usage
[  +0.000001] 4.18.0-0.rc0.git5.1.fc29.x86_64 #1 Tainted: G           OE
[  +0.000001] -----------------------------
[  +0.000004] arch/x86/kernel/traps.c:290 entry code didn't wake RCU!

[  +0.000002] other info that might help us debug this:


[  +0.000002] RCU used illegally from idle CPU!
[  +0.000001] rcu_scheduler_active = 2, debug_locks = 1
[  +0.000002] RCU used illegally from extended quiescent state!
[  +0.000001] 1 lock held by swapper/2/0:
[  +0.000001]  #0: 000000007b71c679 (logbuf_lock){-.-.}, at:
vprintk_emit+0xfd/0x540

[  +0.000007] stack backtrace:
[  +0.000001] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G           OE    
4.18.0-0.rc0.git5.1.fc29.x86_64 #1
[  +0.000001] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000001] Call Trace:
[  +0.000001]  <IRQ>
[  +0.000001]  dump_stack+0x85/0xc0
[  +0.000001]  do_error_trap+0x185/0x1a0
[  +0.000002]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  +0.000001]  invalid_op+0x14/0x20
[  +0.000001] RIP: 0010:module_assert_mutex_or_preempt+0x2e/0x40
[  +0.000001] Code: 00 8b 05 85 b9 6f 01 85 c0 74 09 e8 3c 3d fd ff 85 c0 74 01
c3 be ff ff ff ff 48 c7 c7 10 f0 7d ad e8 86 db fa ff 85 c0 75 ea <0f> 0b c3 0f
1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00
[  +0.000060] RSP: 0018:ffff9ce77b203a20 EFLAGS: 00010046
[  +0.000002] RAX: 0000000000000000 RBX: ffffffffc06be145 RCX: 0000000000000002
[  +0.000002] RDX: 0000000000000000 RSI: ffffffffad7df010 RDI: 0000000000000046
[  +0.000001] RBP: ffffffffc06be145 R08: ffff9ce77b203ae9 R09: 0000000052d2710c
[  +0.000001] R10: ffffffffaeec4500 R11: ffffffffae96d5d8 R12: ffff9ce77b203a98
[  +0.000001] R13: ffff9ce77b203aa8 R14: ffff9ce77b203aa0 R15: ffffffffad2d8f16
[  +0.000002] WAR_stp_runtime_entryfn_get_context+0x85/0x90
[stap_61cee45e5765364295112bccded04275__24890]
[  +0.000001]  stap_61cee45e5765364295112bccded04275__24890(OE) uinput
nf_conntrack_netbios_ns nf_conntrack_broadcast devlink xt_CT ip6t_rpfilter
ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat
ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6
nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat
nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c
iptable_mangle iptable_raw iptable_security ebtable_filter ebtables
ip6table_filter ip6_tables sunrpc snd_hda_codec_generic snd_hda_intel
snd_hda_codec snd_hda_core snd_hwdep snd_seq joydev snd_seq_device snd_pcm
snd_timer virtio_balloon snd soundcore i2c_piix4 8139too qxl drm_kms_helper ttm
drm serio_raw virtio_blk virtio_console ata_generic 8139cp mii pata_acpi
qemu_fw_cfg
[  +0.000060]  [last unloaded: stap_55cf9342ec9f8dd00d6844446722b11_24392]
[  +0.000004] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G           OE    
4.18.0-0.rc0.git5.1.fc29.x86_64 #1
[  +0.000001] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000001] RIP: 0010:module_assert_mutex_or_preempt+0x2e/0x40
[  +0.000001] Code: 00 8b 05 85 b9 6f 01 85 c0 74 09 e8 3c 3d fd ff 85 c0 74 01
c3 be ff ff ff ff 48 c7 c7 10 f0 7d ad e8 86 db fa ff 85 c0 75 ea <0f> 0b c3 0f
1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00
[  +0.000055] RSP: 0018:ffff9ce77b203478 EFLAGS: 00010046
[  +0.000002] RAX: 0000000000000000 RBX: ffffffffc06be144 RCX: 0000000000000002
[  +0.000001] RDX: 0000000000000000 RSI: ffffffffad7df010 RDI: 0000000000000046
[  +0.000001] RBP: ffffffffc06be144 R08: ffff9ce77b203541 R09: 0000000052c2f313
[  +0.000001] R10: ffff9ce77b3d8d00 R11: 0000000000000000 R12: ffff9ce77b2034f0
[  +0.000002] R13: ffff9ce77b203500 R14: ffff9ce77b2034f8 R15: ffffffffad2d8f16
[  +0.000001] FS:  0000000000000000(0000) GS:ffff9ce77b200000(0000)
knlGS:0000000000000000
[  +0.000002] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  +0.000002] CR2: 00007ff92692f598 CR3: 000000002a0ea000 CR4: 00000000000006e0
[  +0.000001] DR0: ffffffffc04d4108 DR1: 0000000000000000 DR2: 0000000000000000
[  +0.000001] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[  +0.000001] Call Trace:
[  +0.000001]  <IRQ>
[  +0.000001]  __module_address+0
[  +0.000003] Lost 505 message(s)!
[ +30.060459] stap_fe72e0969e7a0dfe3c9d082ea5c5ca3c__25387: systemtap:
4.0/0.171, base:
00000000dba24f97, memory: 3460data/52text/27ctx/2063net/82alloc kb, probes: 202

[  +2.308311] =============================
[  +0.000002] WARNING: suspicious RCU usage
[  +0.000004] 4.18.0-0.rc0.git5.1.fc29.x86_64 #1 Tainted: G        W  OE
[  +0.000003] -----------------------------
[  +0.000004]
/notnfs/smakarov/stap-checkout/stap_install/share/systemtap/runtime/linux/
runtime_context.h:76 suspicious rcu_dereference_check() usage!
[  +0.000002]
              other info that might help us debug this:

[  +0.000004]
              RCU used illegally from idle CPU!
              rcu_scheduler_active = 2, debug_locks = 1
[  +0.000003] RCU used illegally from extended quiescent state!
[  +0.000003] no locks held by swapper/0/0.
[  +0.000003]
              stack backtrace:
[  +0.000005] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W  OE    
4.18.0-0.rc0.git
5.1.fc29.x86_64 #1
[  +0.000003] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000002] Call Trace:
[  +0.000004]  <IRQ>
[  +0.000011]  dump_stack+0x85/0xc0
[  +0.000030]  _stp_runtime_entryfn_get_context+0x86/0x90
[stap_fe72e0969e7a0dfe3c9d082ea5c5ca3c__25387]
[  +0.000025]  ? enter_kprobe_probe+0xb5/0x3a0
[stap_fe72e0969e7a0dfe3c9d082ea5c5ca3c__25387]
[  +0.000012]  ? irq_enter+0x1/0x70
[  +0.000008]  ? kprobe_ftrace_handler+0x97/0x100
[  +0.000009]  ? ftrace_ops_assist_func+0x75/0xf0
[  +0.000021]  ? 0xffffffffc04a80bf
[  +0.000019]  ? apic_timer_interrupt+0xa/0x20
[  +0.000006]  ? irq_enter+0x1/0x70
[  +0.000009]  ? irq_enter+0x5/0x70
[  +0.000005]  ? smp_apic_timer_interrupt+0x1c/0x2c0
[  +0.000006]  ? apic_timer_interrupt+0xf/0x20
[  +0.000003]  </IRQ>
[  +0.000017]  ? native_safe_halt+0x2/0x10
[  +0.000007]  ? default_idle+0x1f/0x180
[  +0.000009]  ? do_idle+0x1f5/0x270
[  +0.000010]  ? cpu_startup_entry+0x6f/0x80
[  +0.000017]  ? start_kernel+0x567/0x587
[  +0.000012]  ? secondary_startup_64+0xa5/0xb0
[Jun11 19:15] stap_5edf7cc3741a456c5a5d56b31620e2f1__25886: systemtap:
4.0/0.171, base:
0000000002ed075d, memory: 3460data/52text/27ctx/2063net/82alloc kb, probes: 202

[  +2.254638] =============================
[  +0.000002] WARNING: suspicious RCU usage
[  +0.000004] 4.18.0-0.rc0.git5.1.fc29.x86_64 #1 Tainted: G        W  OE
[  +0.000003] -----------------------------
[  +0.000004]
/notnfs/smakarov/stap-checkout/stap_install/share/systemtap/runtime/linux/runtime_context.h:76
suspicious rcu_dereference_check() usage!
[  +0.000002]
              other info that might help us debug this:

[  +0.000003]
              RCU used illegally from idle CPU!
              rcu_scheduler_active = 2, debug_locks = 1
[  +0.000003] RCU used illegally from extended quiescent state!
[  +0.000003] no locks held by swapper/1/0.
[  +0.000002]
              stack backtrace:
[  +0.000005] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W  OE    
4.18.0-0.rc0.git5.1.fc29.x86_64 #1
[  +0.000003] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000003] Call Trace:
[  +0.000004]  <IRQ>
[  +0.000011]  dump_stack+0x85/0xc0
[  +0.000033]  _stp_runtime_entryfn_get_context+0x86/0x90
[stap_5edf7cc3741a456c5a5d56b31620e2f1__25886]
[  +0.000023]  ? enter_kprobe_probe+0xb5/0x3a0
[stap_5edf7cc3741a456c5a5d56b31620e2f1__25886]
[  +0.000010]  ? irq_enter+0x1/0x70
[  +0.000008]  ? kprobe_ftrace_handler+0x97/0x100
[  +0.000009]  ? ftrace_ops_assist_func+0x75/0xf0
[  +0.000019]  ? 0xffffffffc04a80bf
[  +0.000018]  ? apic_timer_interrupt+0xa/0x20
[  +0.000006]  ? irq_enter+0x1/0x70
[  +0.000009]  ? irq_enter+0x5/0x70
[  +0.000004]  ? smp_apic_timer_interrupt+0x1c/0x2c0
[  +0.000006]  ? apic_timer_interrupt+0xf/0x20
[  +0.000004]  </IRQ>
[  +0.000018]  ? native_safe_halt+0x2/0x10
[  +0.000007]  ? default_idle+0x1f/0x180
[  +0.000009]  ? do_idle+0x1f5/0x270
[  +0.000010]  ? cpu_startup_entry+0x6f/0x80
[  +0.000009]  ? start_secondary+0x1b3/0x200
[  +0.000008]  ? secondary_startup_64+0xa5/0xb0
[ +31.545700] stap_99eefb40f93f2571f5bf3f967972831b__26385: systemtap:
4.0/0.171, base:
00000000dba24f97, memory: 3544data/76text/29ctx/2063net/82alloc kb, probes: 202

[  +2.244447] =============================
[  +0.000003] WARNING: suspicious RCU usage
[  +0.000004] 4.18.0-0.rc0.git5.1.fc29.x86_64 #1 Tainted: G        W  OE
[  +0.000002] -----------------------------
[  +0.000005]
/notnfs/smakarov/stap-checkout/stap_install/share/systemtap/runtime/linux/runtime_context.h:76
suspicious rcu_dereference_check() usage!
[  +0.000002]
              other info that might help us debug this:

[  +0.000003]
              RCU used illegally from idle CPU!
              rcu_scheduler_active = 2, debug_locks = 1
[  +0.000003] RCU used illegally from extended quiescent state!
[  +0.000003] no locks held by swapper/2/0.
[  +0.000003]
              stack backtrace:
[  +0.000005] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G        W  OE    
4.18.0-0.rc0.git5.1.fc29.x86_64 #1
[  +0.000003] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-2.fc27
04/01/2014
[  +0.000003] Call Trace:
[  +0.000004]  <IRQ>
[  +0.000010]  dump_stack+0x85/0xc0
[  +0.000038]  _stp_runtime_entryfn_get_context+0x86/0x90
[stap_99eefb40f93f2571f5bf3f967972831b__26385]
[  +0.000040]  ? enter_kprobe_probe+0xb5/0x3a0
[stap_99eefb40f93f2571f5bf3f967972831b__26385]
[  +0.000011]  ? irq_enter+0x1/0x70
[  +0.000007]  ? kprobe_ftrace_handler+0x97/0x100
[  +0.000009]  ? ftrace_ops_assist_func+0x75/0xf0
[  +0.000005]  ? rcu_read_lock_sched_held+0x6b/0x80
[  +0.000005]  ? rcu_process_callbacks+0x479/0x7b0
[  +0.000018]  ? 0xffffffffc04a80bf
[  +0.000018]  ? irq_enter+0x1/0x70
[  +0.000009]  ? irq_enter+0x5/0x70
[  +0.000005]  ? scheduler_ipi+0xa5/0x130
[  +0.000006]  ? reschedule_interrupt+0xf/0x20
[  +0.000004]  </IRQ>
[  +0.000018]  ? native_safe_halt+0x2/0x10
[  +0.000008]  ? default_idle+0x1f/0x180
[  +0.000008]  ? do_idle+0x1f5/0x270
[  +0.000011]  ? cpu_startup_entry+0x6f/0x80
[  +0.000008]  ? start_secondary+0x1b3/0x200
[  +0.000007]  ? secondary_startup_64+0xa5/0xb0

The full testsuite run hangs (does not finish, system unresponsive) sometime
after the suspicious tests (many more tests finish before that happens).

--
You are receiving this mail because:
You are the assignee for the bug.
Reply | Threaded
Open this post in threaded view
|

[Bug kprobes/23276] 'suspicious RCU usage' on rawhide 4.18.0-0.rc0

glaubitz at physik dot fu-berlin.de
https://sourceware.org/bugzilla/show_bug.cgi?id=23276

--- Comment #1 from Serhei Makarov <serhei.public at gmail dot com> ---
This happens consistently during the testcase pr14546.exp.

--
You are receiving this mail because:
You are the assignee for the bug.
Reply | Threaded
Open this post in threaded view
|

[Bug kprobes/23276] 'suspicious RCU usage' on rawhide 4.18.0-0.rc0

glaubitz at physik dot fu-berlin.de
In reply to this post by glaubitz at physik dot fu-berlin.de
https://sourceware.org/bugzilla/show_bug.cgi?id=23276

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|UNCONFIRMED                 |RESOLVED
                 CC|                            |fche at redhat dot com
         Resolution|---                         |FIXED

--- Comment #2 from Frank Ch. Eigler <fche at redhat dot com> ---
commit 2699450dde9af4cc609bdeca2b346a014840f0f0
Author: Frank Ch. Eigler <[hidden email]>
Date:   Thu Jan 23 13:35:30 2020 -0500

    RHBZ1788662: check rcu_is_watching() before probe entry

--
You are receiving this mail because:
You are the assignee for the bug.
Reply | Threaded
Open this post in threaded view
|

[Bug kprobes/23276] 'suspicious RCU usage' on rawhide 4.18.0-0.rc0

glaubitz at physik dot fu-berlin.de
In reply to this post by glaubitz at physik dot fu-berlin.de
https://sourceware.org/bugzilla/show_bug.cgi?id=23276

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dsmith at redhat dot com

--- Comment #3 from Frank Ch. Eigler <fche at redhat dot com> ---
*** Bug 22182 has been marked as a duplicate of this bug. ***

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