linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH] perf: sample after exit loses thread correlation - v4
@ 2013-08-14 14:49 David Ahern
  2013-08-20 18:04 ` David Ahern
  2013-08-29 10:08 ` [tip:perf/core] perf tools: Sample after exit loses thread correlation tip-bot for David Ahern
  0 siblings, 2 replies; 3+ messages in thread
From: David Ahern @ 2013-08-14 14:49 UTC (permalink / raw)
  To: acme, linux-kernel
  Cc: David Ahern, Frederic Weisbecker, Ingo Molnar, Jiri Olsa,
	Mike Galbraith, Namhyung Kim, Peter Zijlstra, Stephane Eranian,
	Adrian Hunter

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 - a 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.

This patch address the problem by delaying the move to the dead_threads list
until the tid is re-used (per Adrian's suggestion).

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

v4: per Arnaldo's request add dead flag to thread struct and set when task exits

v3: re-do from a time based check to a delayed move to dead_threads list

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>
Acked-by: Adrian Hunter <adrian.hunter@intel.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>
Cc: Adrian Hunter <adrian.hunter@intel.com>
---
 tools/perf/util/machine.c |   34 ++++++++++++++++++++--------------
 tools/perf/util/thread.h  |    5 +++++
 2 files changed, 25 insertions(+), 14 deletions(-)

diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 4514e7e..574feb7 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -1031,11 +1031,27 @@ out_problem:
 	return 0;
 }
 
