Received-SPF: pass (google.com: domain of linux-kernel+bounces-75174-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) client-ip=147.75.199.223;
Precedence: bulk
MIME-Version: 1.0
References: <ZdYtJs8nWt6ALprh@x1>
In-Reply-To: <ZdYtJs8nWt6ALprh@x1>
From: Ian Rogers <irogers@google.com>
Date: Wed, 21 Feb 2024 09:15:01 -0800
Message-ID: <CAP-5=fXQPEe4KSQHs421kiUa7Ttr-WqtPtcdju2WRi6rdKy4rw@mail.gmail.com>
Subject: Re: [PATCH 1/1] perf trace: Collect sys_nanosleep first argument
To: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>, Adrian Hunter <adrian.hunter@intel.com>, 
	Jiri Olsa <jolsa@kernel.org>, Linux Kernel Mailing List <linux-kernel@vger.kernel.org>, 
	linux-perf-users@vger.kernel.org
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Wed, Feb 21, 2024 at 9:04=E2=80=AFAM Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>
> That is a 'struct timespec' passed from userspace to the kernel as we
> can see with a system wide syscall tracing:
>
>   root@number:~# perf trace -e nanosleep
>        0.000 (10.102 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>       38.924 (10.077 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      100.177 (10.107 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      139.171 (10.063 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      200.603 (10.105 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      239.399 (10.064 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      300.994 (10.096 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      339.584 (10.067 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      401.335 (10.057 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      439.758 (10.166 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      501.814 (10.110 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      539.983 (10.227 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      602.284 (10.199 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      640.208 (10.105 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      702.662 (10.163 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>      740.440 (10.107 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .t=
v_nsec: 10000000 })                   =3D 0
>      802.993 (10.159 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_n=
sec: 10000000 })                   =3D 0
>   ^Croot@number:~# strace -p 9150 -e nanosleep
>
> If we then use the ptrace method to look at that podman process:
>
>   root@number:~# strace -p 9150 -e nanosleep
>   strace: Process 9150 attached
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   nanosleep({tv_sec=3D0, tv_nsec=3D10000000}, NULL) =3D 0
>   ^Cstrace: Process 9150 detached
>   root@number:~#
>
> With some changes we can get something closer to the strace output,
> still in system wide mode:
>
>   root@number:~# perf config trace.show_arg_names=3Dfalse
>   root@number:~# perf config trace.show_duration=3Dfalse
>   root@number:~# perf config trace.show_timestamp=3Dfalse
>   root@number:~# perf config trace.show_zeros=3Dtrue
>   root@number:~# perf config trace.args_alignment=3D0
>   root@number:~# perf trace -e nanosleep --max-events=3D10
>   podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D =
0
>   podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D 0
>   podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D =
0
>   podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D 0
>   podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D =
0
>   podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D 0
>   podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D =
0
>   podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D 0
>   podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D =
0
>   podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) =3D 0
>   root@number:~#
>   root@number:~# perf config
>   trace.show_arg_names=3Dfalse
>   trace.show_duration=3Dfalse
>   trace.show_timestamp=3Dfalse
>   trace.show_zeros=3Dtrue
>   trace.args_alignment=3D0
>   root@number:~# cat ~/.perfconfig
>   # this file is auto-generated.
>   [trace]
>         show_arg_names =3D false
>         show_duration =3D false
>         show_timestamp =3D false
>         show_zeros =3D true
>         args_alignment =3D 0
>   root@number:~#
>
> This will not get reused by any other syscall as nanosleep is the only
> one to have as its first argument a 'struct timespec" pointer argument
> passed from userspace to the kernel:
>
>   root@number:~# grep timespec /sys/kernel/tracing/events/syscalls/sys_en=
ter_*/format | grep offset:16
>   /sys/kernel/tracing/events/syscalls/sys_enter_nanosleep/format:       f=
ield:struct __kernel_timespec * rqtp;  offset:16;      size:8; signed:0;
>   root@number:~#
>
> BTF based pretty printing will simplify all this, but then lets just get
> the low hanging fruits first.
>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> Cc: Ian Rogers <irogers@google.com>
> Cc: Jiri Olsa <jolsa@kernel.org>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

v2? https://lore.kernel.org/lkml/Zbq72dJRpOlfRWnf@kernel.org/

Thanks,
Ian