mirror of
https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git
synced 2024-09-06 02:50:43 +00:00
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>
This commit is contained in:
parent
42052bea16
commit
e596663ebb
1 changed files with 28 additions and 0 deletions
|
@ -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;
|
||||
}
|
||||
|
||||
|
|
Loading…
Reference in a new issue