perf: sample after exit loses thread correlation - v3
PATCH 1/1 perf: sample after exit loses thread correlation - v3
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.
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
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
--- tools/perf/util/machine.c | 37 +++++++++++++++++++------------------ 1 file changed, 19 insertions(+), 18 deletions(-)
tools/perf/util/machine.c +19 -18
@@ -994,11 +994,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);
@@ -1011,27 +1027,12 @@ int machine__process_fork_event(struct machine *machine, union perf_event *eventreturn 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); -if (dump_trace)perf_event__fprintf_task (event, stdout); -if (thread !=NULL ) -machine__remove_thread (machine, thread); -return 0 ; }
Signature · 1 line
1.7.10.1
Quoted 50 lines · David Ahern
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 13797275894624970x1540e8[0x80]:PERF_RECORD_SAMPLE(IP, 1): 30482/30482:0xffffffff816416f1period: 1 addr: 0 ... thread: :30482:30482When perf processes the EXIT event the thread is moved to the
dead_threadslist. When the SAMPLE event is processed no thread exists for the pid so a new one is created bymachine__findnew_thread.This patch address the problem by delaying the move to the
dead_threadslist 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 13797275894624970x1540e8[0x80]:PERF_RECORD_SAMPLE(IP, 1): 30482/30482:0xffffffff816416f1period: 1 addr: 0 ... thread: ls:30482v3: re-do from a time based check to a delayed move to
dead_threadslistv2: Rebased to latest perf/core branch. Changed time comparison to use
a macro which explicitly shows the time basisSigned-off-by David Ahern <[email protected]>Cc Frederic Weisbecker <[email protected]>Cc Ingo Molnar <[email protected]>Cc Jiri Olsa <[email protected]>Cc Mike Galbraith <[email protected]>Cc Namhyung Kim <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Stephane Eranian <[email protected]>Cc Adrian Hunter <[email protected]>
Quoted 1 line
---
This has the side-effect of leaving more threads on machine->threads, which seems OK to me. So:
Quoted 67 lines
tools/perf/util/machine.c | 37 +++++++++++++++++++------------------ 1 file changed, 19 insertions(+), 18 deletions(-)tools/perf/util/machine.c +19
-18@@ -994,11 +994,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);@@ -1011,27 +1027,12 @@ int machine__process_fork_event(struct machine *machine, union perf_event *eventreturn 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); -if (dump_trace)perf_event__fprintf_task (event, stdout); -if (thread !=NULL ) -machine__remove_thread (machine, thread); -return 0 ; }