[PATCH] perf trace: always print return value for syscalls with set errpid

[PATCH] perf trace: always print return value for syscalls with set errpid

[Anubhav Shelat]

Currently some syscalls that have errpid set to true do not print a
return value in perf trace. The syscalls that were consistently
observed were set_robust_list and rseq. This is because perf cannot find
their child process. This change ensures that the return value is always
printed.

Before:
     0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len: 24)                        =
     0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32, sig: 1392848979)             =
After:
     0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len: 24)                        = 0
     0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32, sig: 1392848979)             = 0

Signed-off-by: Anubhav Shelat <ashelat@redhat.com>
---
 tools/perf/builtin-trace.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 6ac51925ea42..c192f0219b2b 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3005,8 +3005,8 @@ errno_print: {
 	else if (sc->fmt->errpid) {
 		struct thread *child = machine__find_thread(trace->host, ret, ret);
 
+		fprintf(trace->output, "%ld", ret);
 		if (child != NULL) {
-			fprintf(trace->output, "%ld", ret);
 			if (thread__comm_set(child))
 				fprintf(trace->output, " (%s)", thread__comm_str(child));
 			thread__put(child);
-- 
2.48.1

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Howard Chu]

[Resend due to rejection by mailing list]

Hello Anubhav,

Thanks for doing this :)

On Thu, Apr 3, 2025 at 9:06 AM Anubhav Shelat <ashelat@redhat.com> wrote:
>
> Currently some syscalls that have errpid set to true do not print a
> return value in perf trace. The syscalls that were consistently
> observed were set_robust_list and rseq. This is because perf cannot find
> their child process. This change ensures that the return value is always
> printed.
>
> Before:
>      0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len: 24)                        =
>      0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32, sig: 1392848979)             =
> After:
>      0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len: 24)                        = 0
>      0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32, sig: 1392848979)             = 0
>
> Signed-off-by: Anubhav Shelat <ashelat@redhat.com>

Reviewed-by: Howard Chu <howardchu95@gmail.com>

Thanks,
Howard

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Howard Chu]

Hello,

Ping.

Thanks,
Howard

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Arnaldo Carvalho de Melo]

On Thu, Apr 03, 2025 at 08:26:52PM -0700, Howard Chu wrote:
> [Resend due to rejection by mailing list]
> 
> Hello Anubhav,
> 
> Thanks for doing this :)
> 
> On Thu, Apr 3, 2025 at 9:06 AM Anubhav Shelat <ashelat@redhat.com> wrote:
> >
> > Currently some syscalls that have errpid set to true do not print a
> > return value in perf trace. The syscalls that were consistently
> > observed were set_robust_list and rseq. This is because perf cannot find
> > their child process. This change ensures that the return value is always
> > printed.
> >
> > Before:
> >      0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len: 24)                        =
> >      0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32, sig: 1392848979)             =
> > After:
> >      0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len: 24)                        = 0
> >      0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32, sig: 1392848979)             = 0
> >
> > Signed-off-by: Anubhav Shelat <ashelat@redhat.com>
> 
> Reviewed-by: Howard Chu <howardchu95@gmail.com>

Thanks, applied after rewording it a bit to mention that this not
related to rseq/set_robust_list as those shouldn't be using errpid, but
that the problem predates that and added this, where the problem
started:

Fixes: 11c8e39f5133aed9 ("perf trace: Infrastructure to show COMM strings for syscalls returning PIDs")

- Arnaldo

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Anubhav Shelat]

Sent the second patch for errpid.

Best,
Anubhav

On Wed, May 28, 2025 at 2:41 PM Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>
> On Thu, Apr 03, 2025 at 08:26:52PM -0700, Howard Chu wrote:
> > [Resend due to rejection by mailing list]
> >
> > Hello Anubhav,
> >
> > Thanks for doing this :)
> >
> > On Thu, Apr 3, 2025 at 9:06 AM Anubhav Shelat <ashelat@redhat.com> wrote:
> > >
> > > Currently some syscalls that have errpid set to true do not print a
> > > return value in perf trace. The syscalls that were consistently
> > > observed were set_robust_list and rseq. This is because perf cannot find
> > > their child process. This change ensures that the return value is always
> > > printed.
> > >
> > > Before:
> > >      0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len: 24)                        =
> > >      0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32, sig: 1392848979)             =
> > > After:
> > >      0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len: 24)                        = 0
> > >      0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32, sig: 1392848979)             = 0
> > >
> > > Signed-off-by: Anubhav Shelat <ashelat@redhat.com>
> >
> > Reviewed-by: Howard Chu <howardchu95@gmail.com>
>
> Thanks, applied after rewording it a bit to mention that this not
> related to rseq/set_robust_list as those shouldn't be using errpid, but
> that the problem predates that and added this, where the problem
> started:
>
> Fixes: 11c8e39f5133aed9 ("perf trace: Infrastructure to show COMM strings for syscalls returning PIDs")
>
> - Arnaldo
>

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Namhyung Kim]

On Thu, Apr 03, 2025 at 12:04:12PM -0400, Anubhav Shelat wrote:
> Currently some syscalls that have errpid set to true do not print a
> return value in perf trace. The syscalls that were consistently
> observed were set_robust_list and rseq. This is because perf cannot find
> their child process. This change ensures that the return value is always
> printed.
> 
> Before:
>      0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len: 24)                        =
>      0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32, sig: 1392848979)             =
> After:
>      0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len: 24)                        = 0
>      0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32, sig: 1392848979)             = 0

