[PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Steven Rostedt]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Arnaldo noticed that the latest kernel is missing the syscall event system
directory in x86. I bisected it down to d5a00528b58c ("syscalls/core,
syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()").

The system call trace events are special, as there is only one trace event
for all system calls (the raw_syscalls). But a macro that wraps the system
calls creates meta data for them that copies the name to find the system
call that maps to the system call table (the number). At boot up, it does a
kallsyms lookup for this mapping. If it does not find a function, then that
system call is ignored.

Because the x86 system calls had "__x86_" appended to the "sys" for the
names, they do not match the default compare algorithm. As this was a
problem for power pc, the algorithm can be overwritten by the architecture.
The solution is to have x86 have its own algorithm to do the compare and
this brings back the system call trace events.

Reported-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Fixes: d5a00528b58c ("syscalls/core, syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 arch/x86/include/asm/ftrace.h | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/arch/x86/include/asm/ftrace.h b/arch/x86/include/asm/ftrace.h
index 09ad88572746..c30b3fac20ae 100644
--- a/arch/x86/include/asm/ftrace.h
+++ b/arch/x86/include/asm/ftrace.h
@@ -31,6 +31,16 @@ static inline unsigned long ftrace_call_adjust(unsigned long addr)
 	return addr;
 }
 
+#define ARCH_HAS_SYSCALL_MATCH_SYM_NAME
+static inline bool arch_syscall_match_sym_name(const char *sym, const char *name)
+{
+	/*
+	 * Compare the symbol name with the system call name. Skip the
+	 * "__x64_sys" prefix.
+	 */
+	return !strcmp(sym + 9, name + 3);
+}
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 struct dyn_arch_ftrace {
-- 
2.13.6

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Dominik Brodowski]

Steven,

On Tue, Apr 17, 2018 at 11:54:40AM -0400, Steven Rostedt wrote:
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Arnaldo noticed that the latest kernel is missing the syscall event system
> directory in x86. I bisected it down to d5a00528b58c ("syscalls/core,
> syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()").
> 
> The system call trace events are special, as there is only one trace event
> for all system calls (the raw_syscalls). But a macro that wraps the system
> calls creates meta data for them that copies the name to find the system
> call that maps to the system call table (the number). At boot up, it does a
> kallsyms lookup for this mapping. If it does not find a function, then that
> system call is ignored.
> 
> Because the x86 system calls had "__x86_" appended to the "sys" for the

__x64 actually.

> names, they do not match the default compare algorithm. As this was a
> problem for power pc, the algorithm can be overwritten by the architecture.
> The solution is to have x86 have its own algorithm to do the compare and
> this brings back the system call trace events.

this lets me wonder *which* syscall "function" should be included in this
directory. Is it really the stub (__x64_sys_waitid, for example), or better
the sign-extending C function (__se_sys_waitid) which then calls an
internal helper (__do_sys_waitid). An additional advantage:
__se_sys_waitid would be available on x86 and, AFAICS, on all other archs.

> Reported-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> Fixes: d5a00528b58c ("syscalls/core, syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()")
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  arch/x86/include/asm/ftrace.h | 10 ++++++++++
>  1 file changed, 10 insertions(+)
> 
> diff --git a/arch/x86/include/asm/ftrace.h b/arch/x86/include/asm/ftrace.h
> index 09ad88572746..c30b3fac20ae 100644
> --- a/arch/x86/include/asm/ftrace.h
> +++ b/arch/x86/include/asm/ftrace.h
> @@ -31,6 +31,16 @@ static inline unsigned long ftrace_call_adjust(unsigned long addr)
>  	return addr;
>  }
>  
> +#define ARCH_HAS_SYSCALL_MATCH_SYM_NAME
> +static inline bool arch_syscall_match_sym_name(const char *sym, const char *name)
> +{
> +	/*
> +	 * Compare the symbol name with the system call name. Skip the
> +	 * "__x64_sys" prefix.
> +	 */
> +	return !strcmp(sym + 9, name + 3);
> +}

What are the first three chars you skip for *name?

Thanks,
	Dominik

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Arnaldo Carvalho de Melo]

