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

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

[Douglas RAILLARD]

From: Douglas Raillard <douglas.raillard@arm.com>

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.

Signed-off-by: Douglas Raillard <douglas.raillard@arm.com>
---
 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

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

[Masami Hiramatsu]

Hi,

On Tue, 18 Mar 2025 18:09:38 +0000
Douglas RAILLARD <douglas.raillard@arm.com> wrote:

> From: Douglas Raillard <douglas.raillard@arm.com>
> 
> 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.

Thank you,

> 
> Signed-off-by: Douglas Raillard <douglas.raillard@arm.com>
> ---
>  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
> 


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

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

[Douglas Raillard]

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@arm.com> wrote:
> 
>> From: Douglas Raillard <douglas.raillard@arm.com>
>>
>> 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.

> 
> Thank you,
> 
>>
>> Signed-off-by: Douglas Raillard <douglas.raillard@arm.com>
>> ---
>>   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
>>

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

[Masami Hiramatsu]

On Wed, 19 Mar 2025 14:34:19 +0000
Douglas Raillard <douglas.raillard@arm.com> 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@arm.com> wrote:
> > 
> >> From: Douglas Raillard <douglas.raillard@arm.com>
> >>
> >> 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@kernel.org/T/#u

So, I think it should always print the STR_VAR_LEN_MAX value.
Steve, can you check it?

Thank you,

> 
> > 
> > Thank you,
> > 
> >>
> >> Signed-off-by: Douglas Raillard <douglas.raillard@arm.com>
> >> ---
> >>   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
> >>
> 


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

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@arm.com> 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@arm.com> wrote:
>>>
>>>> From: Douglas Raillard <douglas.raillard@arm.com>
>>>>
>>>> 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@kernel.org/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@arm.com>
>>>> ---
>>>>    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

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

[Steven Rostedt]

On Mon, 24 Mar 2025 10:18:50 +0000
Douglas Raillard <douglas.raillard@arm.com> wrote:

> > https://lore.kernel.org/all/b6bdb34e70d970e8026daa3503db6b8e5cdad524.1601848695.git.zanussi@kernel.org/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?

So I did take this patch, but thinking about this more, I may remove it.

The __get_str() doesn't expect a string end. The parser should limit it, as
the length of the string is saved in the ring buffer. Just like other trace
events where dynamically size strings only use "%s" and __get_str().

I think the real fix is to replace the "%.*s" with "%s".

-- Steve

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

[Steven Rostedt]

On Mon, 24 Mar 2025 09:40:05 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> So I did take this patch, but thinking about this more, I may remove it.
> 
> The __get_str() doesn't expect a string end. The parser should limit it, as
> the length of the string is saved in the ring buffer. Just like other trace
> events where dynamically size strings only use "%s" and __get_str().
> 
> I think the real fix is to replace the "%.*s" with "%s".

I just tested it out. Yep, it should just be "%s".

-- Steve