* [PATCH v3 0/3] tracing: add trace_seq_reset function
@ 2024-01-25 22:28 Ricardo B. Marliere
2024-01-25 22:28 ` [PATCH v3 1/3] tracing: initialize trace_seq buffers Ricardo B. Marliere
` (2 more replies)
0 siblings, 3 replies; 5+ messages in thread
From: Ricardo B. Marliere @ 2024-01-25 22:28 UTC (permalink / raw)
To: Steven Rostedt, Masami Hiramatsu, Mathieu Desnoyers
Cc: Ricardo B. Marliere, linux-kernel, linux-trace-kernel
This series is a prerequisite for a later effort of making trace_seq more
flexible about its buffer size. To achieve that, initializing and resetting
the buffers need to be differentiated.
Changes in v3:
- Reordered commits so it doesn't produce a failing build in-between.
- Improved changelogs.
Changes in v2:
- Added a WARN_ON_ONCE to __trace_seq_init to catch possible misuses.
- Properly initialized trace_seq buffers.
Ricardo B. Marliere (3):
tracing: initialize trace_seq buffers
tracing: add trace_seq_reset function
tracing: convert __trace_seq_init to use WARN_ON_ONCE
include/linux/trace_seq.h | 11 +++++++++++
include/trace/trace_events.h | 2 +-
kernel/trace/trace.c | 24 +++++++++++++++++++-----
kernel/trace/trace_output.c | 2 +-
kernel/trace/trace_seq.c | 4 ++--
5 files changed, 34 insertions(+), 9 deletions(-)
--
2.43.0
^ permalink raw reply [flat|nested] 5+ messages in thread* [PATCH v3 1/3] tracing: initialize trace_seq buffers 2024-01-25 22:28 [PATCH v3 0/3] tracing: add trace_seq_reset function Ricardo B. Marliere @ 2024-01-25 22:28 ` Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 2/3] tracing: add trace_seq_reset function Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE Ricardo B. Marliere 2 siblings, 0 replies; 5+ messages in thread From: Ricardo B. Marliere @ 2024-01-25 22:28 UTC (permalink / raw) To: Steven Rostedt, Masami Hiramatsu, Mathieu Desnoyers Cc: Ricardo B. Marliere, linux-kernel, linux-trace-kernel In order to extend trace_seq into being dynamic, the struct trace_seq will no longer be valid if simply set to zero. Call trace_seq_init() for all trace_seq when they are first created. Suggested-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Ricardo B. Marliere <ricardo@marliere.net> --- kernel/trace/trace.c | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 46dbe22121e9..9eddf8168df2 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4889,6 +4889,9 @@ __tracing_open(struct inode *inode, struct file *file, bool snapshot) mutex_unlock(&trace_types_lock); + trace_seq_init(&iter->seq); + trace_seq_init(&iter->tmp_seq); + return iter; fail: @@ -6770,6 +6773,7 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) } trace_seq_init(&iter->seq); + trace_seq_init(&iter->tmp_seq); iter->trace = tr->current_trace; if (!alloc_cpumask_var(&iter->started, GFP_KERNEL)) { @@ -6947,6 +6951,7 @@ tracing_read_pipe(struct file *filp, char __user *ubuf, trace_iterator_reset(iter); cpumask_clear(iter->started); trace_seq_init(&iter->seq); + trace_seq_init(&iter->tmp_seq); trace_event_read_lock(); trace_access_lock(iter->cpu_file); @@ -8277,6 +8282,9 @@ static int tracing_buffers_open(struct inode *inode, struct file *filp) if (ret < 0) trace_array_put(tr); + trace_seq_init(&info->iter.seq); + trace_seq_init(&info->iter.tmp_seq); + return ret; } @@ -10300,6 +10308,9 @@ void trace_init_global_iter(struct trace_iterator *iter) iter->temp_size = STATIC_TEMP_BUF_SIZE; iter->fmt = static_fmt_buf; iter->fmt_size = STATIC_FMT_BUF_SIZE; + + trace_seq_init(&iter->seq); + trace_seq_init(&iter->tmp_seq); } void ftrace_dump(enum ftrace_dump_mode oops_dump_mode) @@ -10712,6 +10723,9 @@ void __init early_trace_init(void) tracepoint_printk = 0; else static_key_enable(&tracepoint_printk_key.key); + + trace_seq_init(&tracepoint_print_iter->seq); + trace_seq_init(&tracepoint_print_iter->tmp_seq); } tracer_alloc_buffers(); -- 2.43.0 ^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH v3 2/3] tracing: add trace_seq_reset function 2024-01-25 22:28 [PATCH v3 0/3] tracing: add trace_seq_reset function Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 1/3] tracing: initialize trace_seq buffers Ricardo B. Marliere @ 2024-01-25 22:28 ` Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE Ricardo B. Marliere 2 siblings, 0 replies; 5+ messages in thread From: Ricardo B. Marliere @ 2024-01-25 22:28 UTC (permalink / raw) To: Steven Rostedt, Masami Hiramatsu, Mathieu Desnoyers Cc: Ricardo B. Marliere, linux-kernel, linux-trace-kernel Currently, trace_seq_init may be called many times with the intent of resetting the buffer. Add a function trace_seq_reset that does that and replace the relevant occurrences to use it instead. Suggested-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Ricardo B. Marliere <ricardo@marliere.net> --- include/linux/trace_seq.h | 11 +++++++++++ include/trace/trace_events.h | 2 +- kernel/trace/trace.c | 10 +++++----- kernel/trace/trace_output.c | 2 +- kernel/trace/trace_seq.c | 2 +- 5 files changed, 19 insertions(+), 8 deletions(-) diff --git a/include/linux/trace_seq.h b/include/linux/trace_seq.h index 9ec229dfddaa..d3fa41001813 100644 --- a/include/linux/trace_seq.h +++ b/include/linux/trace_seq.h @@ -29,6 +29,17 @@ trace_seq_init(struct trace_seq *s) s->readpos = 0; } +static inline void +trace_seq_reset(struct trace_seq *s) +{ + if (WARN_ON_ONCE(!s->seq.size)) + seq_buf_init(&s->seq, s->buffer, TRACE_SEQ_BUFFER_SIZE); + else + seq_buf_clear(&s->seq); + s->full = 0; + s->readpos = 0; +} + /** * trace_seq_used - amount of actual data written to buffer * @s: trace sequence descriptor diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h index c2f9cabf154d..2bc79998e5ab 100644 --- a/include/trace/trace_events.h +++ b/include/trace/trace_events.h @@ -227,7 +227,7 @@ trace_raw_output_##call(struct trace_iterator *iter, int flags, \ \ field = (typeof(field))entry; \ \ - trace_seq_init(p); \ + trace_seq_reset(p); \ return trace_output_call(iter, #call, print); \ } \ static struct trace_event_functions trace_event_type_funcs_##call = { \ diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 9eddf8168df2..9827700d0164 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -2928,7 +2928,7 @@ static void output_printk(struct trace_event_buffer *fbuffer) event = &fbuffer->trace_file->event_call->event; raw_spin_lock_irqsave(&tracepoint_iter_lock, flags); - trace_seq_init(&iter->seq); + trace_seq_reset(&iter->seq); iter->ent = fbuffer->entry; event_call->event.funcs->trace(iter, 0, event); trace_seq_putc(&iter->seq, 0); @@ -6925,7 +6925,7 @@ tracing_read_pipe(struct file *filp, char __user *ubuf, if (sret != -EBUSY) goto out; - trace_seq_init(&iter->seq); + trace_seq_reset(&iter->seq); if (iter->trace->read) { sret = iter->trace->read(iter, filp, ubuf, cnt, ppos); @@ -6998,7 +6998,7 @@ tracing_read_pipe(struct file *filp, char __user *ubuf, /* Now copy what we have to the user */ sret = trace_seq_to_user(&iter->seq, ubuf, cnt); if (iter->seq.readpos >= trace_seq_used(&iter->seq)) - trace_seq_init(&iter->seq); + trace_seq_reset(&iter->seq); /* * If there was nothing to send to user, in spite of consuming trace @@ -7130,7 +7130,7 @@ static ssize_t tracing_splice_read_pipe(struct file *filp, spd.partial[i].offset = 0; spd.partial[i].len = trace_seq_used(&iter->seq); - trace_seq_init(&iter->seq); + trace_seq_reset(&iter->seq); } trace_access_unlock(iter->cpu_file); @@ -10282,7 +10282,7 @@ trace_printk_seq(struct trace_seq *s) printk(KERN_TRACE "%s", s->buffer); - trace_seq_init(s); + trace_seq_reset(s); } void trace_init_global_iter(struct trace_iterator *iter) diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 3e7fa44dc2b2..c949e7736618 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -308,7 +308,7 @@ int trace_raw_output_prep(struct trace_iterator *iter, return TRACE_TYPE_UNHANDLED; } - trace_seq_init(p); + trace_seq_reset(p); trace_seq_printf(s, "%s: ", trace_event_name(event)); return trace_handle_return(s); diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c index c158d65a8a88..741b2f3d76c0 100644 --- a/kernel/trace/trace_seq.c +++ b/kernel/trace/trace_seq.c @@ -59,7 +59,7 @@ int trace_print_seq(struct seq_file *m, struct trace_seq *s) * do something else with the contents. */ if (!ret) - trace_seq_init(s); + trace_seq_reset(s); return ret; } -- 2.43.0 ^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE 2024-01-25 22:28 [PATCH v3 0/3] tracing: add trace_seq_reset function Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 1/3] tracing: initialize trace_seq buffers Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 2/3] tracing: add trace_seq_reset function Ricardo B. Marliere @ 2024-01-25 22:28 ` Ricardo B. Marliere 2024-02-05 13:59 ` kernel test robot 2 siblings, 1 reply; 5+ messages in thread From: Ricardo B. Marliere @ 2024-01-25 22:28 UTC (permalink / raw) To: Steven Rostedt, Masami Hiramatsu, Mathieu Desnoyers Cc: Ricardo B. Marliere, linux-kernel, linux-trace-kernel The initialization of trace_seq buffers is done elsewhere and therefore __trace_seq_init should yield a warning if it has to actually initialize the buffer. Suggested-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Ricardo B. Marliere <ricardo@marliere.net> --- kernel/trace/trace_seq.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c index 741b2f3d76c0..3c7a7d903b54 100644 --- a/kernel/trace/trace_seq.c +++ b/kernel/trace/trace_seq.c @@ -32,7 +32,7 @@ */ static inline void __trace_seq_init(struct trace_seq *s) { - if (unlikely(!s->seq.size)) + if (WARN_ON_ONCE(!s->seq.size)) trace_seq_init(s); } -- 2.43.0 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE 2024-01-25 22:28 ` [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE Ricardo B. Marliere @ 2024-02-05 13:59 ` kernel test robot 0 siblings, 0 replies; 5+ messages in thread From: kernel test robot @ 2024-02-05 13:59 UTC (permalink / raw) To: Ricardo B. Marliere Cc: oe-lkp, lkp, Steven Rostedt, linux-kernel, linux-trace-kernel, Masami Hiramatsu, Mathieu Desnoyers, Ricardo B. Marliere, oliver.sang Hello, kernel test robot noticed "WARNING:at_kernel/trace/trace_seq.c:#trace_seq_printf" on: commit: 233bcd2427b36992e8918a67a88912f9c3d497af ("[PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE") url: https://github.com/intel-lab-lkp/linux/commits/Ricardo-B-Marliere/tracing-initialize-trace_seq-buffers/20240126-063125 base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git ecb1b8288dc7ccbdcb3b9df005fa1c0e0c0388a7 patch link: https://lore.kernel.org/all/20240125222818.7425-4-ricardo@marliere.net/ patch subject: [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE in testcase: boot compiler: clang-17 test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G (please refer to attached dmesg/kmsg for entire log/backtrace) we noticed the WARN_ON_ONCE added in this commit was hit in our tests. but not always happen, just FYI. 27b32d2097dcb40a 233bcd2427b36992e8918a67a88 ---------------- --------------------------- fail:runs %reproduction fail:runs | | | :10 50% 5:11 dmesg.RIP:trace_seq_printf :10 50% 5:11 dmesg.WARNING:at_kernel/trace/trace_seq.c:#trace_seq_printf 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 <lkp@intel.com> | Closes: https://lore.kernel.org/oe-lkp/202402052141.769871e2-lkp@intel.com [ 1915.506477][ T42] ------------[ cut here ]------------ [ 1915.506778][ T42] WARNING: CPU: 0 PID: 42 at kernel/trace/trace_seq.c:35 trace_seq_printf (kernel/trace/trace_seq.c:35) [ 1915.507296][ T42] Modules linked in: ipv6 [ 1915.507538][ T42] CPU: 0 PID: 42 Comm: rcu_scale_write Tainted: G TN 6.8.0-rc1-00172-g233bcd2427b3 #1 [ 1915.508125][ T42] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 [ 1915.508690][ T42] RIP: 0010:trace_seq_printf (kernel/trace/trace_seq.c:35) [ 1915.508999][ T42] Code: 00 00 48 3b 83 e8 1f 00 00 77 51 48 8d 65 f0 5b 41 5e 5d 31 c0 31 c9 31 ff 31 d2 45 31 c0 45 31 c9 c3 cc 48 8d 83 f0 1f 00 00 <0f> 0b 48 89 9b e0 1f 00 00 48 c7 83 e8 1f 00 00 dc 1f 00 00 c6 03 All code ======== 0: 00 00 add %al,(%rax) 2: 48 3b 83 e8 1f 00 00 cmp 0x1fe8(%rbx),%rax 9: 77 51 ja 0x5c b: 48 8d 65 f0 lea -0x10(%rbp),%rsp f: 5b pop %rbx 10: 41 5e pop %r14 12: 5d pop %rbp 13: 31 c0 xor %eax,%eax 15: 31 c9 xor %ecx,%ecx 17: 31 ff xor %edi,%edi 19: 31 d2 xor %edx,%edx 1b: 45 31 c0 xor %r8d,%r8d 1e: 45 31 c9 xor %r9d,%r9d 21: c3 ret 22: cc int3 23: 48 8d 83 f0 1f 00 00 lea 0x1ff0(%rbx),%rax 2a:* 0f 0b ud2 <-- trapping instruction 2c: 48 89 9b e0 1f 00 00 mov %rbx,0x1fe0(%rbx) 33: 48 c7 83 e8 1f 00 00 movq $0x1fdc,0x1fe8(%rbx) 3a: dc 1f 00 00 3e: c6 .byte 0xc6 3f: 03 .byte 0x3 Code starting with the faulting instruction =========================================== 0: 0f 0b ud2 2: 48 89 9b e0 1f 00 00 mov %rbx,0x1fe0(%rbx) 9: 48 c7 83 e8 1f 00 00 movq $0x1fdc,0x1fe8(%rbx) 10: dc 1f 00 00 14: c6 .byte 0xc6 15: 03 .byte 0x3 [ 1915.510058][ T42] RSP: 0018:ffffc90000157d40 EFLAGS: 00010046 [ 1915.510390][ T42] RAX: ffffffff84141a18 RBX: ffffffff8413fa28 RCX: 0000000000000001 [ 1915.510822][ T42] RDX: ffffc90000157dc0 RSI: ffffffff82768da2 RDI: ffffffff84141a08 [ 1915.511253][ T42] RBP: ffffc90000157da0 R08: 0000000000000000 R09: 0000000000000000 [ 1915.511684][ T42] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 [ 1915.512115][ T42] R13: ffffc90000157dc0 R14: 0000000000000000 R15: ffffffff8413d894 [ 1915.512546][ T42] FS: 0000000000000000(0000) GS:ffffffff82a60000(0000) knlGS:0000000000000000 [ 1915.513033][ T42] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1915.513392][ T42] CR2: 000055fe70034138 CR3: 00000001740d7000 CR4: 00000000000406b0 [ 1915.513828][ T42] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 1915.514262][ T42] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 1915.514696][ T42] Call Trace: [ 1915.514881][ T42] <TASK> [ 1915.515048][ T42] ? __warn (kernel/panic.c:236 kernel/panic.c:677) [ 1915.515275][ T42] ? trace_seq_printf (kernel/trace/trace_seq.c:35) [ 1915.515550][ T42] ? report_bug (lib/bug.c:?) [ 1915.515799][ T42] ? handle_bug (arch/x86/kernel/traps.c:238) [ 1915.516038][ T42] ? exc_invalid_op (arch/x86/kernel/traps.c:259) [ 1915.516298][ T42] ? asm_exc_invalid_op (arch/x86/include/asm/idtentry.h:568) [ 1915.516586][ T42] ? trace_seq_printf (kernel/trace/trace_seq.c:35) [ 1915.516860][ T42] ? trace_find_cmdline (arch/x86/include/asm/preempt.h:103 kernel/trace/trace.c:2546) [ 1915.517142][ T42] ? trace_find_cmdline (arch/x86/include/asm/preempt.h:103 kernel/trace/trace.c:2546) [ 1915.517420][ T42] ? preempt_count_sub (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:5900) [ 1915.517694][ T42] trace_print_lat_context (kernel/trace/trace_output.c:516 kernel/trace/trace_output.c:664) [ 1915.517995][ T42] print_trace_fmt (kernel/trace/trace.c:?) [ 1915.518257][ T42] ftrace_dump (kernel/trace/trace.c:10413) [ 1915.518505][ T42] rcu_scale_writer (kernel/rcu/rcuscale.c:534) [ 1915.518775][ T42] ? __cfi_rcu_scale_writer (kernel/rcu/rcuscale.c:453) [ 1915.519071][ T42] kthread (kernel/kthread.c:390) [ 1915.519298][ T42] ? __cfi_kthread (kernel/kthread.c:341) [ 1915.519554][ T42] ret_from_fork (arch/x86/kernel/process.c:153) [ 1915.519802][ T42] ? __cfi_kthread (kernel/kthread.c:341) [ 1915.520057][ T42] ret_from_fork_asm (arch/x86/entry/entry_64.S:250) [ 1915.520326][ T42] </TASK> [ 1915.520496][ T42] irq event stamp: 8228 [ 1915.520724][ T42] hardirqs last enabled at (8227): _raw_spin_unlock_irqrestore (include/linux/spinlock_api_smp.h:?) [ 1915.521290][ T42] hardirqs last disabled at (8228): ftrace_dump (kernel/trace/trace.c:10359) [ 1915.521783][ T42] softirqs last enabled at (0): copy_process (include/linux/rcupdate.h:298 include/linux/rcupdate.h:750 kernel/fork.c:2366) [ 1915.522276][ T42] softirqs last disabled at (0): 0x0 [ 1915.522663][ T42] ---[ end trace 0000000000000000 ]--- [ 1915.522970][ T42] swapper-1 0..Zff 1910231878us : fib6_table_lookup: table 2166473472 oif 80736 iif -14080 proto 0 81ff:ffff:ff60:6d05:81ff:ffff:ff00:0/0 -> ::/0 tos 96 scope 109 flags 5 ==> dev gw :: err -1 [ 1915.524039][ T42] swapper-1 0..... 1910231880us : Unknown type 1830 [ 1915.524442][ T42] --------------------------------- [ 1915.524733][ T42] rcu-scale: Test complete The kernel config and materials to reproduce are available at: https://download.01.org/0day-ci/archive/20240205/202402052141.769871e2-lkp@intel.com -- 0-DAY CI Kernel Test Service https://github.com/intel/lkp-tests/wiki ^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2024-02-05 13:59 UTC | newest] Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2024-01-25 22:28 [PATCH v3 0/3] tracing: add trace_seq_reset function Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 1/3] tracing: initialize trace_seq buffers Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 2/3] tracing: add trace_seq_reset function Ricardo B. Marliere 2024-01-25 22:28 ` [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE Ricardo B. Marliere 2024-02-05 13:59 ` kernel test robot
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
Powered by JetHome