Date: Mon, 15 Jan 2018 13:31:57 +0100
From: Peter Zijlstra <peterz@infradead.org>
To: Cheng Jian <cj.chengjian@huawei.com>
Cc: mingo@redhat.com, acme@kernel.org,
        alexander.shishkin@linux.intel.com, jolsa@redhat.com,
        namhyung@kernel.org, xiexiuqi@huawei.com, huawei.libin@huawei.com,
        wangnan0@huawei.com, linux-kernel@vger.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 :
Message-ID: <20180115123157.GA2228@hirez.programming.kicks-ass.net>
References: <1516019633-6709-1-git-send-email-cj.chengjian@huawei.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <1516019633-6709-1-git-send-email-cj.chengjian@huawei.com>
User-Agent: Mutt/1.9.2 (2017-12-15)
Sender: linux-kernel-owner@vger.kernel.org

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?