[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <CAH0uvoj_2An0QQgCSenZiK8XubS=amyrxhAWK7ragAFfi+Hnqg@mail.gmail.com>
Date: Mon, 23 Sep 2024 10:42:53 -0700
From: Howard Chu <howardchu95@...il.com>
To: Arnaldo Carvalho de Melo <acme@...nel.org>
Cc: Adrian Hunter <adrian.hunter@...el.com>, Alan Maguire <alan.maguire@...cle.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,
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.
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:~#
Powered by blists - more mailing lists