Commit ecf1e225 authored Oct 18, 2016 by Arnaldo Carvalho de Melo

perf trace: Use the syscall raw_syscalls:sys_enter timestamp

Instead of the one when another syscall takes place while another is being
processed (in another CPU, but we show it serialized, so need to "interrupt"
the other), and also when finally showing the sys_enter + sys_exit + duration,
where we were showing the sample->time for the sys_exit, duh.

Before:

  # perf trace sleep 1
  <SNIP>
     0.373 (   0.001 ms): close(fd: 3                   ) = 0
  1000.626 (1000.211 ms): nanosleep(rqtp: 0x7ffd6ddddfb0) = 0
  1000.653 (   0.003 ms): close(fd: 1                   ) = 0
  1000.657 (   0.002 ms): close(fd: 2                   ) = 0
  1000.667 (   0.000 ms): exit_group(                   )
  #

After:

  # perf trace sleep 1
  <SNIP>
     0.336 (   0.001 ms): close(fd: 3                   ) = 0
     0.373 (1000.086 ms): nanosleep(rqtp: 0x7ffe303e9550) = 0
  1000.481 (   0.002 ms): close(fd: 1                   ) = 0
  1000.485 (   0.001 ms): close(fd: 2                   ) = 0
  1000.494 (   0.000 ms): exit_group(                   )
[root@jouet linux]#

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: http://lkml.kernel.org/n/tip-ecbzgmu2ni6glc6zkw8p1zmx@git.kernel.org


Fixes: 752fde44 ("perf trace: Support interrupted syscalls")
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

parent 1f369460

tools/perf/builtin-trace.c

+3 −3

Original line number	Diff line number	Diff line
		@@ -1451,7 +1451,7 @@ static int trace__printf_interrupted_entry(struct trace *trace, struct perf_samp

		duration = sample->time - ttrace->entry_time;

		printed = trace__fprintf_entry_head(trace, trace->current, duration, sample->time, trace->output);
		printed = trace__fprintf_entry_head(trace, trace->current, duration, ttrace->entry_time, trace->output);
		printed += fprintf(trace->output, "%-70s) ...\n", ttrace->entry_str);
		ttrace->entry_pending = false;

		@@ -1498,7 +1498,7 @@ static int trace__sys_enter(struct trace trace, struct perf_evsel evsel,

		if (sc->is_exit) {
		if (!(trace->duration_filter \|\| trace->summary_only \|\| trace->min_stack)) {
		trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
		trace__fprintf_entry_head(trace, thread, 1, ttrace->entry_time, trace->output);
		fprintf(trace->output, "%-70s)\n", ttrace->entry_str);
		}
		} else {
		@@ -1589,7 +1589,7 @@ static int trace__sys_exit(struct trace trace, struct perf_evsel evsel,
		if (trace->summary_only)
		goto out;

		trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output);
		trace__fprintf_entry_head(trace, thread, duration, ttrace->entry_time, trace->output);

		if (ttrace->entry_pending) {
		fprintf(trace->output, "%-70s", ttrace->entry_str);