• Arnaldo Carvalho de Melo's avatar
    perf trace: Collect sys_nanosleep first argument · a9f4c6c9
    Arnaldo Carvalho de Melo authored
    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_nsec: 10000000 })                   = 0
          38.924 (10.077 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         100.177 (10.107 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         139.171 (10.063 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         200.603 (10.105 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         239.399 (10.064 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         300.994 (10.096 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         339.584 (10.067 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         401.335 (10.057 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         439.758 (10.166 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         501.814 (10.110 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         539.983 (10.227 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         602.284 (10.199 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         640.208 (10.105 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         702.662 (10.163 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         740.440 (10.107 ms): podman/2195174 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 0
         802.993 (10.159 ms): podman/9150 nanosleep(rqtp: { .tv_sec: 0, .tv_nsec: 10000000 })                   = 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=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
      nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 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=false
      root@number:~# perf config trace.show_duration=false
      root@number:~# perf config trace.show_timestamp=false
      root@number:~# perf config trace.show_zeros=true
      root@number:~# perf config trace.args_alignment=0
      root@number:~# perf trace -e nanosleep --max-events=10
      podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/2195174 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      podman/9150 nanosleep({ .tv_sec: 0, .tv_nsec: 10000000 }, NULL) = 0
      root@number:~#
      root@number:~# perf config
      trace.show_arg_names=false
      trace.show_duration=false
      trace.show_timestamp=false
      trace.show_zeros=true
      trace.args_alignment=0
      root@number:~# cat ~/.perfconfig
      # this file is auto-generated.
      [trace]
      	show_arg_names = false
      	show_duration = false
      	show_timestamp = false
      	show_zeros = true
      	args_alignment = 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_enter_*/format | grep offset:16
      /sys/kernel/tracing/events/syscalls/sys_enter_nanosleep/format:	field: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.
    Reviewed-by: default avatarIan Rogers <irogers@google.com>
    Cc: Adrian Hunter <adrian.hunter@intel.com>
    Cc: Jiri Olsa <jolsa@kernel.org>
    Cc: Namhyung Kim <namhyung@kernel.org>
    Link: https://lore.kernel.org/lkml/Zbq72dJRpOlfRWnf@kernel.org/Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
    a9f4c6c9
builtin-trace.c 145 KB