linux-kernel - Re: perf trace: substruct BTF based pretty printing

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <CAH0uvohqECsYgCkJKop6ubv3iOpRGEUyj7=LXLfJobisdMKfcw@mail.gmail.com>
Date: Mon, 23 Sep 2024 11:17:47 -0700
From: Howard Chu <howardchu95@...il.com>
To: Alan Maguire <alan.maguire@...cle.com>
Cc: Arnaldo Carvalho de Melo <acme@...nel.org>, Adrian Hunter <adrian.hunter@...el.com>, 
	Jiri Olsa <jolsa@...nel.org>, Kan Liang <kan.liang@...ux.intel.com>, 
	Namhyung Kim <namhyung@...nel.org>, 
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>, linux-perf-users@...r.kernel.org
Subject: Re: perf trace: substruct BTF based pretty printing

Hello Alan,

On Mon, Sep 23, 2024 at 10:48 AM Alan Maguire <alan.maguire@...cle.com> wrote:
>
> On 23/09/2024 18:42, Howard Chu wrote:
> > Hello,
> >
> > On Wed, Sep 11, 2024 at 6:29 PM Howard Chu <howardchu95@...il.com> wrote:
> >>
> >> Hello Arnaldo,
> >>
> >> On Wed, Sep 11, 2024 at 1:25 PM Arnaldo Carvalho de Melo
> >> <acme@...nel.org> 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@...ber:~# 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 of all I bypass the from_user check to make perf trace use BTF
> > output instead of just printing an address:
> >
> >         for (i = 0, field = sc->args; field; ++i, field = field->next) {
> >                 // XXX We're only collecting pointer payloads _from_ user space
> >                 /*if (!sc->arg_fmt[i].from_user)*/
> >                         /*continue;*/
> >
> > Got the bad output:
> >
> >    500.218 ( 0.015 ms): a.out/112335 setitimer(value: (struct
> > __kernel_old_itimerval){})                   = 0
> >
> > But after switching on emit_zeroes from btf_dump_type_data_opts:
> >
> > dump_data_opts.compact   = true;
> > dump_data_opts.skip_names = !arg->trace->show_arg_names;
> > dump_data_opts.emit_zeroes = true; // this
> >
> > My output is good:
> >
> >  96058.828 ( 0.010 ms): a.out/104347 setitimer(value: (struct
> > __kernel_old_itimerval){.it_interval = (struct
> > __kernel_old_timeval){.tv_sec = (__kernel_long_t)0,.tv_usec =
> > (__kernel_long_t)500000,},.it_value = (struct
> > __kernel_old_timeval){.tv_sec = (__kernel_long_t)0,.tv_usec =
> > (__kernel_long_t)500000,},}) = 0
> >
> > So I think this is btf_dump's problem... Because most of the time we
> > want to omit the zeroes, but that will have the side effect of not
> > being able to print the whole output. I'll figure something out.
> >
>
> One thing we could think about is if there's a way for BTF data dump to
> better represent the fact that a structure is all 0s; currently we will
> show "{}" since we skip emitting zeroed data, but maybe - at the
> toplevel only - "{ 0 }" would be more expressive? Thanks!

I think if the struct is filled with 0, showing "{ 0 }" is a really good idea.

Thanks,
Howard
>
> Alan
>
> > Thanks,
> > Howard
> >>
> >> 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@...ber:~# 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@...ber:~#
> >>> root@...ber:~#
> >>> root@...ber:~# grep -w value /sys/kernel/tracing/events/syscalls/sys_enter_rseq/format
> >>> root@...ber:~# 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@...ber:~# 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@...ber:~# 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@...ber:~#
>