Re: perf trace: substruct BTF based pretty printing

[Howard Chu]

Hello Arnaldo,

On Wed, Sep 11, 2024 at 1:25 PM Arnaldo Carvalho de Melo
<acme@xxxxxxxxxx> wrote:
>
> Hi Howard,
>
>         Not really a requirement on you to do work, just a some notes to
> add to our discussion/experiment on using BTF to pretty print syscall
> (and tracepoints/whatever) arguments:
>
> root@number:~# perf trace -e setitimer -p 5444 |& head -5
>      0.000 ( 0.017 ms): Xwayland/5444 setitimer(value: (struct __kernel_old_itimerval){})                   = 0
>      0.050 ( 0.004 ms): Xwayland/5444 setitimer(value: (struct __kernel_old_itimerval){})                   = 0
>      0.142 ( 0.005 ms): Xwayland/5444 setitimer(value: (struct __kernel_old_itimerval){})                   = 0
>      0.174 ( 0.004 ms): Xwayland/5444 setitimer(value: (struct __kernel_old_itimerval){})                   = 0
>      0.293 ( 0.004 ms): Xwayland/5444 setitimer(value: (struct __kernel_old_itimerval){})                   = 0

First glance, yes this is a substruct, but we should be able to
collect those substruct data in BPF, since it is substruct, not
substruct pointer. It seems to be the same -p problem we discussed
here:

Before:
```
perf $ perf trace -e open -p 3792392
         ? (         ):  ... [continued]: open())
                       = -1 ENOENT (No such file or directory)
         ? (         ):  ... [continued]: open())
                       = -1 ENOENT (No such file or directory)
```

We can see there's no output.

After:
```
perf $ perf trace -e open -p 3792392
     0.000 ( 0.123 ms): a.out/3792392 open(filename: "DINGZHEN",
flags: WRONLY)                             = -1 ENOENT (No such file
or directory)
  1000.398 ( 0.116 ms): a.out/3792392 open(filename: "DINGZHEN",
flags: WRONLY)                             = -1 ENOENT (No such file
or directory)
```

I will test and fix it later.

Thanks,
Howard

> root@number:~# strace -e setitimer -p 5444 |& head -5
> strace: Process 5444 attached
> setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=5000}, it_value={tv_sec=0, tv_usec=5000}}, NULL) = 0
> setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, NULL) = 0
> setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=5000}, it_value={tv_sec=0, tv_usec=5000}}, NULL) = 0
> setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, NULL) = 0
> root@number:~#
> root@number:~#
> root@number:~# grep -w value /sys/kernel/tracing/events/syscalls/sys_enter_rseq/format
> root@number:~# grep -w value /sys/kernel/tracing/events/syscalls/sys_enter_setitimer/format
>         field:struct __kernel_old_itimerval * value;    offset:24;      size:8; signed:0;
> print fmt: "which: 0x%08lx, value: 0x%08lx, ovalue: 0x%08lx", ((unsigned long)(REC->which)), ((unsigned long)(REC->value)), ((unsigned long)(REC->ovalue))
> root@number:~# pahole __kernel_old_itimerval
> struct __kernel_old_itimerval {
>         struct __kernel_old_timeval it_interval;         /*     0    16 */
>         struct __kernel_old_timeval it_value;            /*    16    16 */
>
>         /* size: 32, cachelines: 1, members: 2 */
>         /* last cacheline: 32 bytes */
> };
>
> root@number:~# pahole -E __kernel_old_itimerval
> struct __kernel_old_itimerval {
>         struct __kernel_old_timeval {
>                 /* typedef __kernel_long_t */ long int           tv_sec;                 /*     0     8 */
>                 /* typedef __kernel_long_t */ long int           tv_usec;                /*     8     8 */
>         } it_interval; /*     0    16 */
>         struct __kernel_old_timeval {
>                 /* typedef __kernel_long_t */ long int           tv_sec;                 /*    16     8 */
>                 /* typedef __kernel_long_t */ long int           tv_usec;                /*    24     8 */
>         } it_value; /*    16    16 */
>
>         /* size: 32, cachelines: 1, members: 2 */
>         /* last cacheline: 32 bytes */
> };
>
> root@number:~#