| Message ID | 20250318180939.227696-1-douglas.raillard@arm.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | tracing: Fix synth event printk format for str fields | expand |
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 >
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 >>
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 > >> >
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
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
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
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);