From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752442AbeA0Jmv (ORCPT ); Sat, 27 Jan 2018 04:42:51 -0500 Received: from szxga06-in.huawei.com ([45.249.212.32]:34553 "EHLO huawei.com" rhost-flags-OK-FAIL-OK-FAIL) by vger.kernel.org with ESMTP id S1752048AbeA0Jms (ORCPT ); Sat, 27 Jan 2018 04:42:48 -0500 Subject: Re: [PATCH v3] perf/trace : Fix repetitious traces of perf on tracepoint To: Milian Wolff CC: , , , , , , , , , , Li Bin , "Xiexiuqi (Xie XiuQi)" , "chengjian (D)" References: <1516106438-4143-1-git-send-email-cj.chengjian@huawei.com> <8597218.ZhpRet0H89@milian-kdab2> From: "chengjian (D)" Message-ID: <3e594e1d-55aa-ee68-0563-f03c22cea6fd@huawei.com> Date: Sat, 27 Jan 2018 17:42:19 +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: <8597218.ZhpRet0H89@milian-kdab2> Content-Type: text/plain; charset="windows-1252"; 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 Hi, Milian On 2018/1/16 22:33, Milian Wolff wrote: >> perf script print the same 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. >> >> the sched_stat_* tracepoint also specify a target process, so it will be reported nrcpus times too. for example sched_stat_sleep swapper 0 [002] 188.752870: sched:sched_stat_sleep: comm=bug_fork_loop pid=1051 delay=2133649486 [ns] | | | | current task > Oh, this sounds awesome. I don't have the setup available to compile a kernel > with this patch applied, but I think from the description it solves a long- > standing issue with perf's sleep-time profiling. > > Can someone try this please: > https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times > when current != task. #echo 1 > /proc/sys/kernel/sched_schedstats #./perf-bin/perf record -e sched:sched_stat_sleep ./test_fork_loop before this patch: :1050 1050 [000] 186.597339: sched:sched_stat_sleep: comm=perf pid=1051 delay=22955314 [ns] :1050 1050 [000] 186.597397: sched:sched_stat_sleep: comm=perf pid=1051 delay=22955314 [ns] :1050 1050 [000] 186.597406: sched:sched_stat_sleep: comm=perf pid=1051 delay=22955314 [ns] :1050 1050 [000] 186.597415: sched:sched_stat_sleep: comm=perf pid=1051 delay=22955314 [ns] swapper 0 [002] 188.752870: sched:sched_stat_sleep: comm=bug_fork_loop pid=1051 delay=2133649486 [ns] swapper 0 [002] 188.752899: sched:sched_stat_sleep: comm=bug_fork_loop pid=1051 delay=2133649486 [ns] swapper 0 [002] 188.752952: sched:sched_stat_sleep: comm=bug_fork_loop pid=1051 delay=2133649486 [ns] swapper 0 [002] 188.752965: sched:sched_stat_sleep: comm=bug_fork_loop pid=1051 delay=2133649486 [ns] after this patch: :1041 1041 [001] 62.447062: sched:sched_stat_sleep: comm=perf pid=1042 delay=43035826 [ns] swapper 0 [001] 62.704644: sched:sched_stat_sleep: comm=bug_fork_loop pid=1042 delay=234613068 [ns] > > I believe your patch also fixes the sched_stat_* tracepoints to be only > emitted once per CPU. Can you verify this? I.e. is the period finally > correctly calculated and we get a value of roughly 1E9ns == 1s? > Yeah, this patch fix it. Thanks. CHENG Jian