Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751187AbeAPBHL (ORCPT + 1 other); Mon, 15 Jan 2018 20:07:11 -0500 Received: from szxga06-in.huawei.com ([45.249.212.32]:58954 "EHLO huawei.com" rhost-flags-OK-FAIL-OK-FAIL) by vger.kernel.org with ESMTP id S1750773AbeAPBHJ (ORCPT ); Mon, 15 Jan 2018 20:07:09 -0500 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 : To: Peter Zijlstra CC: , , , , , , , , References: <1516019633-6709-1-git-send-email-cj.chengjian@huawei.com> <20180115123157.GA2228@hirez.programming.kicks-ass.net> From: "chengjian (D)" Message-ID: <042431f9-5a9d-d53d-add9-b3dcf4f09c9a@huawei.com> Date: Tue, 16 Jan 2018 09:06:16 +0800 User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101 Thunderbird/52.2.1 MIME-Version: 1.0 In-Reply-To: <20180115123157.GA2228@hirez.programming.kicks-ass.net> Content-Type: text/plain; charset="UTF-8"; format=flowed Content-Transfer-Encoding: 7bit X-Originating-IP: [10.177.219.85] X-CFilter-Loop: Reflected Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Return-Path: 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