Re: [PATCH 0/2 v2] Syscalls tracing

Mathieu Desnoyers
2009-03-13T16:49:18Z

* Frederic Weisbecker (fweisbec@gmail.com) wrote:
> On Fri, Mar 13, 2009 at 03:42:10PM +0100, Frederic Weisbecker wrote:
> > tracing/syscalls: core infrastructure to trace syscalls
> >
> > This new iteration addresses a good part of the previous reviews.
>
>
> Ah I just discovered that you applied the previous version today.
> But the v2 is not a delta :-s
>
> I can rebase them but not until Sunday.
>

Hi Frederic,

I like the approach you are taking for syscall tracing. As I read your
code, I see that your infrastructure basically exports the information
under ascii format. How hard do you think that would be to get this to
work for binary output with LTTng ? Ascii output is not exactly a
high-performance output for a hot path such as system call entry/exit.
We could :

1 - Iterate on the table at trace start to dump the syscall names, and
their arguments, into a syscall-table data channel.

2 - We might have to create one event type per syscall argument types.
Or one event per syscall, this would be great because we would benefit
from the event identification infrastructure. And actually, the syscall
declaration macros could declare tiny callbacks that would declare a
marker name (syscall, <syscall_name>) along with the code that saves the
system call pr_regs parameters into the event payload.

Any thoughts ?

Mathieu

>
> > As suggested by Ingo Molnar and Peter Zijlstra, the syscalls
> > prototypes probing is done by abusing the SYSCALL_DEFINE family
> > macros.
> > We now store automatically the arguments names, their types, their number
> > and the name of the syscall.
> >
> > Also some fixes on output newlines and dangerous exporting of global_trace
> > are provided.
> >
> > An example of the trace:
> >
> > echo syscall > /debugfs/tracing/current_tracer
> >
> >
> > # tracer: syscall
> > #
> > # TASK-PID CPU# TIMESTAMP FUNCTION
> > # | | | | |
> > <...>-5080 [001] 132.192228: sys_dup2(oldfd: a, newfd: 1)
> > <...>-5080 [001] 132.192239: sys_dup2 -> 0x1
> > <...>-5080 [001] 132.192242: sys_fcntl(fd: a, cmd: 1, arg: 0)
> > <...>-5080 [001] 132.192245: sys_fcntl -> 0x1
> > <...>-5080 [001] 132.192248: sys_close(fd: a)
> > <...>-5080 [001] 132.192250: sys_close -> 0x0
> > <...>-5080 [001] 132.192265: sys_rt_sigprocmask(how: 0, set: 0, oset: 6cf808, sigsetsize: 8)
> > <...>-5080 [001] 132.192267: sys_rt_sigprocmask -> 0x0
> > <...>-5080 [001] 132.192271: sys_rt_sigaction(sig: 2, act: 7fffff4338f0, oact: 7fffff433850, sigsetsize: 8)
> > <...>-5080 [001] 132.192273: sys_rt_sigaction -> 0x0
> > <...>-5080 [001] 132.192285: sys_rt_sigprocmask(how: 0, set: 0, oset: 6cf808, sigsetsize: 8)
> > <...>-5080 [001] 132.192287: sys_rt_sigprocmask -> 0x0
> > <...>-5080 [001] 132.192415: sys_write(fd: 1, buf: 15dfc08, count: 21)
> > <...>-5080 [001] 132.192436: sys_write -> 0x21
> > <...>-4754 [000] 132.192478: sys_read(fd: 8, buf: 2a9340e, count: 1fee)
> > <...>-5080 [001] 132.192487: sys_rt_sigprocmask(how: 0, set: 7fffff432a70, oset: 7fffff4329f0, sigsetsize: 8)
> >
> > And if you ask for the parameters types:
> >
> > echo syscall_arg_type > trace_options
> >
> > # tracer: syscall
> > #
> > # TASK-PID CPU# TIMESTAMP FUNCTION
> > # | | | | |
> > <...>-5080 [001] 132.192228: sys_dup2(unsigned int oldfd: a, unsigned int newfd: 1)
> > <...>-5080 [001] 132.192239: sys_dup2 -> 0x1
> > <...>-5080 [001] 132.192242: sys_fcntl(unsigned int fd: a, unsigned int cmd: 1, unsigned long arg: 0)
> > <...>-5080 [001] 132.192245: sys_fcntl -> 0x1
> > <...>-5080 [001] 132.192248: sys_close(unsigned int fd: a)
> > <...>-5080 [001] 132.192250: sys_close -> 0x0
> > <...>-5080 [001] 132.192265: sys_rt_sigprocmask(int how: 0, sigset_t * set: 0, sigset_t * oset: 6cf808, size_t sigsetsize: 8)
> > <...>-5080 [001] 132.192267: sys_rt_sigprocmask -> 0x0
> > <...>-5080 [001] 132.192271: sys_rt_sigaction(int sig: 2, const struct sigaction * act: 7fffff4338f0, struct sigaction * oact: 7fffff433850, size_t sigsetsize: 8)
> > <...>-5080 [001] 132.192273: sys_rt_sigaction -> 0x0
> > <...>-5080 [001] 132.192285: sys_rt_sigprocmask(int how: 0, sigset_t * set: 0, sigset_t * oset: 6cf808, size_t sigsetsize: 8)
> > <...>-5080 [001] 132.192287: sys_rt_sigprocmask -> 0x0
> > <...>-5080 [001] 132.192415: sys_write(unsigned int fd: 1, const char * buf: 15dfc08, size_t count: 21)
> > <...>-5080 [001] 132.192436: sys_write -> 0x21
> >
> > TODO:
> >
> > - add a single mask on the struct syscall_metadata to provide quickly which arguments is
> > a pointer (usually type __user *p) so that the user can decide if he wants to save them of tracing time
> >
> > - now that we have each parameter type as strings, add a new field on struct syscall_metadata to have the parameter types
> > encoded as single enum values (for quick checks) so that we can use specific callbacks for each parameter type
> > to be displayed.
> >
> > NOTE: this is still not overlapping with a potential future merge of utrace, since the low-level hooks on
> > the syscalls remain somewhat basic.
> >
> > NOTE2: I've only tested it on x86-64 for now, so only x86-64 support is provided.
> > --
> >
> > Frederic Weisbecker (2):
> > tracing/syscalls: core infrastructure for syscalls tracing
> > tracing/syscalls: support for syscalls tracing on x86-64
> >
> > arch/x86/Kconfig | 1 +
> > arch/x86/include/asm/ftrace.h | 7 +
> > arch/x86/include/asm/thread_info.h | 9 +-
> > arch/x86/kernel/ftrace.c | 63 +++++++++
> > arch/x86/kernel/ptrace.c | 7 +
> > include/asm-generic/vmlinux.lds.h | 11 ++-
> > include/linux/ftrace.h | 29 +++++
> > include/linux/syscalls.h | 60 +++++++++-
> > kernel/trace/Kconfig | 10 ++
> > kernel/trace/Makefile | 1 +
> > kernel/trace/trace.h | 19 +++
> > kernel/trace/trace_syscalls.c | 243 ++++++++++++++++++++++++++++++++++++
> > 12 files changed, 454 insertions(+), 6 deletions(-)
> > create mode 100644 kernel/trace/trace_syscalls.c
> >
>

--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68