lkml.org 
[lkml]   [2013]   [Jul]   [29]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH] perf: sample after exit loses thread correlation
On 27/07/2013 1:04 a.m., David Ahern wrote:
> Occassionally events (e.g., context-switch, sched tracepoints) are losing
> the conversion of sample data associated with a thread. For example:
>
> $ perf record -e sched:sched_switch -c 1 -a -- sleep 5
> $ perf script
> <selected events shown>
> ls 30482 [000] 1379727.583037: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
> ls 30482 [000] 1379727.586339: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
> :30482 30482 [000] 1379727.589462: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
>
> The last line lost the conversion from tid to comm. If you look at the events
> (perf script -D) you see why - SAMPLE event is generated after the EXIT:
>
> 0 1379727589449774 0x1540b0 [0x38]: PERF_RECORD_EXIT(30482:30482):(30482:30482)
> 0 1379727589462497 0x1540e8 [0x80]: PERF_RECORD_SAMPLE(IP, 1): 30482/30482: 0xffffffff816416f1 period: 1 addr: 0
> .... thread: :30482:30482
>
> When perf processes the EXIT event the thread is moved to the dead_threads
> list. When the SAMPLE event is processed no thread exists for the pid so a new
> one is created by machine__findnew_thread.

In the case of per-cpu recording, it is normal for sample events to
occur after the EXIT event simply because the EXIT event is recorded
while the task is still running (in kernel). It is therefore a mistake
to move the thread to dead_threads just because of the EXIT event.

Instead the thread should be marked as exiting and not moved to
dead_threads until another thread starts on the same CPU. i.e. a comm,
mmap, fork event with the same tid and same CPU, or any event with a
different tid and same CPU.

>
> This patch addresses the problem by saving the exit time and checking the
> dead_threads list for the requested tid. If the time passed into
> machine_findnew_thread is non-0 the dead_threads list is walked looking for
> the tid. If the thread struct associated with the tid exited within 1 msec
> of the time passed in the thread is considered a match and returned.
>
> If samples do not contain timestamps then sample->time will be 0 and the
> dead_threads list will not be checked. -1 can be used to force always checking
> the dead_threads list and returning a match.
>
> With this patch we get the previous example shows:
>
> ls 30482 [000] 1379727.583037: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
> ls 30482 [000] 1379727.586339: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
> ls 30482 [000] 1379727.589462: sched:sched_switch: prev_comm=ls prev_pid=30482 ...
>
> and
>
> 0 1379727589449774 0x1540b0 [0x38]: PERF_RECORD_EXIT(30482:30482):(30482:30482)
> 0 1379727589462497 0x1540e8 [0x80]: PERF_RECORD_SAMPLE(IP, 1): 30482/30482: 0xffffffff816416f1 period: 1 addr: 0
> .... thread: ls:30482
>
> v2: Rebased to latest perf/core branch. Changed time comparison to use
> a macro which explicitly shows the time basis
>
> Signed-off-by: David Ahern<dsahern@gmail.com>
> Cc: Frederic Weisbecker<fweisbec@gmail.com>
> Cc: Ingo Molnar<mingo@kernel.org>
> Cc: Jiri Olsa<jolsa@redhat.com>
> Cc: Mike Galbraith<efault@gmx.de>
> Cc: Namhyung Kim<namhyung@kernel.org>
> Cc: Peter Zijlstra<peterz@infradead.org>
> Cc: Stephane Eranian<eranian@google.com>
> ---
> tools/perf/builtin-inject.c | 2 +-
> tools/perf/builtin-kmem.c | 3 +--
> tools/perf/builtin-kvm.c | 2 +-
> tools/perf/builtin-lock.c | 2 +-
> tools/perf/builtin-sched.c | 16 +++++++--------
> tools/perf/builtin-script.c | 2 +-
> tools/perf/builtin-trace.c | 6 +++---
> tools/perf/perf.h | 3 +++
> tools/perf/tests/hists_link.c | 2 +-
> tools/perf/util/build-id.c | 9 ++++-----
> tools/perf/util/event.c | 10 ++++++++--
> tools/perf/util/machine.c | 44 ++++++++++++++++++++++++++++++-----------
> tools/perf/util/machine.h | 6 ++++--
> tools/perf/util/session.c | 2 +-
> tools/perf/util/thread.h | 2 +-
> 15 files changed, 71 insertions(+), 40 deletions(-)


\
 
 \ /
  Last update: 2013-07-29 12:41    [W:0.052 / U:2.976 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site