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] [thread-next>] [day] [month] [year] [list]

Message-ID: <20180115123157.GA2228@hirez.programming.kicks-ass.net>
Date:   Mon, 15 Jan 2018 13:31:57 +0100
From:   Peter Zijlstra <peterz@...radead.org>
To:     Cheng Jian <cj.chengjian@...wei.com>
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 Mon, Jan 15, 2018 at 08:33:53PM +0800, Cheng Jian wrote:
> 	perf record -e sched:sched_wakeup_new ./bug_fork
> 
> bug_fork is an demo that can generating wakeup_new event, parent
> process does nothing but fork a child process, and then they both
> quit.
> 
> There are 4 processors in this machine. before this patch,
> perf script(perf-1058, parent-1059, child-1060) :
> 
> 	bug_fork  1059 [001]    62.913666: sched:sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002
>         bug_fork  1059 [001]    62.913680: sched:sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002
>         bug_fork  1059 [001]    62.913689: sched:sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002
>         bug_fork  1059 [001]    62.913698: sched:sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002
>         bug_fork  1059 [001]    62.913705: sched:sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002

Please don't wrap that, that's unreadable

> 
> but ftrace report this event only once :
> 
> 	bug_fork-1059  [002] d...   62.913666: sched_wakeup_new:
> comm=bug_fork pid=1060 prio=120 target_cpu=002
> 
> perf script print wakeup_new event multiple times.
> 
> These events which trigger this issue all specify a target process.
> commit e6dab5ffab59 ("perf/trace: Add ability to set a target task
> for events") has designed a method to trace these events. For
> example, the sched_wakeup and sched_wakeup_new tracepoint will be
> caught when the current task wakeup a target task. If we trace both
> of them and task(waken) != current(wakee), it will match this event
> at the beginning for tracing current task, and then match again for
> tracing the waken task. But these events are registered at all cpus
> most of the time, so these events will be matched nr_cpu times
> in this branch.
> 
> We just forcus on the task thread here, so check the cpu number of
> this event and task.
> 
> 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?