I'm ok with the change but I'm not sure if they are right syscalls.  It
seems neither of syscalls return a thread id.

Thanks,
Namhyung

> 
> Signed-off-by: Anubhav Shelat <ashelat@redhat.com>
> ---
>  tools/perf/builtin-trace.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index 6ac51925ea42..c192f0219b2b 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -3005,8 +3005,8 @@ errno_print: {
>  	else if (sc->fmt->errpid) {
>  		struct thread *child = machine__find_thread(trace->host, ret, ret);
>  
> +		fprintf(trace->output, "%ld", ret);
>  		if (child != NULL) {
> -			fprintf(trace->output, "%ld", ret);
>  			if (thread__comm_set(child))
>  				fprintf(trace->output, " (%s)", thread__comm_str(child));
>  			thread__put(child);
> -- 
> 2.48.1
> 

Re: [PATCH] perf trace: always print return value for syscalls with set errpid

[Arnaldo Carvalho de Melo]

On Tue, May 27, 2025 at 12:34:34PM -0400, Anubhav Shelat wrote:
>    Every time I ran perf trace I saw that the return value for only
>    set_robust_list and rseq was empty, even though while stepping through
>    the code the return value was 0. So I do think that these are the right
>    syscalls.
>    The cause of the problem is that no thread id is returned, so the logic
>    skips printing the return value. The change ensures the return value

Well:

RETURN VALUE
       The set_robust_list() and get_robust_list() system calls return zero when the operation is successful, an error code otherwise.

and rset return -errno on failure, so they are both not returning a pid
and should print errno when less than zero.

>    always gets printed. Another solution would be to set errpid to false
>    for both set_robust_list and rseq.

Can you please send a new patch with this? please add a Fixes tag as
well, for these two csets:

⬢ [acme@toolbx perf-tools-next]$ git blame tools/perf/builtin-trace.c  | grep -E '"(rseq|set_robust_list)"'
0c1019e3463b263a8 (Arnaldo Carvalho de Melo    2024-09-11 16:34:16 -0300 1351) 	{ .name	    = "rseq",	    .errpid = true,
1de5b5dcb8353f365 (Arnaldo Carvalho de Melo    2024-09-11 17:10:33 -0300 1375) 	{ .name	    = "set_robust_list",	    .errpid = true,
⬢ [acme@toolbx perf-tools-next]$ 

My mistake, that was a copy'n'paste error, those '.errpid = true'
shouldn't be there, as you noticed.

The first patch from you is also valid, but due to a different reason,
as Namhyung pointed out.

So I'm applying it now.

- Arnaldo

>    Best, Anubhav

>    On Sun, May 18, 2025 at 2:03 PM Namhyung Kim <[1]namhyung@kernel.org>
>    wrote:
> 
>      On Thu, Apr 03, 2025 at 12:04:12PM -0400, Anubhav Shelat wrote:
>      > Currently some syscalls that have errpid set to true do not print
>      a
>      > return value in perf trace. The syscalls that were consistently
>      > observed were set_robust_list and rseq. This is because perf
>      cannot find
>      > their child process. This change ensures that the return value is
>      always
>      > printed.
>      >
>      > Before:
>      >      0.256 ( 0.001 ms): set_robust_list(head: 0x7f09c77dba20, len:
>      24)                        =
>      >      0.259 ( 0.001 ms): rseq(rseq: 0x7f09c77dc0e0, rseq_len: 32,
>      sig: 1392848979)             =
>      > After:
>      >      0.270 ( 0.002 ms): set_robust_list(head: 0x7f0bb14a6a20, len:
>      24)                        = 0
>      >      0.273 ( 0.002 ms): rseq(rseq: 0x7f0bb14a70e0, rseq_len: 32,
>      sig: 1392848979)             = 0
> 
>      I'm ok with the change but I'm not sure if they are right syscalls.
>      It
>      seems neither of syscalls return a thread id.
> 
>      Thanks,
>      Namhyung
> 
>      >
>      > Signed-off-by: Anubhav Shelat <[2]ashelat@redhat.com>
>      > ---
>      >  tools/perf/builtin-trace.c | 2 +-
>      >  1 file changed, 1 insertion(+), 1 deletion(-)
>      >
>      > diff --git a/tools/perf/builtin-trace.c
>      b/tools/perf/builtin-trace.c
>      > index 6ac51925ea42..c192f0219b2b 100644
>      > --- a/tools/perf/builtin-trace.c
>      > +++ b/tools/perf/builtin-trace.c
>      > @@ -3005,8 +3005,8 @@ errno_print: {
>      >       else if (sc->fmt->errpid) {
>      >               struct thread *child =
>      machine__find_thread(trace->host, ret, ret);
>      >
>      > +             fprintf(trace->output, "%ld", ret);
>      >               if (child != NULL) {
>      > -                     fprintf(trace->output, "%ld", ret);
>      >                       if (thread__comm_set(child))
>      >                               fprintf(trace->output, " (%s)",
>      thread__comm_str(child));
>      >                       thread__put(child);
>      > --
>      > 2.48.1
>      >
> 
> References
> 
>    1. mailto:namhyung@kernel.org
>    2. mailto:ashelat@redhat.com