Re: [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 :

Mon, 15 Jan 2018 17:07:30 -0800 

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

Reply via email to