diff mbox series

tracing: Have large events show up as '[LINE TOO BIG]' instead of nothing

Message ID 20231209171058.78c1a026@gandalf.local.home (mailing list archive)
State Accepted
Commit b55b0a0d7c4aa2dac3579aa7e6802d1f57445096
Headers show
Series tracing: Have large events show up as '[LINE TOO BIG]' instead of nothing | expand

Commit Message

Steven Rostedt Dec. 9, 2023, 10:10 p.m. UTC
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

If a large event was added to the ring buffer that is larger than what the
trace_seq can handle, it just drops the output:

 ~# cat /sys/kernel/tracing/trace
 # tracer: nop
 #
 # entries-in-buffer/entries-written: 2/2   #P:8
 #
 #                                _-----=> irqs-off/BH-disabled
 #                               / _----=> need-resched
 #                              | / _---=> hardirq/softirq
 #                              || / _--=> preempt-depth
 #                              ||| / _-=> migrate-disable
 #                              |||| /     delay
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
            <...>-859     [001] .....   141.118951: tracing_mark_write           <...>-859     [001] .....   141.148201: tracing_mark_write: 78901234

Instead, catch this case and add some context:

 ~# cat /sys/kernel/tracing/trace
 # tracer: nop
 #
 # entries-in-buffer/entries-written: 2/2   #P:8
 #
 #                                _-----=> irqs-off/BH-disabled
 #                               / _----=> need-resched
 #                              | / _---=> hardirq/softirq
 #                              || / _--=> preempt-depth
 #                              ||| / _-=> migrate-disable
 #                              |||| /     delay
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
            <...>-852     [001] .....   121.550551: tracing_mark_write[LINE TOO BIG]
            <...>-852     [001] .....   121.550581: tracing_mark_write: 78901234

This now emulates the same output as trace_pipe.

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 kernel/trace/trace.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

Comments

Mathieu Desnoyers Dec. 10, 2023, 2:11 p.m. UTC | #1
On 2023-12-09 17:10, Steven Rostedt wrote:
[...]
>              <...>-852     [001] .....   121.550551: tracing_mark_write[LINE TOO BIG]
>              <...>-852     [001] .....   121.550581: tracing_mark_write: 78901234

Failing to print an entire message because it does not fit in the
buffer size is rather inconvenient.

It would be better to print the partial line, and end the line with
a <TRUNCATED LINE> tag.

Thanks,

Mathieu
Steven Rostedt Dec. 10, 2023, 3:34 p.m. UTC | #2
On Sun, 10 Dec 2023 09:11:40 -0500
Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:

> On 2023-12-09 17:10, Steven Rostedt wrote:
> [...]
> >              <...>-852     [001] .....   121.550551: tracing_mark_write[LINE TOO BIG]
> >              <...>-852     [001] .....   121.550581: tracing_mark_write: 78901234  
> 
> Failing to print an entire message because it does not fit in the
> buffer size is rather inconvenient.

Yes I agree, and luckily it hasn't been called out as an issue. Note, I hit
this because I extended the trace_marker buffer before increasing the
trace_seq size. Otherwise, the trace_marker just breaks it up. This can now
only be triggered by internal changes.

> 
> It would be better to print the partial line, and end the line with
> a <TRUNCATED LINE> tag.

Agreed, but I don't have time to do that (I already spent way too much time
on this than I had allocated). I decided to just do what the trace_pipe
currently does, and leave "print partial line" to another day when I can
allocate time on this.

Hmm, this could be added to the "TODO" list that was talked about in
ksummit-discuss.

-- Steve
Masami Hiramatsu (Google) Dec. 11, 2023, 12:08 p.m. UTC | #3
On Sun, 10 Dec 2023 10:34:15 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Sun, 10 Dec 2023 09:11:40 -0500
> Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:
> 
> > On 2023-12-09 17:10, Steven Rostedt wrote:
> > [...]
> > >              <...>-852     [001] .....   121.550551: tracing_mark_write[LINE TOO BIG]
> > >              <...>-852     [001] .....   121.550581: tracing_mark_write: 78901234  
> > 
> > Failing to print an entire message because it does not fit in the
> > buffer size is rather inconvenient.
> 
> Yes I agree, and luckily it hasn't been called out as an issue. Note, I hit
> this because I extended the trace_marker buffer before increasing the
> trace_seq size. Otherwise, the trace_marker just breaks it up. This can now
> only be triggered by internal changes.

Rather than the broken output, I would perfer this output.

> 
> > 
> > It would be better to print the partial line, and end the line with
> > a <TRUNCATED LINE> tag.

But how long the partial line length is good enough? I think that big (and long)
user marker maybe not for human, so we don't need to care about readability.
I think current one is one of better solutions.

So I'll give my Reviewed-by. :)

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Thank you,

> 
> Agreed, but I don't have time to do that (I already spent way too much time
> on this than I had allocated). I decided to just do what the trace_pipe
> currently does, and leave "print partial line" to another day when I can
> allocate time on this.
> 
> Hmm, this could be added to the "TODO" list that was talked about in
> ksummit-discuss.
> 
> -- Steve
>
diff mbox series

Patch

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index fbcd3bafb93e..aa8f99f3e5de 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -4722,7 +4722,11 @@  static int s_show(struct seq_file *m, void *v)
 		iter->leftover = ret;
 
 	} else {
-		print_trace_line(iter);
+		ret = print_trace_line(iter);
+		if (ret == TRACE_TYPE_PARTIAL_LINE) {
+			iter->seq.full = 0;
+			trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n");
+		}
 		ret = trace_print_seq(m, &iter->seq);
 		/*
 		 * If we overflow the seq_file buffer, then it will