Em Tue, Apr 17, 2018 at 11:54:40AM -0400, Steven Rostedt escreveu:
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Arnaldo noticed that the latest kernel is missing the syscall event system
> directory in x86. I bisected it down to d5a00528b58c ("syscalls/core,
> syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()").
> 
> The system call trace events are special, as there is only one trace event
> for all system calls (the raw_syscalls). But a macro that wraps the system
> calls creates meta data for them that copies the name to find the system
> call that maps to the system call table (the number). At boot up, it does a
> kallsyms lookup for this mapping. If it does not find a function, then that
> system call is ignored.
> 
> Because the x86 system calls had "__x86_" appended to the "sys" for the
> names, they do not match the default compare algorithm. As this was a
> problem for power pc, the algorithm can be overwritten by the architecture.
> The solution is to have x86 have its own algorithm to do the compare and
> this brings back the system call trace events.
> 
> Reported-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> Fixes: d5a00528b58c ("syscalls/core, syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()")
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

[root@jouet ~]# perf test openat
 2: Detect openat syscall event                           : Ok
 3: Detect openat syscall event on all cpus               : Ok
15: syscalls:sys_enter_openat event fields                : Ok
[root@jouet ~]#

[root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
     0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
     0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
  1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
     0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
[root@jouet ~]#

Works, so the regression seems to be fixed, without looking at the code
that much:

Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>

- Arnaldo

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Steven Rostedt]

On Tue, 17 Apr 2018 18:10:29 +0200
Dominik Brodowski <linux@dominikbrodowski.net> wrote:


> > Because the x86 system calls had "__x86_" appended to the "sys" for the  
> 
> __x64 actually.

Heh, I constantly make that mistake.

Hmm, OK, I need to look at this a bit more. If this is x64, then
there's probably syscalls (on 32 bit), that don't have that. It should
probably include more checks. Something like:

  return !strcmp(sym + 9, name + 3) || !strcmp(sym + 3, name + 3);


> 
> > names, they do not match the default compare algorithm. As this was a
> > problem for power pc, the algorithm can be overwritten by the architecture.
> > The solution is to have x86 have its own algorithm to do the compare and
> > this brings back the system call trace events.  
> 
> this lets me wonder *which* syscall "function" should be included in this
> directory. Is it really the stub (__x64_sys_waitid, for example), or better
> the sign-extending C function (__se_sys_waitid) which then calls an
> internal helper (__do_sys_waitid). An additional advantage:
> __se_sys_waitid would be available on x86 and, AFAICS, on all other archs.

It should include anything that uses the "SYSCALL_DEFINE#()" macros.

> 
> > Reported-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> > Fixes: d5a00528b58c ("syscalls/core, syscalls/x86: Rename struct pt_regs-based sys_*() to __x64_sys_*()")
> > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> > ---
> >  arch/x86/include/asm/ftrace.h | 10 ++++++++++
> >  1 file changed, 10 insertions(+)
> > 
> > diff --git a/arch/x86/include/asm/ftrace.h b/arch/x86/include/asm/ftrace.h
> > index 09ad88572746..c30b3fac20ae 100644
> > --- a/arch/x86/include/asm/ftrace.h
> > +++ b/arch/x86/include/asm/ftrace.h
> > @@ -31,6 +31,16 @@ static inline unsigned long ftrace_call_adjust(unsigned long addr)
> >  	return addr;
> >  }
> >  
> > +#define ARCH_HAS_SYSCALL_MATCH_SYM_NAME
> > +static inline bool arch_syscall_match_sym_name(const char *sym, const char *name)
> > +{
> > +	/*
> > +	 * Compare the symbol name with the system call name. Skip the
> > +	 * "__x64_sys" prefix.
> > +	 */
> > +	return !strcmp(sym + 9, name + 3);
> > +}  
> 
> What are the first three chars you skip for *name?

"sys_"

-- Steve

> 
> Thanks,
> 	Dominik

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Steven Rostedt]

On Tue, 17 Apr 2018 13:35:27 -0300
Arnaldo Carvalho de Melo <acme@kernel.org> wrote:


