Re: [PATCH v1] Ftrace: make sched_wakeup can focus on the target process
Hello,
kernel test robot noticed "BUG:kernel_NULL_pointer_dereference,address" on:
commit: e70b12f847f6d1b5db838c0eefa9d1d00c1591bd ("[PATCH v1] Ftrace: make
sched_wakeup can focus on the target process")
url:
https://github.com/intel-lab-lkp/linux/commits/Jinyu-Tang/Ftrace-make-sched_wakeup-can-focus-on-the-target-process/20231009-234127
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git
94f6f0550c625fab1f373bb86a6669b45e9748b3
patch link:
https://lore.kernel.org/all/20231009153714.10743-1-tangji...@tinylab.org/
patch subject: [PATCH v1] Ftrace: make sched_wakeup can focus on the target
process
in testcase: boot
compiler: gcc-7
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
+-+--++
| | v6.6-rc5 | e70b12f847 |
+-+--++
| boot_successes | 33 | 0 |
| boot_failures | 0| 18 |
| BUG:kernel_NULL_pointer_dereference,address | 0| 18 |
| Oops:#[##] | 0| 18 |
| EIP:__kmem_cache_alloc_lru | 0| 18 |
| Kernel_panic-not_syncing:Fatal_exception| 0| 18 |
+-+--++
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot
| Closes:
https://lore.kernel.org/oe-lkp/202310201530.46065346-oliver.s...@intel.com
[6.082261][T1] BUG: kernel NULL pointer dereference, address: 000c
[6.083178][T1] #PF: supervisor read access in kernel mode
[6.083178][T1] #PF: error_code(0x) - not-present page
[6.083178][T1] *pde =
[6.083178][T1] Oops: [#1]
[6.083178][T1] CPU: 0 PID: 1 Comm: swapper Not tainted
6.6.0-rc5-1-ge70b12f847f6 #1
[ 6.083178][ T1] EIP: __kmem_cache_alloc_lru+0x1d/0x88
[ 6.083178][ T1] Code: 04 eb a7 31 db e9 a5 fe ff ff 8d 76 00 3e 8d 74 26 00 55
b9 ff ff ff ff 89 e5 83 ec 18 89 5d f4 89 c3 89 75 f8 89 7d fc 89 d7 <8b> 40 0c
89 04 24 89 d8 e8 ca fd ff ff 8b 55 04 89 c6 a1 e4 38 25
All code
0: 04 eb add$0xeb,%al
2: a7 cmpsl %es:(%rdi),%ds:(%rsi)
3: 31 db xor%ebx,%ebx
5: e9 a5 fe ff ff jmpq 0xfeaf
a: 8d 76 00lea0x0(%rsi),%esi
d: 3e 8d 74 26 00 lea%ds:0x0(%rsi,%riz,1),%esi
12: 55 push %rbp
13: b9 ff ff ff ff mov$0x,%ecx
18: 89 e5 mov%esp,%ebp
1a: 83 ec 18sub$0x18,%esp
1d: 89 5d f4mov%ebx,-0xc(%rbp)
20: 89 c3 mov%eax,%ebx
22: 89 75 f8mov%esi,-0x8(%rbp)
25: 89 7d fcmov%edi,-0x4(%rbp)
28: 89 d7 mov%edx,%edi
2a:* 8b 40 0cmov0xc(%rax),%eax <-- trapping
instruction
2d: 89 04 24mov%eax,(%rsp)
30: 89 d8 mov%ebx,%eax
32: e8 ca fd ff ff callq 0xfe01
37: 8b 55 04mov0x4(%rbp),%edx
3a: 89 c6 mov%eax,%esi
3c: a1 .byte 0xa1
3d: e4 38 in $0x38,%al
3f: 25 .byte 0x25
Code starting with the faulting instruction
===
0: 8b 40 0cmov0xc(%rax),%eax
3: 89 04 24mov%eax,(%rsp)
6: 89 d8 mov%ebx,%eax
8: e8 ca fd ff ff callq 0xfdd7
d: 8b 55 04mov0x4(%rbp),%edx
10: 89 c6 mov%eax,%esi
12: a1 .byte 0xa1
13: e4 38 in $0x38,%al
15: 25 .byte 0x25
[6.083178][T1] EAX: EBX: ECX: EDX: 0cc0
[6.083178][T1] ESI: c3213800 EDI: 0cc0 EBP: c3217d78 ESP: c3217d60
[6.083178][T1] DS: 007b ES: 007b FS: GS: SS: 0068 EFLAGS:
00010286
[6.083178][T1] CR0: 80050033 CR2: 000c CR3: 02364000 CR4: 000406d0
[6.083178][T1] DR0: DR1: DR2: DR3:
[6.083178][T1] DR6: fffe0ff0 DR7: 0400
[6.083178][T1] Call Trace:
[ 6.083178][ T1] ? show_regs (arch/x86/kernel/dumpstack.c:479)
[ 6.083178][ T1] ? __die_body (arch/x86/kernel/dumpstack.c:421)
[ 6.083178][ T1] ? __die (arch/x86/kernel/dumpstack.c:435)
[ 6.0
Re: [PATCH v1] Ftrace: make sched_wakeup can focus on the target process
Hi Jinyu, kernel test robot noticed the following build warnings: [auto build test WARNING on linus/master] [also build test WARNING on rostedt-trace/for-next v6.6-rc5 next-20231010] [cannot apply to rostedt-trace/for-next-urgent] [If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch#_base_tree_information] url: https://github.com/intel-lab-lkp/linux/commits/Jinyu-Tang/Ftrace-make-sched_wakeup-can-focus-on-the-target-process/20231009-234127 base: linus/master patch link: https://lore.kernel.org/r/20231009153714.10743-1-tangjinyu%40tinylab.org patch subject: [PATCH v1] Ftrace: make sched_wakeup can focus on the target process config: i386-randconfig-062-20231010 (https://download.01.org/0day-ci/archive/20231011/202310110813.fxuatrh0-...@intel.com/config) compiler: gcc-9 (Debian 9.3.0-22) 9.3.0 reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20231011/202310110813.fxuatrh0-...@intel.com/reproduce) If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags | Reported-by: kernel test robot | Closes: https://lore.kernel.org/oe-kbuild-all/202310110813.fxuatrh0-...@intel.com/ sparse warnings: (new ones prefixed by >>) >> kernel/trace/trace_sched_wakeup.c:368:1: sparse: sparse: symbol >> 'sched_wakeup_mutex' was not declared. Should it be static? -- 0-DAY CI Kernel Test Service https://github.com/intel/lkp-tests/wiki
Re: [PATCH v1] Ftrace: make sched_wakeup can focus on the target process
On 10/9/23 17:37, Jinyu Tang wrote: > $ cyclictest --mlockall --smp --priority=99 & rtla timerlat -a will give you an structured analysis of your latency... https://bristot.me/linux-scheduling-latency-debug-and-analysis/ -- Daniel
Re: [PATCH v1] Ftrace: make sched_wakeup can focus on the target process
On Mon, 9 Oct 2023 23:37:14 +0800
Jinyu Tang wrote:
> When we want to know what happened in kernel when our app
> has more latency than we hope, but the larger latency of
> our app may be lower than other process in the syetem.
> We feel sad after waiting a long time but only get other
> process sched_wakeup trace.
>
> This Patch can let us only trace target process sched-wakeup
> time, other process sched-wakeup will be dropped and won't
> change tracing_max_latency.
>
> The patch is tested by the following commands:
>
> $ mount -t tracefs none /sys/kernel/tracing
> $ echo wakeup_rt > /sys/kernel/tracing/current_tracer
> # some other stress-ng options are also tested
> $ stress-ng --cpu 4 &
> $ cyclictest --mlockall --smp --priority=99 &
> $ cyclictest_pid=$!
> # child thread of cyclictest main process
> $ thread_pid=$((cyclictest_pid + 1))
>
> $ echo ${thread_pid} > /sys/kernel/tracing/set_wakeup_pid
>
> $ echo 1 > /sys/kernel/tracing/tracing_on
> $ echo 0 > /sys/kernel/tracing/tracing_max_latency
> $ wait ${cyclictest_pid}
> $ echo 0 > /sys/kernel/tracing/tracing_on
> $ cat /sys/kernel/tracing/trace
>
> The maximum latency and backtrace recorded in the trace file will be only
> generated by the target process.
> Then we can eliminate interference from other programs, making it easier
> to identify the cause of latency.
>
> Tested-by: Jiexun Wang
> Signed-off-by: Jinyu Tang
> ---
Honestly, the wakeup tracers are obsolete. I haven't used them in years. I
use synthetic events instead:
# cd /sys/kernel/tracing
# echo 'wakeup_lat pid_t pid; u64 delay;' > synthetic_events
# echo 'hist:keys=pid:ts=common_timestamp.usecs' if pid==$thread_pid >
events/sched/sched_waking/trigger
# echo
'hist:keys=next_pid:delta=common_timestamp.usecs-$ts:onmax($delta).trace(wakeup_lat,next_pid,$delta)'
> events/sched/sched_switch/trigger
# echo 1 > events/synthetic/wakeup_lat/enable
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 3/3 #P:8
#
#_-=> irqs-off/BH-disabled
# / _=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# / delay
# TASK-PID CPU# | TIMESTAMP FUNCTION
# | | | | | |
-0 [000] d..4. 350799.423428: wakeup_lat: pid=59921
delay=1281
-0 [000] d..4. 350800.423441: wakeup_lat: pid=59921
delay=1317
-0 [000] d..4. 350801.423445: wakeup_lat: pid=59921
delay=1331
I could also make it record stack traces, disable tracing, and all sorts of
other nifty things.
-- Steve
[PATCH v1] Ftrace: make sched_wakeup can focus on the target process
When we want to know what happened in kernel when our app
has more latency than we hope, but the larger latency of
our app may be lower than other process in the syetem.
We feel sad after waiting a long time but only get other
process sched_wakeup trace.
This Patch can let us only trace target process sched-wakeup
time, other process sched-wakeup will be dropped and won't
change tracing_max_latency.
The patch is tested by the following commands:
$ mount -t tracefs none /sys/kernel/tracing
$ echo wakeup_rt > /sys/kernel/tracing/current_tracer
# some other stress-ng options are also tested
$ stress-ng --cpu 4 &
$ cyclictest --mlockall --smp --priority=99 &
$ cyclictest_pid=$!
# child thread of cyclictest main process
$ thread_pid=$((cyclictest_pid + 1))
$ echo ${thread_pid} > /sys/kernel/tracing/set_wakeup_pid
$ echo 1 > /sys/kernel/tracing/tracing_on
$ echo 0 > /sys/kernel/tracing/tracing_max_latency
$ wait ${cyclictest_pid}
$ echo 0 > /sys/kernel/tracing/tracing_on
$ cat /sys/kernel/tracing/trace
The maximum latency and backtrace recorded in the trace file will be only
generated by the target process.
Then we can eliminate interference from other programs, making it easier
to identify the cause of latency.
Tested-by: Jiexun Wang
Signed-off-by: Jinyu Tang
---
kernel/trace/trace.h | 3 +
kernel/trace/trace_sched_wakeup.c | 179 ++
2 files changed, 182 insertions(+)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 77debe53f07c..c6f212e8bfd2 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -403,6 +403,9 @@ struct trace_array {
#endif
/* function tracing enabled */
int function_enabled;
+#endif
+#ifdef CONFIG_SCHED_TRACER
+ struct trace_pid_list __rcu *wakeup_pids;
#endif
int no_filter_buffering_ref;
struct list_headhist_vars;
diff --git a/kernel/trace/trace_sched_wakeup.c
b/kernel/trace/trace_sched_wakeup.c
index 0469a04a355f..b6cb9391e120 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -10,6 +10,9 @@
* Copyright (C) 2004-2006 Ingo Molnar
* Copyright (C) 2004 Nadia Yvette Chambers
*/
+#include
+#include
+#include
#include
#include
#include
@@ -17,6 +20,7 @@
#include
#include
#include
+#include
#include "trace.h"
static struct trace_array *wakeup_trace;
@@ -361,6 +365,169 @@ static bool report_latency(struct trace_array *tr, u64
delta)
return true;
}
+DEFINE_MUTEX(sched_wakeup_mutex);
+static void *
+p_next(struct seq_file *m, void *v, loff_t *pos)
+{
+ struct trace_array *tr = m->private;
+ struct trace_pid_list *pid_list =
rcu_dereference_sched(tr->wakeup_pids);
+
+ return trace_pid_next(pid_list, v, pos);
+}
+
+static void *p_start(struct seq_file *m, loff_t *pos)
+ __acquires(RCU)
+{
+ struct trace_pid_list *pid_list;
+ struct trace_array *tr = m->private;
+
+ /*
+* Grab the mutex, to keep calls to p_next() having the same
+* tr->wakeup_pids as p_start() has.
+* If we just passed the tr->wakeup_pids around, then RCU would
+* have been enough, but doing that makes things more complex.
+*/
+ mutex_lock(_wakeup_mutex);
+ rcu_read_lock_sched();
+
+ pid_list = rcu_dereference_sched(tr->wakeup_pids);
+
+ if (!pid_list)
+ return NULL;
+
+ return trace_pid_start(pid_list, pos);
+}
+
+static void p_stop(struct seq_file *m, void *p)
+ __releases(RCU)
+{
+ rcu_read_unlock_sched();
+ mutex_unlock(_wakeup_mutex);
+}
+
+static const struct seq_operations show_set_pid_seq_ops = {
+ .start = p_start,
+ .next = p_next,
+ .show = trace_pid_show,
+ .stop = p_stop,
+};
+
+static int
+ftrace_wakeup_open(struct inode *inode, struct file *file,
+ const struct seq_operations *seq_ops)
+{
+ struct seq_file *m;
+ int ret;
+
+ ret = seq_open(file, seq_ops);
+ if (ret < 0)
+ return ret;
+ m = file->private_data;
+ /* copy tr over to seq ops */
+ m->private = inode->i_private;
+
+ return ret;
+}
+
+static void __clear_wakeup_pids(struct trace_array *tr)
+{
+ struct trace_pid_list *pid_list;
+
+ pid_list = rcu_dereference_protected(tr->wakeup_pids,
+
lockdep_is_held(_wakeup_mutex));
+ if (!pid_list)
+ return;
+
+ rcu_assign_pointer(tr->wakeup_pids, NULL);
+
+ synchronize_rcu();
+ trace_pid_list_free(pid_list);
+}
+
+static void clear_wakeup_pids(struct trace_array *tr)
+{
+ mutex_lock(_wakeup_mutex);
+ __clear_wakeup_pids(tr);
+ mutex_unlock(_wakeup_mutex);
+
+}
+
+static int
+ftrace_set_wakeup_pid_open(struct inode *inode, struct file *file)
+{
+ const struct seq_operations *seq_ops = _set_pid_seq_ops;
+ struct
