2023-01-19 15:07:34

by kernel test robot

[permalink] [raw]
Subject: [tip:sched/core] [tracing, hardirq] 9aedeaed6f: WARNING:suspicious_RCU_usage


Greeting,

FYI, we noticed WARNING:suspicious_RCU_usage due to commit (built with gcc-11):

commit: 9aedeaed6fc6fe8452b9b8225e95cc2b8631ff91 ("tracing, hardirq: No moar _rcuidle() tracing")
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git sched/core

[test failed on linux-next/master f3381a7baf5ccbd091eb2c4fd2afd84266fcef24]

in testcase: kernel-selftests
version: kernel-selftests-x86_64-d4cf28ee-1_20230110
with following parameters:

group: ftrace

test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
test-url: https://www.kernel.org/doc/Documentation/kselftest.txt


on test machine: 4 threads Intel(R) Xeon(R) CPU E3-1225 v5 @ 3.30GHz (Skylake) with 16G memory

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <[email protected]>
| Link: https://lore.kernel.org/oe-lkp/[email protected]


[ 137.120136][ T0] WARNING: suspicious RCU usage
[ 137.120151][ T0] 6.2.0-rc1-00074-g9aedeaed6fc6 #1 Not tainted
[ 137.120168][ T0] -----------------------------
[ 137.120182][ T0] include/trace/events/lock.h:24 suspicious rcu_dereference_check() usage!
[ 137.120198][ T0]
[ 137.120198][ T0] other info that might help us debug this:
[ 137.120198][ T0]
[ 137.120213][ T0]
[ 137.120213][ T0] rcu_scheduler_active = 2, debug_locks = 1
[ 137.120228][ T0] RCU used illegally from extended quiescent state!
[ 137.120242][ T0] no locks held by swapper/0/0.
[ 137.120256][ T0]
[ 137.120256][ T0] stack backtrace:
[ 137.120273][ T0] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.2.0-rc1-00074-g9aedeaed6fc6 #1
[ 137.120289][ T0] Hardware name: HP HP Z238 Microtower Workstation/8183, BIOS N51 Ver. 01.63 10/05/2017
[ 137.120306][ T0] Call Trace:
[ 137.120333][ T0] <TASK>
[ 137.120420][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.120448][ T0] dump_stack_lvl (lib/dump_stack.c:107 (discriminator 4))
[ 137.120517][ T0] lock_acquire.cold (include/trace/events/lock.h:24 kernel/locking/lockdep.c:5639)
[ 137.120620][ T0] ? rcu_read_unlock (include/linux/rcupdate.h:793 (discriminator 5))
[ 137.120734][ T0] ------------[ cut here ]------------
[ 137.120749][ T0] WARNING: CPU: 0 PID: 0 at kernel/module/internal.h:115 __module_address (kernel/module/main.c:3100 kernel/module/main.c:3081)
[ 137.120778][ T0] Modules linked in: openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 btrfs intel_rapl_msr blake2b_generic xor intel_rapl_common raid6_pq zstd_compress libcrc32c x86_pkg_temp_thermal intel_powerclamp coretemp sd_mod t10_pi kvm_intel crc64_rocksoft_generic crc64_rocksoft crc64 kvm sg irqbypass crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel sha512_ssse3 mei_wdt ipmi_devintf wmi_bmof i915 rapl ipmi_msghandler intel_cstate drm_buddy intel_gtt drm_display_helper i2c_i801 ttm ahci intel_uncore drm_kms_helper libahci mei_me serio_raw i2c_smbus syscopyarea sysfillrect libata ie31200_edac mei sysimgblt intel_pch_thermal video wmi intel_pmc_core acpi_pad tpm_infineon binfmt_misc drm fuse ip_tables [last unloaded: ftrace_direct]
[ 137.121813][ T0] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.2.0-rc1-00074-g9aedeaed6fc6 #1
[ 137.121830][ T0] Hardware name: HP HP Z238 Microtower Workstation/8183, BIOS N51 Ver. 01.63 10/05/2017
[ 137.121848][ T0] RIP: 0010:__module_address (kernel/module/main.c:3100 kernel/module/main.c:3081)
[ 137.121877][ T0] Code: 01 00 00 48 01 da 48 39 d5 0f 82 69 ff ff ff 0f 0b be ff ff ff ff 48 c7 c7 48 56 9f 84 e8 e6 88 3b 02 85 c0 0f 85 d1 fe ff ff <0f> 0b e9 ca fe ff ff 48 83 c4 08 31 c0 5b 5d c3 48 c7 c7 cc 15 29
All code
========
0: 01 00 add %eax,(%rax)
2: 00 48 01 add %cl,0x1(%rax)
5: da 48 39 fimull 0x39(%rax)
8: d5 (bad)
9: 0f 82 69 ff ff ff jb 0xffffffffffffff78
f: 0f 0b ud2
11: be ff ff ff ff mov $0xffffffff,%esi
16: 48 c7 c7 48 56 9f 84 mov $0xffffffff849f5648,%rdi
1d: e8 e6 88 3b 02 callq 0x23b8908
22: 85 c0 test %eax,%eax
24: 0f 85 d1 fe ff ff jne 0xfffffffffffffefb
2a:* 0f 0b ud2 <-- trapping instruction
2c: e9 ca fe ff ff jmpq 0xfffffffffffffefb
31: 48 83 c4 08 add $0x8,%rsp
35: 31 c0 xor %eax,%eax
37: 5b pop %rbx
38: 5d pop %rbp
39: c3 retq
3a: 48 rex.W
3b: c7 .byte 0xc7
3c: c7 (bad)
3d: cc int3
3e: 15 .byte 0x15
3f: 29 .byte 0x29

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: e9 ca fe ff ff jmpq 0xfffffffffffffed1
7: 48 83 c4 08 add $0x8,%rsp
b: 31 c0 xor %eax,%eax
d: 5b pop %rbx
e: 5d pop %rbp
f: c3 retq
10: 48 rex.W
11: c7 .byte 0xc7
12: c7 (bad)
13: cc int3
14: 15 .byte 0x15
15: 29 .byte 0x29
[ 137.121895][ T0] RSP: 0018:ffffffff84406b40 EFLAGS: 00010046
[ 137.121924][ T0] RAX: 0000000000000000 RBX: ffffffff84406d38 RCX: 0000000000000001
[ 137.121939][ T0] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffffffff849f5648
[ 137.121954][ T0] RBP: ffffffffa03e6086 R08: 0000000000000000 R09: ffff88837f43f943
[ 137.121969][ T0] R10: ffffed106fe87f28 R11: 0000000000000001 R12: ffffffff84406c30
[ 137.121984][ T0] R13: ffffffff84406c10 R14: ffffffffa03e6086 R15: ffffffff84406c70
[ 137.121999][ T0] FS: 0000000000000000(0000) GS:ffff88837f400000(0000) knlGS:0000000000000000
[ 137.122014][ T0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 137.122030][ T0] CR2: 0000000000451c00 CR3: 000000043ce2a003 CR4: 00000000003706f0
[ 137.122046][ T0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 137.122061][ T0] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 137.122078][ T0] Call Trace:
[ 137.122100][ T0] <TASK>
[ 137.122173][ T0]
[ 137.122187][ T0] =============================
[ 137.122202][ T0] WARNING: suspicious RCU usage
[ 137.122217][ T0] 6.2.0-rc1-00074-g9aedeaed6fc6 #1 Not tainted
[ 137.122231][ T0] -----------------------------
[ 137.122245][ T0] include/linux/rcupdate.h:765 rcu_read_lock() used illegally while idle!
[ 137.122260][ T0]
[ 137.122260][ T0] other info that might help us debug this:
[ 137.122260][ T0]
[ 137.122275][ T0]
[ 137.122275][ T0] rcu_scheduler_active = 2, debug_locks = 1
[ 137.122290][ T0] RCU used illegally from extended quiescent state!
[ 137.122304][ T0] 1 lock held by swapper/0/0:
[ 137.122319][ T0] #0: ffffffff84925b40 (rcu_read_lock){....}-{1:2}, at: __bpf_address_lookup (kernel/bpf/core.c:690)
[ 137.122417][ T0]
[ 137.122417][ T0] stack backtrace:
[ 137.122433][ T0] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.2.0-rc1-00074-g9aedeaed6fc6 #1
[ 137.122449][ T0] Hardware name: HP HP Z238 Microtower Workstation/8183, BIOS N51 Ver. 01.63 10/05/2017
[ 137.122466][ T0] Call Trace:
[ 137.122491][ T0] <TASK>
[ 137.122577][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.122598][ T0] dump_stack_lvl (lib/dump_stack.c:107 (discriminator 4))
[ 137.122630][ T0] ? 0xffffffffa03e6085
[ 137.127567][ T0] __bpf_address_lookup (include/linux/rcupdate.h:765 kernel/bpf/core.c:694)
[ 137.127635][ T0] ? 0xffffffffa03e6085
[ 137.127738][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.127759][ T0] kallsyms_lookup_buildid (include/linux/filter.h:1145 kernel/kallsyms.c:434)
[ 137.127883][ T0] ? 0xffffffffa03e6086
[ 137.127932][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.127953][ T0] __sprint_symbol+0xaf/0x1c0
[ 137.127981][ T0] ? prepare_ftrace_return (arch/x86/kernel/ftrace.c:653)
[ 137.128042][ T0] ? kallsyms_lookup_buildid (kernel/kallsyms.c:517)
[ 137.128144][ T0] ? 0xffffffffa03e6087
[ 137.128193][ T0] ? ftrace_return_to_handler (arch/x86/include/asm/current.h:41 kernel/trace/fgraph.c:257)
[ 137.128421][ T0] ? 0xffffffffa03e6086
[ 137.128596][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.128617][ T0] symbol_string (lib/vsprintf.c:994)
[ 137.128664][ T0] ? rb_handle_head_page (kernel/trace/ring_buffer.c:1411 kernel/trace/ring_buffer.c:1444 kernel/trace/ring_buffer.c:2650)
[ 137.128724][ T0] ? ip6_addr_string (lib/vsprintf.c:982)
[ 137.128855][ T0] ? __rb_reserve_next (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:2952 kernel/trace/ring_buffer.c:3709)
[ 137.129239][ T0] ? __rb_reserve_next (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:2952 kernel/trace/ring_buffer.c:3709)
[ 137.129575][ T0] ? ring_buffer_lock_reserve (kernel/trace/ring_buffer.c:3781 kernel/trace/ring_buffer.c:3838)
[ 137.129861][ T0] ? __rb_reserve_next (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:2952 kernel/trace/ring_buffer.c:3709)
[ 137.130068][ T0] ? __rb_reserve_next (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:2952 kernel/trace/ring_buffer.c:3709)
[ 137.130331][ T0] ? __rb_reserve_next (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:2952 kernel/trace/ring_buffer.c:3709)
[ 137.130625][ T0] ? move_right (lib/vsprintf.c:617)
[ 137.130855][ T0] ? 0xffffffffa03e6086
[ 137.130905][ T0] pointer (lib/vsprintf.c:2394)
[ 137.131025][ T0] ? resource_string+0x1590/0x1590
[ 137.131106][ T0] ? rb_commit (arch/x86/include/asm/atomic64_64.h:22 include/linux/atomic/atomic-long.h:29 include/linux/atomic/atomic-instrumented.h:1266 kernel/trace/ring_buffer.c:3181 kernel/trace/ring_buffer.c:3204)
[ 137.131331][ T0] vsnprintf (lib/vsprintf.c:2802)
[ 137.131521][ T0] ? pointer (lib/vsprintf.c:2727)
[ 137.131617][ T0] ? __trace_graph_entry (kernel/trace/trace_functions_graph.c:113)
[ 137.131820][ T0] vprintk_store (kernel/printk/printk.c:2241)
[ 137.131956][ T0] ? ftrace_graph_stop (kernel/trace/fgraph.c:124)
[ 137.132016][ T0] ? printk_sprint (kernel/printk/printk.c:2206)
[ 137.132040][ T0] ? vprintk (kernel/printk/printk_safe.c:30)
[ 137.132188][ T0] ? vprintk_store (kernel/printk/printk.c:2206)
[ 137.132266][ T0] ? prepare_ftrace_return (arch/x86/kernel/ftrace.c:653)
[ 137.132384][ T0] ? 0xffffffffa03e6086
[ 137.132438][ T0] ? 0xffffffffa03e6087
[ 137.132853][ T0] ? 0xffffffffa03e6086
[ 137.132884][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.132905][ T0] vprintk (kernel/printk/printk_safe.c:44 kernel/printk/printk_safe.c:29)
[ 137.132950][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.132971][ T0] _printk (kernel/printk/printk.c:2373)
[ 137.133034][ T0] ? record_print_text.cold (kernel/printk/printk.c:2373)
[ 137.133242][ T0] ? 0xffffffffa03e6086
[ 137.133368][ T0] ? 0xffffffffa03e6086
[ 137.133471][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.133492][ T0] show_trace_log_lvl (arch/x86/kernel/dumpstack.c:284)
[ 137.133561][ T0] ? 0xffffffffa03e6086
[ 137.133886][ T0] ? 0xffffffffa03e6086
[ 137.133916][ T0] ? module_address_lookup (kernel/module/kallsyms.c:339)
[ 137.134048][ T0] ? __module_address (kernel/module/main.c:3100 kernel/module/main.c:3081)
[ 137.134107][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.134128][ T0] __warn (kernel/panic.c:664)
[ 137.134210][ T0] ? __module_address (kernel/module/main.c:3100 kernel/module/main.c:3081)
[ 137.134287][ T0] ? ftrace_regs_caller_end (arch/x86/kernel/ftrace_64.S:345)
[ 137.134308][ T0] report_bug (lib/bug.c:200)
[ 137.134480][ T0] handle_bug (arch/x86/kernel/traps.c:324)
[ 137.134525][ T0] exc_invalid_op (arch/x86/kernel/traps.c:345 (discriminator 1))
[ 137.134589][ T0] asm_exc_invalid_op (arch/x86/include/asm/idtentry.h:568)
[ 137.134615][ T0] RIP: 0010:__module_address (kernel/module/main.c:3100 kernel/module/main.c:3081)
[ 137.134622][ T0] Code: 01 00 00 48 01 da 48 39 d5 0f 82 69 ff ff ff 0f 0b be ff ff ff ff 48 c7 c7 48 56 9f 84 e8 e6 88 3b 02 85 c0 0f 85 d1 fe ff ff <0f> 0b e9 ca fe ff ff 48 83 c4 08 31 c0 5b 5d c3 48 c7 c7 cc 15 29
All code
========
0: 01 00 add %eax,(%rax)
2: 00 48 01 add %cl,0x1(%rax)
5: da 48 39 fimull 0x39(%rax)
8: d5 (bad)
9: 0f 82 69 ff ff ff jb 0xffffffffffffff78
f: 0f 0b ud2
11: be ff ff ff ff mov $0xffffffff,%esi
16: 48 c7 c7 48 56 9f 84 mov $0xffffffff849f5648,%rdi
1d: e8 e6 88 3b 02 callq 0x23b8908
22: 85 c0 test %eax,%eax
24: 0f 85 d1 fe ff ff jne 0xfffffffffffffefb
2a:* 0f 0b ud2 <-- trapping instruction
2c: e9 ca fe ff ff jmpq 0xfffffffffffffefb
31: 48 83 c4 08 add $0x8,%rsp
35: 31 c0 xor %eax,%eax
37: 5b pop %rbx
38: 5d pop %rbp
39: c3 retq
3a: 48 rex.W
3b: c7 .byte 0xc7
3c: c7 (bad)
3d: cc int3
3e: 15 .byte 0x15
3f: 29 .byte 0x29

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: e9 ca fe ff ff jmpq 0xfffffffffffffed1
7: 48 83 c4 08 add $0x8,%rsp
b: 31 c0 xor %eax,%eax
d: 5b pop %rbx
e: 5d pop %rbp
f: c3 retq
10: 48 rex.W
11: c7 .byte 0xc7
12: c7 (bad)
13: cc int3
14: 15 .byte 0x15
15: 29 .byte 0x29


