perf trace: Do not print from time delta for interrupted syscall lines
authorArnaldo Carvalho de Melo <acme@redhat.com>
Mon, 22 Jan 2018 14:42:11 +0000 (11:42 -0300)
committerArnaldo Carvalho de Melo <acme@redhat.com>
Thu, 25 Jan 2018 09:37:29 +0000 (06:37 -0300)
commit522283fec7d3f312224360da48057e923ee22765
tree65befc7c681e95faf296bbc18f3e2af024a39ca8
parent591421e151ddf95e43d690a5c9b291d8e1cb8065
perf trace: Do not print from time delta for interrupted syscall lines

We were calculating the delta from a in-flight syscall that got its
output interrupted by another syscall, which doesn't seem like useful
information, we will print the syscall duration (sys_exit - sys_enter)
when the raw_syscalls:sys_exit event happens.

The problem here is how we're consuming the multiple ring buffers,
without using the ordered_events code used by perf_session, which may
cause some reordering of syscalls for diferent CPUs, so just stop
printing that delta, to avoid things like:

  # trace --print-sample -p 9626 -e futex
  raw_syscalls:sys_enter 411967179.269 Timer 9609/9626 [2]
  raw_syscalls:sys_enter 411967179.213 file:// Content 9609/9609 [3]
     328.038 (18446744073709.496 ms): Timer/9626 futex(uaddr: 0x7fc0d4027044, op: WAIT|PRIV, utime: 0x7fc0b0ffdb50     ) ...
   raw_syscalls:sys_exit 411967179.225 file:// Content 9609/9609 [3]
     327.982 ( 0.012 ms): file:// Conten/9609 futex(uaddr: 0x7fc0d4027040, op: WAKE|PRIV, val: 1                    ) = 1

This is a bandaid, we should better try and use the ordered_events code,
possibly with some refactoring prep work, but for now at least we don't
show those false long deltas for the lines ending in '...'.

Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Wang Nan <wangnan0@huawei.com>
Link: https://lkml.kernel.org/n/tip-q6xgsqrju1sr6ltud9kjjhmb@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
tools/perf/builtin-trace.c