Commit 236a3bbd authored Aug 14, 2013 by David Ahern Committed by Arnaldo Carvalho de Melo Aug 26, 2013

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>

parent ac9be8ee

tools/perf/util/machine.c

+20 −14

Original line number	Diff line number	Diff line
		@@ -1031,11 +1031,27 @@ int machine__process_mmap_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_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;
		}

tools/perf/util/thread.h

+5 −0

Original line number	Diff line number	Diff line
		@@ -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);