[RFC,1/1] tracefs: add TP_printk_no_nl - RFC

  This variant of TP_printk() does *not* add the trailing newline.

https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/

taught dyndbg to send pr_debug() msgs to tracefs, via -x/T flag.

It "reused" the include/trace/events/printk.h console event,
which does the following:

	TP_fast_assign(
		/*
		 * Each trace entry is printed in a new line.
		 * If the msg finishes with '\n', cut it off
		 * to avoid blank lines in the trace.
		 */
		if ((len > 0) && (text[len-1] == '\n'))
			len -= 1;

		memcpy(__get_str(msg), text, len);
		__get_str(msg)[len] = 0;
	),

That trim work could be avoided, *iff* all pr_debug() callers are
known to have no '\n' to strip.  While thats not true for *all*
callsites, it is 99+% true for DRM.debug callsites, and can be made
true for some subsets of prdbg/dyndbg callsites.

WANTED: macros to validate that a literal format-str has or doesn't
have a trailing newline, or to provide or trim trailing newline(s?).
Should be usable in TP_printk* defns, for use in new event defns.

Cc: <rostedt@goodmis.org>
Cc: Vincent Whitchurch <vincent.whitchurch@axis.com>
Cc: <daniel@ffwll.ch>
Cc: <pmladek@suse.com>
Cc: <sergey.senozhatsky@gmail.com>
Cc: <john.ogness@linutronix.de>
Cc: Simon Ser <contact@emersion.fr>
Cc: Sean Paul <seanpaul@chromium.org>
Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 include/trace/stages/stage3_trace_output.h | 3 +++
 include/trace/stages/stage7_class_define.h | 3 +++
 2 files changed, 6 insertions(+)
  

On 2023-07-30, Jim Cromie <jim.cromie@gmail.com> wrote:
> This variant of TP_printk() does *not* add the trailing newline.
>
> https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/
>
> taught dyndbg to send pr_debug() msgs to tracefs, via -x/T flag.
>
> It "reused" the include/trace/events/printk.h console event,
> which does the following:
>
> 	TP_fast_assign(
> 		/*
> 		 * Each trace entry is printed in a new line.
> 		 * If the msg finishes with '\n', cut it off
> 		 * to avoid blank lines in the trace.
> 		 */
> 		if ((len > 0) && (text[len-1] == '\n'))
> 			len -= 1;
>
> 		memcpy(__get_str(msg), text, len);
> 		__get_str(msg)[len] = 0;
> 	),
>
> That trim work could be avoided, *iff* all pr_debug() callers are
> known to have no '\n' to strip.  While thats not true for *all*
> callsites, it is 99+% true for DRM.debug callsites, and can be made
> true for some subsets of prdbg/dyndbg callsites.

Note that the trailing '\n' in printk messages has a purpose.  It
finalizes commitment of the message to the ringbuffer so that the
message cannot be extended by any LOG_CONT printk's that may come along
(from any context).

If it is not intended that a message is extended, then that message
should include a trailing '\n'.

Grepping through the kernel, I am surprised how many messages are
missing the trailing newline when it is obvious they are not intended to
be extended. I consider these bugs.

John Ogness
  

On Mon 2023-07-31 10:31:03, John Ogness wrote:
> On 2023-07-30, Jim Cromie <jim.cromie@gmail.com> wrote:
> > This variant of TP_printk() does *not* add the trailing newline.
> >
> > https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/
> >
> > taught dyndbg to send pr_debug() msgs to tracefs, via -x/T flag.
> >
> > It "reused" the include/trace/events/printk.h console event,
> > which does the following:
> >
> > 	TP_fast_assign(
> > 		/*
> > 		 * Each trace entry is printed in a new line.
> > 		 * If the msg finishes with '\n', cut it off
> > 		 * to avoid blank lines in the trace.
> > 		 */
> > 		if ((len > 0) && (text[len-1] == '\n'))
> > 			len -= 1;
> >
> > 		memcpy(__get_str(msg), text, len);
> > 		__get_str(msg)[len] = 0;
> > 	),
> >
> > That trim work could be avoided, *iff* all pr_debug() callers are
> > known to have no '\n' to strip.  While thats not true for *all*
> > callsites, it is 99+% true for DRM.debug callsites, and can be made
> > true for some subsets of prdbg/dyndbg callsites.
> 
> Note that the trailing '\n' in printk messages has a purpose.  It
> finalizes commitment of the message to the ringbuffer so that the
> message cannot be extended by any LOG_CONT printk's that may come along
> (from any context).

Also the message is printed on consoles only when finalized. As a
result, the last non-finalized message might not be visible on
consoles for hours or days.

> If it is not intended that a message is extended, then that message
> should include a trailing '\n'.
> 
> Grepping through the kernel, I am surprised how many messages are
> missing the trailing newline when it is obvious they are not intended to
> be extended. I consider these bugs.

I consider this bug as well.

My understanding is that this patch affects only messages printed to
the ftrace buffer so that it does not affect printk() directly.

But still. It creates a habit that is bad for printk(). Also relies
on the fact that people are aware of this macro and use it. IMHO,
it will not work in practice. Or do I miss something?

Best Regards,
Petr
  

On Mon, 31 Jul 2023 12:21:29 +0200
Petr Mladek <pmladek@suse.com> wrote:

> > Grepping through the kernel, I am surprised how many messages are
> > missing the trailing newline when it is obvious they are not intended to
> > be extended. I consider these bugs.  
> 
> I consider this bug as well.
> 
> My understanding is that this patch affects only messages printed to
> the ftrace buffer so that it does not affect printk() directly.
> 
> But still. It creates a habit that is bad for printk(). Also relies
> on the fact that people are aware of this macro and use it. IMHO,
> it will not work in practice. Or do I miss something?

