[v1] tracing: Show contents of syscall trace event user space fields

[PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10

Posted by Steven Rostedt 2 months ago

From: Steven Rostedt <rostedt@goodmis.org>

Currently the syscall trace events show each value as hexadecimal, but
without adding "0x" it can be confusing:

   sys_write(fd: 4, buf: 0x55c4a1fa9270, count: 44)

Looks like the above write wrote 44 bytes, when in reality it wrote 68
bytes.

Add a "0x" for all values greater or equal to 10 to remove the ambiguity.
For values less than 10, leave off the "0x" as that just adds noise to the
output.

Also change the iterator to check if "i" is nonzero and print the ", "
delimiter at the start, then adding the logic to the trace_seq_printf() at
the end.

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 kernel/trace/trace_syscalls.c | 12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index 3a0b65f89130..0f932b22f9ec 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -153,14 +153,20 @@ print_syscall_enter(struct trace_iterator *iter, int flags,
 		if (trace_seq_has_overflowed(s))
 			goto end;
 
+		if (i)
+			trace_seq_puts(s, ", ");
+
 		/* parameter types */
 		if (tr && tr->trace_flags & TRACE_ITER_VERBOSE)
 			trace_seq_printf(s, "%s ", entry->types[i]);
 
 		/* parameter values */
-		trace_seq_printf(s, "%s: %lx%s", entry->args[i],
-				 trace->args[i],
-				 i == entry->nb_args - 1 ? "" : ", ");
+		if (trace->args[i] < 10)
+			trace_seq_printf(s, "%s: %lu", entry->args[i],
+					 trace->args[i]);
+		else
+			trace_seq_printf(s, "%s: 0x%lx", entry->args[i],
+					 trace->args[i]);
 	}
 
 	trace_seq_putc(s, ')');
-- 
2.47.2

Re: [PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10

Posted by Douglas Raillard 2 months ago

On 05-08-2025 20:26, Steven Rostedt wrote:
> From: Steven Rostedt <rostedt@goodmis.org>
> 
> Currently the syscall trace events show each value as hexadecimal, but
> without adding "0x" it can be confusing:
> 
>     sys_write(fd: 4, buf: 0x55c4a1fa9270, count: 44)
> 
> Looks like the above write wrote 44 bytes, when in reality it wrote 68
> bytes.
> 
> Add a "0x" for all values greater or equal to 10 to remove the ambiguity.
> For values less than 10, leave off the "0x" as that just adds noise to the
> output.

I'm on the fence for the value-dependent format. This looks like
it could easily make life harder for quick&dirty scripts, but then both
awk's strtonum() and Python's int(x, base=16) seem to handle
the presence/absence of the 0x prefix so maybe it's a non-issue.

OTH, a hand-crafted regex designed after a small set of input may start
to randomly fail if one field unexpectedly goes beyond 10 ...

Just using explicit hex may be the best here, as the actual proper fix
(type-level display hints) is harder. It could probably be implemented
using btf_decl_tag() and __builtin_btf_type_id() to retrieve the BTF info.

> 
> Also change the iterator to check if "i" is nonzero and print the ", "
> delimiter at the start, then adding the logic to the trace_seq_printf() at
> the end.
> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
>   kernel/trace/trace_syscalls.c | 12 +++++++++---
>   1 file changed, 9 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
> index 3a0b65f89130..0f932b22f9ec 100644
> --- a/kernel/trace/trace_syscalls.c
> +++ b/kernel/trace/trace_syscalls.c
> @@ -153,14 +153,20 @@ print_syscall_enter(struct trace_iterator *iter, int flags,
>   		if (trace_seq_has_overflowed(s))
>   			goto end;
>   
> +		if (i)
> +			trace_seq_puts(s, ", ");
> +
>   		/* parameter types */
>   		if (tr && tr->trace_flags & TRACE_ITER_VERBOSE)
>   			trace_seq_printf(s, "%s ", entry->types[i]);
>   
>   		/* parameter values */
> -		trace_seq_printf(s, "%s: %lx%s", entry->args[i],
> -				 trace->args[i],
> -				 i == entry->nb_args - 1 ? "" : ", ");
> +		if (trace->args[i] < 10)
> +			trace_seq_printf(s, "%s: %lu", entry->args[i],
> +					 trace->args[i]);
> +		else
> +			trace_seq_printf(s, "%s: 0x%lx", entry->args[i],
> +					 trace->args[i]);
>   	}
>   
>   	trace_seq_putc(s, ')');

-- 
Douglas

Re: [PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10

Posted by Steven Rostedt 1 month, 4 weeks ago

On Wed, 6 Aug 2025 11:24:33 +0100
Douglas Raillard <douglas.raillard@arm.com> wrote:

> On 05-08-2025 20:26, Steven Rostedt wrote:
> > From: Steven Rostedt <rostedt@goodmis.org>
> > 
> > Currently the syscall trace events show each value as hexadecimal, but
> > without adding "0x" it can be confusing:
> > 
> >     sys_write(fd: 4, buf: 0x55c4a1fa9270, count: 44)
> > 
> > Looks like the above write wrote 44 bytes, when in reality it wrote 68
> > bytes.
> > 
> > Add a "0x" for all values greater or equal to 10 to remove the ambiguity.
> > For values less than 10, leave off the "0x" as that just adds noise to the
> > output.  
> 
> I'm on the fence for the value-dependent format. This looks like
> it could easily make life harder for quick&dirty scripts, but then both
> awk's strtonum() and Python's int(x, base=16) seem to handle
> the presence/absence of the 0x prefix so maybe it's a non-issue.

Yes, but the trace file is more for humans than scripts, and the 0x1 is
just noise.

> 
> OTH, a hand-crafted regex designed after a small set of input may start
> to randomly fail if one field unexpectedly goes beyond 10 ...

If you are doing hand crafted scripts, I'd suggest to use tracing
filters or other tooling that can handle this easily ;-)

> 
> Just using explicit hex may be the best here, as the actual proper fix
> (type-level display hints) is harder. It could probably be implemented
> using btf_decl_tag() and __builtin_btf_type_id() to retrieve the BTF info.

That would add a dependency on BTF, which I would like to avoid.

Thanks!

-- Steve

Re: [PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10

Posted by Douglas Raillard 1 month, 4 weeks ago

On 06-08-2025 13:39, Steven Rostedt wrote:
> On Wed, 6 Aug 2025 11:24:33 +0100
> Douglas Raillard <douglas.raillard@arm.com> wrote:
> 
>> On 05-08-2025 20:26, Steven Rostedt wrote:
>>> From: Steven Rostedt <rostedt@goodmis.org>
>>>
>>> Currently the syscall trace events show each value as hexadecimal, but
>>> without adding "0x" it can be confusing:
>>>
>>>      sys_write(fd: 4, buf: 0x55c4a1fa9270, count: 44)
>>>
>>> Looks like the above write wrote 44 bytes, when in reality it wrote 68
>>> bytes.
>>>
>>> Add a "0x" for all values greater or equal to 10 to remove the ambiguity.
>>> For values less than 10, leave off the "0x" as that just adds noise to the
>>> output.
>>
>> I'm on the fence for the value-dependent format. This looks like
>> it could easily make life harder for quick&dirty scripts, but then both
>> awk's strtonum() and Python's int(x, base=16) seem to handle
>> the presence/absence of the 0x prefix so maybe it's a non-issue.
> 
> Yes, but the trace file is more for humans than scripts, and the 0x1 is
> just noise.
> 
>>
>> OTH, a hand-crafted regex designed after a small set of input may start
>> to randomly fail if one field unexpectedly goes beyond 10 ...
> 
> If you are doing hand crafted scripts, I'd suggest to use tracing
> filters or other tooling that can handle this easily ;-)

Well, we both know I don't do this sort of things (or do I ? :) ) but for
the first 5+ years of its existence, LISA was actually parsing the text
output of trace-cmd, and I'd be surprised if it was the only place this was done.

AFAIK to this day, there is no tool providing a simple script/SQL interface
to a trace.dat file beyond basic filtering like trace-cmd report. I've had this
PR [1] opened for a while in LISA that does exactly that but got distracted with
other things:

   # Show all the CPUs that emitted a cpu_frequency event
   lisa-trace sql trace.dat --query 'SELECT DISTINCT cpu_id FROM cpu_frequency'

   shape: (8, 1)
   ┌────────┐
   │ cpu_id │
   │ ---    │
   │ u32    │
   ╞════════╡
   │ 0      │
   │ 1      │
   │ 2      │
   │ 3      │
   │ 7      │
   │ 4      │
   │ 5      │
   │ 6      │
   └────────┘


[1] https://gitlab.arm.com/tooling/lisa/-/merge_requests/2444

> 
>>
>> Just using explicit hex may be the best here, as the actual proper fix
>> (type-level display hints) is harder. It could probably be implemented
>> using btf_decl_tag() and __builtin_btf_type_id() to retrieve the BTF info.
> 
> That would add a dependency on BTF, which I would like to avoid.
> 
> Thanks!
> 
> -- Steve
> 

--
Douglas

Re: [PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10

Posted by Steven Rostedt 1 month, 3 weeks ago

On Wed, 6 Aug 2025 17:42:38 +0100
Douglas Raillard <douglas.raillard@arm.com> wrote:

> 
> AFAIK to this day, there is no tool providing a simple script/SQL interface
> to a trace.dat file beyond basic filtering like trace-cmd report. I've had this


Well, I did have this patch that I never applied:

https://lore.kernel.org/all/20200116104804.5d2f71e2@gandalf.local.home/

-- Steve

[PATCH 1/7] tracing: Replace syscall RCU pointer assignment with READ/WRITE_ONCE()
[PATCH 2/7] tracing: Have syscall trace events show "0x" for values greater than 10
[PATCH 3/7] tracing: Have syscall trace events read user space string
[PATCH 4/7] tracing: Have system call events record user array data
[PATCH 5/7] tracing: Display some syscall arrays as strings
[PATCH 6/7] tracing: Allow syscall trace events to read more than one user parameter
[PATCH 7/7] tracing: Add syscall_user_buf_size to limit amount written