[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <8ad3ada6-f719-43ca-bf16-0095be555302@oracle.com>
Date: Mon, 23 Sep 2024 18:47:54 +0100
From: Alan Maguire <alan.maguire@...cle.com>
To: Howard Chu <howardchu95@...il.com>,
Arnaldo Carvalho de Melo <acme@...nel.org>
Cc: 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
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!
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:~#
Powered by blists - more mailing lists