perf trace: Handle multiple threads better wrt syscalls being intermixed

 $ trace time taskset -c 0 usleep 1
   0.845 ( 0.021 ms): time/16722 wait4(upid: 4294967295, stat_addr: 0x7fff17f443d4, ru: 0x7fff17f44438 ) ...
   0.865 ( 0.008 ms): time/16723 execve(arg0: 140733595272004, arg1: 140733595272720, arg2: 140733595272768, arg3: 139755107218496, arg4: 7307199665339051828, arg5: 3) = -2
   2.395 ( 1.523 ms): taskset/16723 execve(arg0: 140733595272013, arg1: 140733595272720, arg2: 140733595272768, arg3: 139755107218496, arg4: 7307199665339051828, arg5: 3) = 0
   2.411 ( 0.002 ms): taskset/16723 brk(                                                                  ) = 0x1915000
   3.300 ( 0.058 ms): usleep/16723 nanosleep(rqtp: 0x7ffff4ada190                                        ) = 0
 <SNIP>
   3.305 ( 0.000 ms): usleep/16723 exit_group(
   3.363 ( 2.539 ms): time/16722  ... [continued]: wait4()) = 16723
   3.366 ( 0.001 ms): time/16722 rt_sigaction(sig: INT, act: 0x7fff17f44160, oact: 0x7fff17f44200, sigsetsize: 8) = 0

We we're not seeing this line:

  0.845 ( 0.021 ms): time/16722 wait4(upid: 4294967295, stat_addr: 0x7fff17f443d4, ru: 0x7fff17f44438 ) ...

just the one when it finishes:

  3.363 ( 2.539 ms): time/16722  ... [continued]: wait4()) = 16723

Still some issues left till we move to ordered_samples when multiple
CPUs/threads are involved...

Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Borislav Petkov <bp@suse.de>
Cc: David Ahern <dsahern@gmail.com>
Cc: Don Zickus <dzickus@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-zq9x30a1ky3djqewqn2v3ja3@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 2bfb2343b7987378fd64b6e780fdef3f14615b4f..feabd08ec90dcc7f9e357ba0c9037f03a9571e0e 100644 (file)
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -1220,6 +1220,7 @@ struct trace {
        } syscalls;
        struct record_opts      opts;
        struct machine          *host;
+       struct thread           *current;
        u64                     base_time;
        FILE                    *output;
        unsigned long           nr_events;
@@ -1642,6 +1643,29 @@ static void thread__update_stats(struct thread_trace *ttrace,
        update_stats(stats, duration);
 }
 
+static int trace__printf_interrupted_entry(struct trace *trace, struct perf_sample *sample)
+{
+       struct thread_trace *ttrace;
+       u64 duration;
+       size_t printed;
+
+       if (trace->current == NULL)
+               return 0;
+
+       ttrace = thread__priv(trace->current);
+
+       if (!ttrace->entry_pending)
+               return 0;
+
+       duration = sample->time - ttrace->entry_time;
+
+       printed  = trace__fprintf_entry_head(trace, trace->current, duration, sample->time, trace->output);
+       printed += fprintf(trace->output, "%-70s) ...\n", ttrace->entry_str);
+       ttrace->entry_pending = false;
+
+       return printed;
+}
+
 static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
                            union perf_event *event __maybe_unused,
                            struct perf_sample *sample)
@@ -1673,6 +1697,8 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
                        return -1;
        }
 
+       printed += trace__printf_interrupted_entry(trace, sample);
+
        ttrace->entry_time = sample->time;
        msg = ttrace->entry_str;
        printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
@@ -1688,6 +1714,8 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
        } else
                ttrace->entry_pending = true;
 
+       trace->current = thread;
+
        return 0;
 }