I believe that the problem Jim is addressing is that there's printk()
messages that also go to a tracepoint() function. The tracepoint function
will add its own '\n' to the message, and now we have two '\n's and this
causes extra spaces in the output of the ftrace ring buffer.

Perhaps what we should do is to make sure that the output doesn't add more
newlines than just one.

Something like this: (totally untested)

diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index db575094c498..a1b73ffa1552 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -333,6 +333,8 @@ int trace_output_raw(struct trace_iterator *iter, char *name,
 
 	trace_seq_printf(s, "%s: ", name);
 	trace_seq_vprintf(s, trace_event_format(iter, fmt), ap);
+	trace_seq_trim_newlines(s);
+	trace_seq_putc(s, '\n');
 
 	return trace_handle_return(s);
 }
diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
index bac06ee3b98b..d4e2049809e3 100644
--- a/kernel/trace/trace_seq.c
+++ b/kernel/trace/trace_seq.c
@@ -221,6 +221,22 @@ void trace_seq_puts(struct trace_seq *s, const char *str)
 }
 EXPORT_SYMBOL_GPL(trace_seq_puts);
 
+/**
+ * trace_seq_trim_newlines - remove ending newlines
+ * @s: trace sequence descriptor
+ *
+ * Remove ending newlines from the buffer.
+ */
+void trace_seq_trim_newlines(struct trace_seq *s)
+{
+	if (unlikely(!s->seq.size || !s->seq.len))
+		return;
+
+	while (s->seq.len && s->buffer[s->seq.len - 1] == '\n') {
+		s->seq.len--;
+	}
+}
+
 /**
  * trace_seq_putc - trace sequence printing of simple character
  * @s: trace sequence descriptor



A similar thing would need to go into libtraceevent.

-- Steve
  

On Mon, Jul 31, 2023 at 9:21 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 31 Jul 2023 12:21:29 +0200
> Petr Mladek <pmladek@suse.com> wrote:
>
> > > Grepping through the kernel, I am surprised how many messages are
> > > missing the trailing newline when it is obvious they are not intended to
> > > be extended. I consider these bugs.
> >
> > I consider this bug as well.
> >

agreed.
I blame pr_cont()  at least in part.

Note - I have submitted
drm_dbg: add trailing newlines where missing
https://patchwork.freedesktop.org/series/121583/

it appears to have failed - on what look like unrelated failures - pipe etc


> > My understanding is that this patch affects only messages printed to
> > the ftrace buffer so that it does not affect printk() directly.
> >
> > But still. It creates a habit that is bad for printk(). Also relies
> > on the fact that people are aware of this macro and use it. IMHO,
> > it will not work in practice. Or do I miss something?

something like (opposite of) this, used inside pr_debug, would force
all callers to add \n.
#include <assert.h>
#define FAIL_IF_TRAILING_NEWLINE(str) \
 _Static_assert((str[sizeof(str) - 2] != '\n'), "String literal has a
trailing newline")

obviously, Inverted, gentler versions are perhaps better.

>
> I believe that the problem Jim is addressing is that there's printk()
> messages that also go to a tracepoint() function. The tracepoint function
> will add its own '\n' to the message, and now we have two '\n's and this
> causes extra spaces in the output of the ftrace ring buffer.

Yes. only quibble - there arent yet, there could be.
Vincents patch didnt go in, Im trying to get it ready for another submit.

I uncovered this bit on the way,
figured I could turn it into a question, and maybe a little conceptual buy-in.

This is a 0 or 1 "\n" problem,
quietly accepting 25 in a row could paper over another problem.
maybe complain-once after 2-3 ?

TP_printk_no_nl   doesnt solve all problems -
it could work for adding DRM.debug trace-events,
cuz the callsites have few of the bad-habits noted above,
*very* few drm_dbg()s without trailing \n. - presuming theyre fixable.

fixing the larger body of pr_debug()s is quite a nuisance,
and if dyndbg -T flag sends them, you'd get the larger varying
population of \n's
So some real-time stripping /adding is needed for some populations of pr_debugs

the no_nl macro would at least allow event-definers
to assert that theyre sending their own.


>
> Perhaps what we should do is to make sure that the output doesn't add more
> newlines than just one.
>
> Something like this: (totally untested)
>
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index db575094c498..a1b73ffa1552 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -333,6 +333,8 @@ int trace_output_raw(struct trace_iterator *iter, char *name,
>
>         trace_seq_printf(s, "%s: ", name);
>         trace_seq_vprintf(s, trace_event_format(iter, fmt), ap);
> +       trace_seq_trim_newlines(s);
> +       trace_seq_putc(s, '\n');
>
>         return trace_handle_return(s);
>  }
> diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
> index bac06ee3b98b..d4e2049809e3 100644
> --- a/kernel/trace/trace_seq.c
> +++ b/kernel/trace/trace_seq.c
> @@ -221,6 +221,22 @@ void trace_seq_puts(struct trace_seq *s, const char *str)
>  }
>  EXPORT_SYMBOL_GPL(trace_seq_puts);
>
> +/**
> + * trace_seq_trim_newlines - remove ending newlines
> + * @s: trace sequence descriptor
> + *
> + * Remove ending newlines from the buffer.
> + */
> +void trace_seq_trim_newlines(struct trace_seq *s)
> +{
> +       if (unlikely(!s->seq.size || !s->seq.len))
> +               return;
> +
> +       while (s->seq.len && s->buffer[s->seq.len - 1] == '\n') {
> +               s->seq.len--;
> +       }
> +}
> +
>  /**
>   * trace_seq_putc - trace sequence printing of simple character
>   * @s: trace sequence descriptor
>
>
>
> A similar thing would need to go into libtraceevent.
>
> -- Steve