perf: sample after exit loses thread correlation
PATCH 1/1 perf: 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 - 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 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
--- 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(-)
tools/perf/builtin-inject.c +1 -1
@@ -198,7 +198,7 @@ static int perf_event__inject_buildid(struct perf_tool *tool, cpumode = event->header.misc &PERF_RECORD_MISC_CPUMODE_MASK ; - thread =machine__findnew_thread (machine, event->ip.pid); + thread =machine__findnew_thread (machine, event->ip.pid, sample->time);if (thread ==NULL ) {pr_err ("problem processing %d event, skipping it.\n" , event->header.type);
tools/perf/builtin-kmem.c +1 -2
@@ -305,8 +305,7 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,struct perf_evsel *evsel, struct machine *machine) { - struct thread *thread = machine__findnew_thread(machine, event->ip.pid); - + struct thread *thread = machine__findnew_thread(machine, event->ip.pid, sample->time);if (thread ==NULL ) {pr_debug ("problem processing %d event, skipping it.\n" , event->header.type);
tools/perf/builtin-kvm.c +1 -1
@@ -691,7 +691,7 @@ static int process_sample_event(struct perf_tool *tool,struct perf_evsel *evsel, struct machine *machine) { - struct thread *thread = machine__findnew_thread(machine, sample->tid); + struct thread *thread = machine__findnew_thread(machine, sample->tid, sample->time); struct perf_kvm_stat *kvm = container_of(tool, struct perf_kvm_stat, tool);
tools/perf/builtin-lock.c +1 -1
@@ -805,7 +805,7 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,struct perf_evsel *evsel, struct machine *machine) { - struct thread *thread = machine__findnew_thread(machine, sample->tid); + struct thread *thread = machine__findnew_thread(machine, sample->tid, sample->time);if (thread ==NULL ) { pr_debug("problem processing %d event, skipping it.\n",
tools/perf/builtin-sched.c +8 -8
@@ -934,8 +934,8 @@ static int latency_switch_event(struct perf_sched *sched,return -1 ; } - sched_out =machine__findnew_thread (machine, prev_pid); - sched_in =machine__findnew_thread (machine, next_pid); + sched_out =machine__findnew_thread (machine, prev_pid, timestamp); + sched_in =machine__findnew_thread (machine, next_pid, timestamp); out_events =thread_atoms_search (&sched->atom_root, sched_out, &sched->cmp_pid);if (!out_events) {
@@ -978,7 +978,7 @@ static int latency_runtime_event(struct perf_sched *sched, {const u32 pid =perf_evsel__intval (evsel, sample,"pid" );const u64 runtime =perf_evsel__intval (evsel, sample,"runtime" ); -struct thread *thread =machine__findnew_thread (machine, pid); +struct thread *thread =machine__findnew_thread (machine, pid, sample->time);struct work_atoms *atoms =thread_atoms_search (&sched->atom_root, thread, &sched->cmp_pid);u64 timestamp = sample->time;int cpu = sample->cpu;
@@ -1016,7 +1016,7 @@ static int latency_wakeup_event(struct perf_sched *sched,if (!success)return 0 ; - wakee =machine__findnew_thread (machine, pid); + wakee =machine__findnew_thread (machine, pid, timestamp); atoms =thread_atoms_search (&sched->atom_root, wakee, &sched->cmp_pid);if (!atoms) {if (thread_atoms_insert (sched, wakee))
@@ -1070,7 +1070,7 @@ static int latency_migrate_task_event(struct perf_sched *sched,if (sched->profile_cpu ==-1 )return 0 ; - migrant =machine__findnew_thread (machine, pid); + migrant =machine__findnew_thread (machine, pid, timestamp); atoms =thread_atoms_search (&sched->atom_root, migrant, &sched->cmp_pid);if (!atoms) {if (thread_atoms_insert (sched, migrant))
@@ -1289,8 +1289,8 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,return -1 ; } - sched_out =machine__findnew_thread (machine, prev_pid); - sched_in =machine__findnew_thread (machine, next_pid); + sched_out =machine__findnew_thread (machine, prev_pid, timestamp); + sched_in =machine__findnew_thread (machine, next_pid, timestamp); sched->curr_thread[this_cpu] = sched_in;
@@ -1425,7 +1425,7 @@ static int perf_sched__process_tracepoint_sample(struct perf_tool *tool __maybe_struct perf_evsel *evsel, struct machine *machine) { - struct thread *thread = machine__findnew_thread(machine, sample->tid); + struct thread *thread = machine__findnew_thread(machine, sample->tid, sample->time);int err =0 ;if (thread ==NULL ) {
tools/perf/builtin-script.c +1 -1
@@ -480,7 +480,7 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused, struct machine *machine) {struct addr_location al; -struct thread *thread =machine__findnew_thread (machine, event->ip.tid); +struct thread *thread =machine__findnew_thread (machine, event->ip.tid, sample->time);if (thread ==NULL ) { pr_debug("problem processing %d event, skipping it.\n",
tools/perf/builtin-trace.c +3 -3
@@ -301,7 +301,7 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,char *msg;void *args;size_t printed =0 ; -struct thread *thread =machine__findnew_thread (&trace->host, sample->tid); +struct thread *thread =machine__findnew_thread (&trace->host, sample->tid, sample->time);struct syscall *sc =trace__syscall_info (trace, evsel, sample);struct thread_trace *ttrace =thread__trace (thread);
@@ -344,7 +344,7 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel, {int ret;u64 duration =0 ; -struct thread *thread =machine__findnew_thread (&trace->host, sample->tid); +struct thread *thread =machine__findnew_thread (&trace->host, sample->tid, sample->time);struct thread_trace *ttrace =thread__trace (thread);struct syscall *sc =trace__syscall_info (trace, evsel, sample);
@@ -397,7 +397,7 @@ static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evs {u64 runtime =perf_evsel__intval (evsel, sample,"runtime" );double runtime_ms = (double )runtime /NSEC_PER_MSEC ; -struct thread *thread =machine__findnew_thread (&trace->host, sample->tid); +struct thread *thread =machine__findnew_thread (&trace->host, sample->tid, sample->time);struct thread_trace *ttrace =thread__trace (thread);if (ttrace ==NULL )
tools/perf/perf.h +3 -0
@@ -125,6 +125,9 @@#ifndef NSEC_PER_SEC # define NSEC_PER_SEC 1000000000ULL#endif +#ifndef NSECS_PER_MSEC +#define NSECS_PER_MSEC 1000000ULL +#endif static inline unsigned long long rdclock (void ) {
tools/perf/tests/hists_link.c +1 -1
@@ -88,7 +88,7 @@ static struct machine *setup_fake_machine(struct machines *machines)for (i =0 ; i <ARRAY_SIZE (fake_threads); i++) {struct thread *thread; - thread =machine__findnew_thread (machine, fake_threads[i].pid); + thread =machine__findnew_thread (machine, fake_threads[i].pid,0 );if (thread ==NULL ) goto out;
tools/perf/util/build-id.c +4 -5
@@ -18,13 +18,13 @@int build_id__mark_dso_hit (struct perf_tool *tool__maybe_unused ,union perf_event *event, -struct perf_sample *sample__maybe_unused , +struct perf_sample *sample,struct perf_evsel *evsel__maybe_unused ,struct machine *machine) {struct addr_location al;u8 cpumode = event->header.misc &PERF_RECORD_MISC_CPUMODE_MASK ; -struct thread *thread =machine__findnew_thread (machine, event->ip.pid); +struct thread *thread =machine__findnew_thread (machine, event->ip.pid, sample->time);if (thread ==NULL ) { pr_err("problem processing %d event, skipping it.\n",
@@ -43,11 +43,10 @@ int build_id__mark_dso_hit(struct perf_tool *tool __maybe_unused,static int perf_event__exit_del_thread (struct perf_tool *tool__maybe_unused ,union perf_event *event, -struct perf_sample *sample -__maybe_unused , +struct perf_sample *sample,struct machine *machine) { -struct thread *thread =machine__findnew_thread (machine, event->fork.tid); +struct thread *thread =machine__findnew_thread (machine, event->fork.tid, sample->time);dump_printf ("(%d:%d):(%d:%d)\n" , event->fork.pid, event->fork.tid, event->fork.ppid, event->fork.ptid);
tools/perf/util/event.c +8 -2
@@ -552,9 +552,15 @@ int perf_event__process_fork(struct perf_tool *tool __maybe_unused,int perf_event__process_exit (struct perf_tool *tool__maybe_unused ,union perf_event *event, -struct perf_sample *sample__maybe_unused , +struct perf_sample *sample,struct machine *machine) { +struct thread *thread; + + thread =machine__find_thread (machine, event->fork.tid,0 ); +if (thread) + thread->t_exit = sample->time; +return machine__process_exit_event (machine, event); }
@@ -677,7 +683,7 @@ int perf_event__preprocess_sample(const union perf_event *event, symbol_filter_t filter) {u8 cpumode = event->header.misc &PERF_RECORD_MISC_CPUMODE_MASK ; -struct thread *thread =machine__findnew_thread (machine, event->ip.pid); +struct thread *thread =machine__findnew_thread (machine, event->ip.pid, sample->time);if (thread ==NULL )return -1 ;
tools/perf/util/machine.c +33 -11
94 lines not on this page · raw message
tools/perf/util/machine.h +4 -2
@@ -37,7 +37,8 @@ struct map *machine__kernel_map(struct machine *machine, enum map_type type)return machine->vmlinux_maps[type]; } -struct thread *machine__find_thread (struct machine *machine,pid_t tid); +struct thread *machine__find_thread (struct machine *machine,pid_t tid, +u64 sample_time);int machine__process_comm_event (struct machine *machine,union perf_event *event);int machine__process_exit_event (struct machine *machine,union perf_event *event);
@@ -101,7 +102,8 @@ static inline bool machine__is_host(struct machine *machine)return machine ? machine->pid ==HOST_KERNEL_ID : false; } -struct thread *machine__findnew_thread (struct machine *machine,pid_t tid); +struct thread *machine__findnew_thread (struct machine *machine,pid_t tid, +u64 sample_time);size_t machine__fprintf (struct machine *machine,FILE *fp);
tools/perf/util/session.c +1 -1
@@ -991,7 +991,7 @@ void perf_event_header__bswap(struct perf_event_header *self)struct thread *perf_session__findnew (struct perf_session *session,pid_t pid) { -return machine__findnew_thread (&session->machines.host, pid); +return machine__findnew_thread (&session->machines.host, pid,0 ); }static struct thread *perf_session__register_idle_thread (struct perf_session *self)
tools/perf/util/thread.h +1 -1
@@ -18,7 +18,7 @@ struct thread {bool comm_set;char *comm;int comm_len; - +u64 t_exit;void *priv; };
Signature · 1 line
1.7.10.1
Quoted 43 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 addresses the problem by saving the exit time and checking the
dead_threadslist for the requested tid. If the time passed intomachine_findnew_threadis non-0 thedead_threadslist 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->timewill be 0 and thedead_threadslist will not be checked. -1 can be used to force always checking thedead_threadslist 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 13797275894624970x1540e8[0x80]:PERF_RECORD_SAMPLE(IP, 1): 30482/30482:0xffffffff816416f1period: 1 addr: 0 ... thread: ls:30482
Quoted 7 lines
v2: 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]>
tested and
jirka
Adrian Hunter
reviewerQuoted 13 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:
Quoted 7 lines
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.
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.
Quoted 51 lines
This patch addresses the problem by saving the exit time and checking the
dead_threadslist for the requested tid. If the time passed intomachine_findnew_threadis non-0 thedead_threadslist 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->timewill be 0 and thedead_threadslist will not be checked. -1 can be used to force always checking thedead_threadslist 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 13797275894624970x1540e8[0x80]:PERF_RECORD_SAMPLE(IP, 1): 30482/30482:0xffffffff816416f1period: 1 addr: 0 .... thread: ls:30482v2: 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]>--- 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(-)
Quoted 11 lines · Adrian Hunter
Quoted 5 lines
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 bymachine__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_threadsjust because of the EXIT event.
Quoted 5 lines
Instead the thread should be marked as exiting and not moved to
dead_threadsuntil 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.
Interesting idea -- delaying the move to the dead-threads list. Following solves the problem as well.
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 ; }