+static void machine__remove_thread(struct machine *machine, struct thread *th)
+{
+	machine->last_match = NULL;
+	rb_erase(&th->rb_node, &machine->threads);
+	/*
+	 * We may have references to this thread, for instance in some hist_entry
+	 * instances, so just move them to a separate list.
+	 */
+	list_add_tail(&th->node, &machine->dead_threads);
+}
+
 int machine__process_fork_event(struct machine *machine, union perf_event *event)
 {
-	struct thread *thread = machine__findnew_thread(machine, event->fork.tid);
+	struct thread *thread = machine__find_thread(machine, event->fork.tid);
 	struct thread *parent = machine__findnew_thread(machine, event->fork.ptid);
 
+	/* if a thread currently exists for the thread id remove it */
+	if (thread != NULL)
+		machine__remove_thread(machine, thread);
+
+	thread = machine__findnew_thread(machine, event->fork.tid);
 	if (dump_trace)
 		perf_event__fprintf_task(event, stdout);
 
@@ -1048,18 +1064,8 @@ int machine__process_fork_event(struct machine *machine, union perf_event *event
 	return 0;
 }
 
-static void machine__remove_thread(struct machine *machine, struct thread *th)
-{
-	machine->last_match = NULL;
-	rb_erase(&th->rb_node, &machine->threads);
-	/*
-	 * We may have references to this thread, for instance in some hist_entry
-	 * instances, so just move them to a separate list.
-	 */
-	list_add_tail(&th->node, &machine->dead_threads);
-}
-
-int machine__process_exit_event(struct machine *machine, union perf_event *event)
+int machine__process_exit_event(struct machine *machine __maybe_unused,
+				union perf_event *event)
 {
 	struct thread *thread = machine__find_thread(machine, event->fork.tid);
 
@@ -1067,7 +1073,7 @@ int machine__process_exit_event(struct machine *machine, union perf_event *event
 		perf_event__fprintf_task(event, stdout);
 
 	if (thread != NULL)
-		machine__remove_thread(machine, thread);
+		thread__exited(thread);
 
 	return 0;
 }
diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
index 13c62c9..32d0601 100644
--- a/tools/perf/util/thread.h
+++ b/tools/perf/util/thread.h
@@ -16,6 +16,7 @@ struct thread {
 	pid_t			ppid;
 	char			shortname[3];
 	bool			comm_set;
+	bool			dead; /* if set thread has exited */
 	char			*comm;
 	int			comm_len;
 
@@ -26,6 +27,10 @@ struct machine;
 
 struct thread *thread__new(pid_t tid);
 void thread__delete(struct thread *self);
+static inline void thread__exited(struct thread *thread)
+{
+	thread->dead = true;
+}
 
 int thread__set_comm(struct thread *self, const char *comm);
 int thread__comm_len(struct thread *self);
-- 
1.7.10.1


^ permalink raw reply related	[flat|nested] 3+ messages in thread

* Re: [PATCH] perf: sample after exit loses thread correlation - v4
  2013-08-14 14:49 [PATCH] perf: sample after exit loses thread correlation - v4 David Ahern
@ 2013-08-20 18:04 ` David Ahern
  2013-08-29 10:08 ` [tip:perf/core] perf tools: Sample after exit loses thread correlation tip-bot for David Ahern
  1 sibling, 0 replies; 3+ messages in thread
From: David Ahern @ 2013-08-20 18:04 UTC (permalink / raw)
  To: acme
  Cc: linux-kernel, Frederic Weisbecker, Ingo Molnar, Jiri Olsa,
	Mike Galbraith, Namhyung Kim, Peter Zijlstra, Stephane Eranian,
	Adrian Hunter

ping

On 8/14/13 8:49 AM, 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 - a 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.
>
> This patch address the problem by delaying the move to the dead_threads list
> until the tid is re-used (per Adrian's suggestion).
>
> 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
>
> v4: per Arnaldo's request add dead flag to thread struct and set when task exits
>
> v3: re-do from a time based check to a delayed move to dead_threads list
>
> 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>
> Acked-by: Adrian Hunter <adrian.hunter@intel.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>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> ---
>   tools/perf/util/machine.c |   34 ++++++++++++++++++++--------------
>   tools/perf/util/thread.h  |    5 +++++
>   2 files changed, 25 insertions(+), 14 deletions(-)
>
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 4514e7e..574feb7 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -1031,11 +1031,27 @@ out_problem:
>   	return 0;
>   }
>
> +static void machine__remove_thread(struct machine *machine, struct thread *th)
> +{
> +	machine->last_match = NULL;
> +	rb_erase(&th->rb_node, &machine->threads);
> +	/*
> +	 * We may have references to this thread, for instance in some hist_entry
> +	 * instances, so just move them to a separate list.
> +	 */
> +	list_add_tail(&th->node, &machine->dead_threads);
> +}
> +
>   int machine__process_fork_event(struct machine *machine, union perf_event *event)
>   {
> -	struct thread *thread = machine__findnew_thread(machine, event->fork.tid);
> +	struct thread *thread = machine__find_thread(machine, event->fork.tid);
>   	struct thread *parent = machine__findnew_thread(machine, event->fork.ptid);
>
> +	/* if a thread currently exists for the thread id remove it */
> +	if (thread != NULL)
> +		machine__remove_thread(machine, thread);
> +
> +	thread = machine__findnew_thread(machine, event->fork.tid);
>   	if (dump_trace)
>   		perf_event__fprintf_task(event, stdout);
>
> @@ -1048,18 +1064,8 @@ int machine__process_fork_event(struct machine *machine, union perf_event *event
>   	return 0;
>   }
>
> -static void machine__remove_thread(struct machine *machine, struct thread *th)
> -{
> -	machine->last_match = NULL;
> -	rb_erase(&th->rb_node, &machine->threads);
> -	/*
> -	 * We may have references to this thread, for instance in some hist_entry
> -	 * instances, so just move them to a separate list.
> -	 */
> -	list_add_tail(&th->node, &machine->dead_threads);
> -}
> -
> -int machine__process_exit_event(struct machine *machine, union perf_event *event)
> +int machine__process_exit_event(struct machine *machine __maybe_unused,
> +				union perf_event *event)
>   {
>   	struct thread *thread = machine__find_thread(machine, event->fork.tid);
>
> @@ -1067,7 +1073,7 @@ int machine__process_exit_event(struct machine *machine, union perf_event *event
>   		perf_event__fprintf_task(event, stdout);
>
>   	if (thread != NULL)
> -		machine__remove_thread(machine, thread);
> +		thread__exited(thread);
>
>   	return 0;
>   }
> diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
> index 13c62c9..32d0601 100644
> --- a/tools/perf/util/thread.h
> +++ b/tools/perf/util/thread.h
> @@ -16,6 +16,7 @@ struct thread {
>   	pid_t			ppid;
>   	char			shortname[3];
>   	bool			comm_set;
> +	bool			dead; /* if set thread has exited */
>   	char			*comm;
>   	int			comm_len;
>
> @@ -26,6 +27,10 @@ struct machine;
>
>   struct thread *thread__new(pid_t tid);
>   void thread__delete(struct thread *self);
> +static inline void thread__exited(struct thread *thread)
> +{
> +	thread->dead = true;
> +}
>
>   int thread__set_comm(struct thread *self, const char *comm);
>   int thread__comm_len(struct thread *self);
>


^ permalink raw reply	[flat|nested] 3+ messages in thread

* [tip:perf/core] perf tools: Sample after exit loses thread correlation
  2013-08-14 14:49 [PATCH] perf: sample after exit loses thread correlation - v4 David Ahern
  2013-08-20 18:04 ` David Ahern
@ 2013-08-29 10:08 ` tip-bot for David Ahern
  1 sibling, 0 replies; 3+ messages in thread
From: tip-bot for David Ahern @ 2013-08-29 10:08 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: acme, linux-kernel, eranian, hpa, mingo, peterz, efault, namhyung,
	jolsa, fweisbec, dsahern, adrian.hunter, tglx

Commit-ID:  236a3bbd5cb51edbf9550f5a7df885665d18a271
Gitweb:     http://git.kernel.org/tip/236a3bbd5cb51edbf9550f5a7df885665d18a271
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 14 Aug 2013 08:49:27 -0600
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Mon, 26 Aug 2013 17:25:36 -0300

perf tools: Sample after exit loses thread correlation

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 - a 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.

This patch address the problem by delaying the move to the dead_threads list
until the tid is re-used (per Adrian's suggestion).

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

v4: per Arnaldo's request add dead flag to thread struct and set when task exits

v3: re-do from a time based check to a delayed move to dead_threads list

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>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: Adrian Hunter <adrian.hunter@intel.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>
Link: http://lkml.kernel.org/r/1376491767-84171-1-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/machine.c | 34 ++++++++++++++++++++--------------
 tools/perf/util/thread.h  |  5 +++++
 2 files changed, 25 insertions(+), 14 deletions(-)

diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 4514e7e..574feb7 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -1031,11 +1031,27 @@ out_problem:
 	return 0;
 }
 
+static void machine__remove_thread(struct machine *machine, struct thread *th)
+{
+	machine->last_match = NULL;
+	rb_erase(&th->rb_node, &machine->threads);
+	/*
+	 * We may have references to this thread, for instance in some hist_entry
+	 * instances, so just move them to a separate list.
+	 */
+	list_add_tail(&th->node, &machine->dead_threads);
+}
+
 int machine__process_fork_event(struct machine *machine, union perf_event *event)
 {
-	struct thread *thread = machine__findnew_thread(machine, event->fork.tid);
+	struct thread *thread = machine__find_thread(machine, event->fork.tid);
 	struct thread *parent = machine__findnew_thread(machine, event->fork.ptid);
 
+	/* if a thread currently exists for the thread id remove it */
+	if (thread != NULL)
+		machine__remove_thread(machine, thread);
+
+	thread = machine__findnew_thread(machine, event->fork.tid);
 	if (dump_trace)
 		perf_event__fprintf_task(event, stdout);
 
@@ -1048,18 +1064,8 @@ int machine__process_fork_event(struct machine *machine, union perf_event *event
 	return 0;
 }
 
-static void machine__remove_thread(struct machine *machine, struct thread *th)
-{
-	machine->last_match = NULL;
-	rb_erase(&th->rb_node, &machine->threads);
-	/*
-	 * We may have references to this thread, for instance in some hist_entry
-	 * instances, so just move them to a separate list.
-	 */
-	list_add_tail(&th->node, &machine->dead_threads);
-}
-
-int machine__process_exit_event(struct machine *machine, union perf_event *event)
+int machine__process_exit_event(struct machine *machine __maybe_unused,
+				union perf_event *event)
 {
 	struct thread *thread = machine__find_thread(machine, event->fork.tid);
 
@@ -1067,7 +1073,7 @@ int machine__process_exit_event(struct machine *machine, union perf_event *event
 		perf_event__fprintf_task(event, stdout);
 
 	if (thread != NULL)
-		machine__remove_thread(machine, thread);
+		thread__exited(thread);
 
 	return 0;
 }
diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
index 13c62c9..32d0601 100644
--- a/tools/perf/util/thread.h
+++ b/tools/perf/util/thread.h
@@ -16,6 +16,7 @@ struct thread {
 	pid_t			ppid;
 	char			shortname[3];
 	bool			comm_set;
+	bool			dead; /* if set thread has exited */
 	char			*comm;
 	int			comm_len;
 
@@ -26,6 +27,10 @@ struct machine;
 
 struct thread *thread__new(pid_t tid);
 void thread__delete(struct thread *self);
+static inline void thread__exited(struct thread *thread)
+{
+	thread->dead = true;
+}
 
 int thread__set_comm(struct thread *self, const char *comm);
 int thread__comm_len(struct thread *self);

^ permalink raw reply related	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2013-08-29 10:09 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-08-14 14:49 [PATCH] perf: sample after exit loses thread correlation - v4 David Ahern
2013-08-20 18:04 ` David Ahern
2013-08-29 10:08 ` [tip:perf/core] perf tools: Sample after exit loses thread correlation tip-bot for David Ahern

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).