To reproduce:

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
sudo bin/lkp install job.yaml # job file is attached in this email
bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
sudo bin/lkp run generated-yaml-file

# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests



Attachments:
(No filename) (15.38 kB)
config-6.2.0-rc1-00074-g9aedeaed6fc6 (172.17 kB)
job-script (6.28 kB)
dmesg.xz (50.94 kB)
kernel-selftests (232.27 kB)
job.yaml (5.14 kB)
reproduce (247.00 B)
Download all attachments

2023-01-19 16:37:24

by Peter Zijlstra

[permalink] [raw]
Subject: Re: [tip:sched/core] [tracing, hardirq] 9aedeaed6f: WARNING:suspicious_RCU_usage

On Thu, Jan 19, 2023 at 10:06:21PM +0800, kernel test robot wrote:
>
> Greeting,
>
> FYI, we noticed WARNING:suspicious_RCU_usage due to commit (built with gcc-11):
>
> commit: 9aedeaed6fc6fe8452b9b8225e95cc2b8631ff91 ("tracing, hardirq: No moar _rcuidle() tracing")
> https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git sched/core
>
> [test failed on linux-next/master f3381a7baf5ccbd091eb2c4fd2afd84266fcef24]
>
> in testcase: kernel-selftests
> version: kernel-selftests-x86_64-d4cf28ee-1_20230110
> with following parameters:
>
> group: ftrace