> [root@jouet ~]# perf test openat
>  2: Detect openat syscall event                           : Ok
>  3: Detect openat syscall event on all cpus               : Ok
> 15: syscalls:sys_enter_openat event fields                : Ok
> [root@jouet ~]#
> 
> [root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
>      0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
>      0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
>   1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
>      0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
> [root@jouet ~]#
> 
> Works, so the regression seems to be fixed, without looking at the code
> that much:
> 
> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>

But does this still work on x86_32? I'll test that out. Thanks for
testing, but I may have another patch soon.

-- Steve

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Arnaldo Carvalho de Melo]

Em Tue, Apr 17, 2018 at 12:40:19PM -0400, Steven Rostedt escreveu:
> On Tue, 17 Apr 2018 13:35:27 -0300
> Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> 
> 
> > [root@jouet ~]# perf test openat
> >  2: Detect openat syscall event                           : Ok
> >  3: Detect openat syscall event on all cpus               : Ok
> > 15: syscalls:sys_enter_openat event fields                : Ok
> > [root@jouet ~]#
> > 
> > [root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
> >      0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
> >      0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
> >   1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
> >      0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
> > [root@jouet ~]#
> > 
> > Works, so the regression seems to be fixed, without looking at the code
> > that much:
> > 
> > Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> 
> But does this still work on x86_32? I'll test that out. Thanks for
> testing, but I may have another patch soon.

I haven't tested that case, no.

- Arnaldo

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Steven Rostedt]

On Tue, 17 Apr 2018 12:40:19 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 17 Apr 2018 13:35:27 -0300
> Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> 
> 
> > [root@jouet ~]# perf test openat
> >  2: Detect openat syscall event                           : Ok
> >  3: Detect openat syscall event on all cpus               : Ok
> > 15: syscalls:sys_enter_openat event fields                : Ok
> > [root@jouet ~]#
> > 
> > [root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
> >      0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
> >      0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
> >   1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
> >      0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
> > [root@jouet ~]#
> > 
> > Works, so the regression seems to be fixed, without looking at the code
> > that much:
> > 
> > Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>  
> 
> But does this still work on x86_32? I'll test that out. Thanks for
> testing, but I may have another patch soon.

OK, it's still broken there with this patch. I got this:

# ls /sys/kernel/tracing/events/syscalls
enable
filter
sys_enter_nanosleep
sys_exit_nanosleep

But with this:

	return !strcmp(sym + 9, name + 3) || !strcmp(sym + 3, name + 3);

I get all the syscalls back. I'll make another patch.

-- Steve

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Dominik Brodowski]

On Tue, Apr 17, 2018 at 12:39:27PM -0400, Steven Rostedt wrote:
> > > names, they do not match the default compare algorithm. As this was a
> > > problem for power pc, the algorithm can be overwritten by the architecture.
> > > The solution is to have x86 have its own algorithm to do the compare and
> > > this brings back the system call trace events.  
> > 
> > this lets me wonder *which* syscall "function" should be included in this
> > directory. Is it really the stub (__x64_sys_waitid, for example), or better
> > the sign-extending C function (__se_sys_waitid) which then calls an
> > internal helper (__do_sys_waitid). An additional advantage:
> > __se_sys_waitid would be available on x86 and, AFAICS, on all other archs.
> 
> It should include anything that uses the "SYSCALL_DEFINE#()" macros.

Well, that's not a 1:1, but a 1:several translation... SYSCALL_DEFINEx()
[SYSCALL_DEFINE0() is special] expands to

	__do_sys_waitid     # inlined helper doing actual work
	__se_sys_waitid     # C func calling inlined helper

on all architectures, with most (!= 64-bit x86) also having

	     sys_waitid	    # alias to __se_sys_waitid()

On 64-bit x86, it does not only extend to the two functions mentioned above,
but also to one or two stubs (depending on the configuration), namely

	  __x64_sys_waitid  # x64 64-bit-ptregs -> C stub
	 __ia32_sys_waitid  # ia32 32-bit-ptregs -> C stub

Thanks,
	Dominik

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Arnaldo Carvalho de Melo]

