linux-kernel - 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 :

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Date:   Tue, 16 Jan 2018 09:06:16 +0800
From:   "chengjian (D)" <cj.chengjian@...wei.com>
To:     Peter Zijlstra <peterz@...radead.org>
CC:     <mingo@...hat.com>, <acme@...nel.org>,
        <alexander.shishkin@...ux.intel.com>, <jolsa@...hat.com>,
        <namhyung@...nel.org>, <xiexiuqi@...wei.com>,
        <huawei.libin@...wei.com>, <wangnan0@...wei.com>,
        <linux-kernel@...r.kernel.org>
Subject: 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 :

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