lkml.org 
[lkml]   [2018]   [Jan]   [15]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH] perf/trace : Fix repetitious traces of perf on tracepoint When i use perf to trace the sched_wakeup_new tracepoint, there is a bug that output the same event repetitiously. It can be reproduced by :
From
Date
On 2018/1/15 20:31, Peter Zijlstra wrote:


I'm sorry I gave an inappropriate example to make the phenomenon look
confusing.

These events are registered per_cpu and attach in the the
perf_event_ctxp of task too.
So the same event is placed in the process context CPU times.

perf record -e sched:sched_wakeup_new -vv bug_fork
......
sys_perf_event_open: pid 1063 cpu 0 group_fd -1 flags 0x8 = 4
sys_perf_event_open: pid 1063 cpu 1 group_fd -1 flags 0x8 = 5
sys_perf_event_open: pid 1063 cpu 2 group_fd -1 flags 0x8 = 6
sys_perf_event_open: pid 1063 cpu 3 group_fd -1 flags 0x8 = 8
mmap size 528384B
perf event ring buffer mmapped per cpu




/*
* If we got specified a target task, also iterate its context and
* deliver this event there too.
*/
// Here we want to see whether this event can be matched by the
task not current.
// task is the child now.(tracing task)
if (task && task != current) {
......
// the event mmaped per cpu, But
// task->perf_event_ctxp[perf_sw_context] get all the events
attach in this task
ctx = rcu_dereference(task->perf_event_ctxp[perf_sw_context]);

list_for_each_entry_rcu(event, &ctx->event_list, event_entry) {
if (event->attr.type != PERF_TYPE_TRACEPOINT)
continue;
if (event->attr.config != entry->type)
continue;
// event->cpu(3) != task_cpu(1) bug_fork 1063
[003] 128.001255: sched:sched_wakeup_new: comm=bug_fork pid=1064
prio=120 target_cpu=002
// event->cpu(2) != task_cpu(1) bug_fork 1063
[003] 128.001255: sched:sched_wakeup_new: comm=bug_fork pid=1064
prio=120 target_cpu=002
// event->cpu(1) == task_cpu(1) bug_fork 1063
[003] 128.001255: sched:sched_wakeup_new: comm=bug_fork pid=1064
prio=120 target_cpu=002
// event->cpu(0) != task_cpu(1) bug_fork 1063
[003] 128.001255: sched:sched_wakeup_new: comm=bug_fork pid=1064
prio=120 target_cpu=002
// but we only need one about event->cpu(1) ==
task_cpu(1), the others are repeated
if (perf_tp_event_match(event, &data, regs))
perf_swevent_event(event, count, &data, regs);
}
unlock:
rcu_read_unlock();
}
```



>> after this patch, perf script(perf-1039, parent-1040, child-1041):
>>
>> bug_fork 1040 [002] 36.535963: sched:sched_wakeup_new:
>> comm=bug_fork pid=1041 prio=120 target_cpu=003
>> bug_fork 1040 [002] 36.536079: sched:sched_wakeup_new:
>> comm=bug_fork pid=1041 prio=120 target_cpu=003
>>
>> match it twice, an match for tracing current(parent) and an match
>> for task(child).
> So what is the bug? The parent gets one, the child gets one, that's
> correct, no?
>
> .
So the bug is, we match the same event NR_CPU times when tracing the
waken(child process in my demo).


I will modify my commit, and make it clearer.


Thanks.

CHENG Jian


\
 
 \ /
  Last update: 2018-01-16 02:07    [W:0.029 / U:3.996 seconds]
©2003-2018 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site