Em Tue, Apr 17, 2018 at 12:57:23PM -0400, Steven Rostedt escreveu:
> On Tue, 17 Apr 2018 12:40:19 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Tue, 17 Apr 2018 13:35:27 -0300
> > Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > 
> > 
> > > [root@jouet ~]# perf test openat
> > >  2: Detect openat syscall event                           : Ok
> > >  3: Detect openat syscall event on all cpus               : Ok
> > > 15: syscalls:sys_enter_openat event fields                : Ok
> > > [root@jouet ~]#
> > > 
> > > [root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
> > >      0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
> > >      0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
> > >   1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
> > >      0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
> > > [root@jouet ~]#
> > > 
> > > Works, so the regression seems to be fixed, without looking at the code
> > > that much:
> > > 
> > > Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>  
> > 
> > But does this still work on x86_32? I'll test that out. Thanks for
> > testing, but I may have another patch soon.
> 
> OK, it's still broken there with this patch. I got this:
> 
> # ls /sys/kernel/tracing/events/syscalls
> enable
> filter
> sys_enter_nanosleep
> sys_exit_nanosleep
> 
> But with this:
> 
> 	return !strcmp(sym + 9, name + 3) || !strcmp(sym + 3, name + 3);
> 
> I get all the syscalls back. I'll make another patch.

[root@jouet ~]# ls -lad /e/syscalls/sys_enter_* | wc -l
299
[root@jouet ~]# ls -lad /e/syscalls/sys_* | wc -l
598
[root@jouet ~]# uname -a
Linux jouet 4.17.0-rc1-00025-g69dd313cd795 #11 SMP Tue Apr 17 13:18:44 -03 2018 x86_64 x86_64 x86_64 GNU/Linux
[root@jouet ~]#

With your first patch, I'll change to the above...

- Arnaldo

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Arnaldo Carvalho de Melo]

Em Tue, Apr 17, 2018 at 12:57:23PM -0400, Steven Rostedt escreveu:
> On Tue, 17 Apr 2018 12:40:19 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Tue, 17 Apr 2018 13:35:27 -0300
> > Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > 
> > 
> > > [root@jouet ~]# perf test openat
> > >  2: Detect openat syscall event                           : Ok
> > >  3: Detect openat syscall event on all cpus               : Ok
> > > 15: syscalls:sys_enter_openat event fields                : Ok
> > > [root@jouet ~]#
> > > 
> > > [root@jouet ~]# perf trace -e nanosleep,syscalls:*nanosleep sleep 1
> > >      0.000 (         ): syscalls:sys_enter_nanosleep:rqtp: 0x7ffd9f737950, rmtp: 0x00000000
> > >      0.009 (         ): sleep/7905 nanosleep(rqtp: 0x7ffd9f737950                                        ) ...
> > >   1000.204 (         ): syscalls:sys_exit_nanosleep:0x0
> > >      0.009 (1000.217 ms): sleep/7905  ... [continued]: nanosleep()) = 0
> > > [root@jouet ~]#
> > > 
> > > Works, so the regression seems to be fixed, without looking at the code
> > > that much:
> > > 
> > > Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>  
> > 
> > But does this still work on x86_32? I'll test that out. Thanks for
> > testing, but I may have another patch soon.
> 
> OK, it's still broken there with this patch. I got this:
> 
> # ls /sys/kernel/tracing/events/syscalls
> enable
> filter
> sys_enter_nanosleep
> sys_exit_nanosleep
> 
> But with this:
> 
> 	return !strcmp(sym + 9, name + 3) || !strcmp(sym + 3, name + 3);
> 
> I get all the syscalls back. I'll make another patch.

Argh, rebuilding the world, since lots of places include ftrace.h...

- Arnaldo

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Steven Rostedt]

On Tue, 17 Apr 2018 14:08:22 -0300
Arnaldo Carvalho de Melo <acme@kernel.org> wrote:

> > I get all the syscalls back. I'll make another patch.  
> 
> Argh, rebuilding the world, since lots of places include ftrace.h...

"make localmodconfig" is your friend.

-- Steve

Re: [PATCH] tracing/x86: Update syscall trace events to handle new x86 syscall func names

[Arnaldo Carvalho de Melo]

Em Tue, Apr 17, 2018 at 01:10:16PM -0400, Steven Rostedt escreveu:
> On Tue, 17 Apr 2018 14:08:22 -0300
> Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> 
> > > I get all the syscalls back. I'll make another patch.  
> > 
> > Argh, rebuilding the world, since lots of places include ftrace.h...
> 
> "make localmodconfig" is your friend.

I'm using that.

- Arnaldo