Re: [PATCH] tracing: Fix synth event printk format for str fields

[Douglas Raillard]

On 24-03-2025 05:45, Masami Hiramatsu (Google) wrote:
> On Wed, 19 Mar 2025 14:34:19 +0000
> Douglas Raillard <douglas.raillard@xxxxxxx> wrote:
>
> > Hi,
> >
> > On 19-03-2025 12:18, Masami Hiramatsu (Google) wrote:
> > > Hi,
> > >
> > > On Tue, 18 Mar 2025 18:09:38 +0000
> > > Douglas RAILLARD <douglas.raillard@xxxxxxx> wrote:
> > >
> > > > From: Douglas Raillard <douglas.raillard@xxxxxxx>
> > > >
> > > > The printk format for synth event uses "%.*s" to print string fields,
> > > > but then only passes the pointer part as var arg.
> > > >
> > > > Add the missing precision var arg.
> > >
> > > I'm not sure what you want to. Would you mean showing the string length too?
> > > But I think actual output(*) shows only string, right?
> > >
> > > (*) the output data which can be read from `trace` file.
> >
> > The "%.*s" printf/printk format specifier has 2 components:
> > 1. the "*" part that in printf documentation called the "precision"
> > 2. the "s" part that is called the "specifier"
> >
> > For a "s" specifier, the precision is interpreted as the number of chars to display from that string.
> > In any case, using "*" as precision means the value is passed dynamically, as a parameter to printf/printk,
> > before the actual char *. Both those args are consumed by printk to display "%.*s", the precision is never
> > displayed on its own.
> >
> > In the current state, synthetic event use "%.*s" for string fields, but then only a single `__get_str(field)`
> > is passed to printk, so it's missing the precision arg. Both trace-cmd and our parser report an error because of that.
> >
> > The alternative would be to just use "%s" instead of "%.*s", but I assume whoever wrote the code initially had a reason
> > to use the precision (maybe to print non-null-terminated strings ?), so I simply fixed the arguments.
>
> Ah, got it. It seems that the first precision parameter is for limiting
> the length of the string according to the commit;
>
> https://lore.kernel.org/all/b6bdb34e70d970e8026daa3503db6b8e5cdad524.1601848695.git.zanussi@xxxxxxxxxx/T/#u
>
> So, I think it should always print the STR_VAR_LEN_MAX value.

That makes sense. It's tempting to keep the actual length value though as native Rust strings are not null-terminated, so
it could make it nicer to emit events from Rust code. From a cursory look, the in-tree Rust code seems to be using both
&str and &CStr (the latter being null-terminated for FFI needs) so I'm not sure what's the plan around those
and what's the established convention if any.

> Steve, can you check it?
>
> Thank you,
>
> > > Thank you,
> > >
> > > > Signed-off-by: Douglas Raillard <douglas.raillard@xxxxxxx>
> > > > ---
> > > >    kernel/trace/trace_events_synth.c | 3 ++-
> > > >    1 file changed, 2 insertions(+), 1 deletion(-)
> > > >
> > > > diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
> > > > index e3f7d09e5512..274b9b1d9f7d 100644
> > > > --- a/kernel/trace/trace_events_synth.c
> > > > +++ b/kernel/trace/trace_events_synth.c
> > > > @@ -620,7 +620,8 @@ static int __set_synth_event_print_fmt(struct synth_event *event,
> > > >    		if (event->fields[i]->is_string &&
> > > >    		    event->fields[i]->is_dynamic)
> > > >    			pos += snprintf(buf + pos, LEN_OR_ZERO,
> > > > -				", __get_str(%s)", event->fields[i]->name);
> > > > +				", (int)__get_dynamic_array_len(%s), __get_str(%s)",
> > > > +				event->fields[i]->name, event->fields[i]->name);
> > > >    		else if (event->fields[i]->is_stack)
> > > >    			pos += snprintf(buf + pos, LEN_OR_ZERO,
> > > >    				", __get_stacktrace(%s)", event->fields[i]->name);
> > > > --
> > > > 2.43.0

Thank you,

Douglas