Moo, so I've had these patches in my git tree for months :/

The thing that seems to shut it up is the below, but I'm not entirely
sure how we get there, all the code should be cpuidle/noinstr, which
implies notrace.

Steve, what's the easiest way to figure out what triggers this? Put a
printk() in prepare_ftrace_return() or so?

---

diff --git a/include/linux/cpuidle.h b/include/linux/cpuidle.h
index 3183aeb7f5b4..fecdf0bb3bc4 100644
--- a/include/linux/cpuidle.h
+++ b/include/linux/cpuidle.h
@@ -15,6 +15,7 @@
#include <linux/list.h>
#include <linux/hrtimer.h>
#include <linux/context_tracking.h>
+#include <linux/ftrace.h>

#define CPUIDLE_STATE_MAX 10
#define CPUIDLE_NAME_LEN 16
@@ -119,6 +120,7 @@ DECLARE_PER_CPU(struct cpuidle_device, cpuidle_dev);
static __always_inline void ct_cpuidle_enter(void)
{
lockdep_assert_irqs_disabled();
+ pause_graph_tracing();
/*
* Idle is allowed to (temporary) enable IRQs. It
* will return with IRQs disabled.
@@ -143,6 +145,7 @@ static __always_inline void ct_cpuidle_exit(void)
lockdep_hardirqs_off(_RET_IP_);
ct_idle_exit();
instrumentation_begin();
+ unpause_graph_tracing();
}

/****************************

2023-01-19 16:49:53

by Steven Rostedt

[permalink] [raw]
Subject: Re: [tip:sched/core] [tracing, hardirq] 9aedeaed6f: WARNING:suspicious_RCU_usage

On Thu, 19 Jan 2023 16:45:49 +0100
Peter Zijlstra <[email protected]> wrote:

> Steve, what's the easiest way to figure out what triggers this? Put a
> printk() in prepare_ftrace_return() or so?

Does it only trigger if all functions are enabled when running function
graph tracer?

That is, if you just trace one function, say "schedule" does it
have an issue?

trace-cmd start -p function_graph -l schedule

And then run your code, and it doesn't trigger, but:


trace-cmd reset # make sure schedule is no longer filtered
trace-cmd start -p function_graph

does trigger the issue, you can then bisect the functions with the script:

scripts/tracing/ftrace-bisect.sh

in the kernel tree.

I need to update this script, because I've optimized it with the "number"
trick. That is, instead echoing in the names of functions, you echo in the
location of were they exist in the available_filter_functions file.

That is: echo 5 > set_ftrace_filter

Will enable the fifth function in available_filter_functions. The reason
for this is because this is an O(1) operation. And echoing in thousands of
these numbers is an O(n) operation where n is the number of functions you
echo in. But by doing it via names, its an O(n*m) operation, where m is the
number of *all* functions, and this can take several minutes to complete,
were as the "number" version usually takes less than a second.

Here's what you can do (ignore the instructions in the script, as that
needs to be updated):

# cd /sys/kernel/tracing
# seq `wc -l available_filter_functions | cut -d' ' -f1` > ~/full-file
# /path/to/ftrace-bisect ~/full-file ~/test-file ~/non-test-file
# cat ~/test-file > set_ftrace_filter

run your tests. If they don't fail (bisect good), then, you can assume that
the bad function is in ~/non-test-file

# /path/to/ftrace-bisect ~/non-test-file ~/test-file.1 ~/non-test-file.1

And repeat:

# cat ~/test-file.1 > set_ftrace_filter

I suggest appending the ".1", ".2", etc, in case something goes wrong and
you want to go back (basically a bisect log).

If the test fails, then you use the first file:

# /path/to/ftrace-bisect ~/test-file.1 ~/test-file.2 ~/non-test-file.2

Keep going until you find a single function that causes the issue.

Always cat the "test-file*" into the set_ftrace_filter.

If it works use the "non-test-file*" for the next iteration. If it fails,
use the "test-file*" for the next iteration.

-- Steve

2023-01-20 10:10:40

by Peter Zijlstra

[permalink] [raw]
Subject: Re: [tip:sched/core] [tracing, hardirq] 9aedeaed6f: WARNING:suspicious_RCU_usage

On Thu, Jan 19, 2023 at 11:24:33AM -0500, Steven Rostedt wrote:
> On Thu, 19 Jan 2023 16:45:49 +0100
> Peter Zijlstra <[email protected]> wrote:
>
> > Steve, what's the easiest way to figure out what triggers this? Put a
> > printk() in prepare_ftrace_return() or so?
>
> Does it only trigger if all functions are enabled when running function
> graph tracer?
>
> That is, if you just trace one function, say "schedule" does it
> have an issue?
>
> trace-cmd start -p function_graph -l schedule
>
> And then run your code, and it doesn't trigger, but:
>
>
> trace-cmd reset # make sure schedule is no longer filtered
> trace-cmd start -p function_graph
>
> does trigger the issue, you can then bisect the functions with the script:
>
> scripts/tracing/ftrace-bisect.sh

Pff, that all sounds like actual work :-)

Instead I did me the below hack and added my early_printk() hacks and
that got me a usable backtrace.

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 5e7ead52cfdb..7defc6e24f8f 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -646,6 +646,9 @@ void prepare_ftrace_return(unsigned long ip, unsigned long *parent,
if (unlikely(atomic_read(&current->tracing_graph_pause)))
return;

+ if (WARN_ONCE(!rcu_is_watching(), "RCU not on for: %pS\n", (void *)ip))
+ return;
+
bit = ftrace_test_recursion_trylock(ip, *parent);
if (bit < 0)
return;

2023-01-21 17:35:03

by Steven Rostedt

[permalink] [raw]
Subject: Re: [tip:sched/core] [tracing, hardirq] 9aedeaed6f: WARNING:suspicious_RCU_usage

On Fri, 20 Jan 2023 10:51:18 +0100
Peter Zijlstra <[email protected]> wrote:

> > does trigger the issue, you can then bisect the functions with the script:
> >
> > scripts/tracing/ftrace-bisect.sh
>
> Pff, that all sounds like actual work :-)
>
> Instead I did me the below hack and added my early_printk() hacks and
> that got me a usable backtrace.

Well, if you system is still running after the issue, then sure. I created
this when it would cause a triple fault reboot. In which case, there was no
real debugging output to use.

-- Steve


>
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 5e7ead52cfdb..7defc6e24f8f 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -646,6 +646,9 @@ void prepare_ftrace_return(unsigned long ip, unsigned long *parent,
> if (unlikely(atomic_read(&current->tracing_graph_pause)))
> return;
>
> + if (WARN_ONCE(!rcu_is_watching(), "RCU not on for: %pS\n", (void *)ip))
> + return;
> +
> bit = ftrace_test_recursion_trylock(ip, *parent);
> if (bit < 0)
> return;

Subject: [tip: sched/core] cpuidle: Fix poll_idle() noinstr annotation

The following commit has been merged into the sched/core branch of tip:

Commit-ID: 4d627628d7584f3d3add1d53342d0f01aa878e04
Gitweb: https://git.kernel.org/tip/4d627628d7584f3d3add1d53342d0f01aa878e04
Author: Peter Zijlstra <[email protected]>
AuthorDate: Thu, 26 Jan 2023 16:08:38 +01:00
Committer: Ingo Molnar <[email protected]>
CommitterDate: Tue, 31 Jan 2023 15:01:47 +01:00

cpuidle: Fix poll_idle() noinstr annotation

The instrumentation_begin()/end() annotations in poll_idle() were
complete nonsense. Specifically they caused tracing to happen in the
middle of noinstr code, resulting in RCU splats.

Now that local_clock() is noinstr, mark up the rest and let it rip.

Fixes: 00717eb8c955 ("cpuidle: Annotate poll_idle()")
Reported-by: kernel test robot <[email protected]>
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
Acked-by: Rafael J. Wysocki <[email protected]>
Link: https://lore.kernel.org/oe-lkp/[email protected]
Link: https://lore.kernel.org/r/[email protected]
---
drivers/cpuidle/cpuidle.c | 2 +-
drivers/cpuidle/poll_state.c | 2 --
2 files changed, 1 insertion(+), 3 deletions(-)

diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
index 500d172..0b00f21 100644
--- a/drivers/cpuidle/cpuidle.c
+++ b/drivers/cpuidle/cpuidle.c
@@ -426,7 +426,7 @@ void cpuidle_reflect(struct cpuidle_device *dev, int index)
* @dev: the cpuidle device
*
*/
-u64 cpuidle_poll_time(struct cpuidle_driver *drv,
+__cpuidle u64 cpuidle_poll_time(struct cpuidle_driver *drv,
struct cpuidle_device *dev)
{
int i;
diff --git a/drivers/cpuidle/poll_state.c b/drivers/cpuidle/poll_state.c
index d25ec52..bdcfeae 100644
--- a/drivers/cpuidle/poll_state.c
+++ b/drivers/cpuidle/poll_state.c
@@ -15,7 +15,6 @@ static int __cpuidle poll_idle(struct cpuidle_device *dev,
{
u64 time_start;

- instrumentation_begin();
time_start = local_clock();

dev->poll_time_limit = false;
@@ -42,7 +41,6 @@ static int __cpuidle poll_idle(struct cpuidle_device *dev,
raw_local_irq_disable();

current_clr_polling();
- instrumentation_end();

return index;
}