* [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 related [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 related [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 related [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