Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Subject: Re: [PATCH v3] perf/trace : Fix repetitious traces of perf on
 tracepoint
To:     Milian Wolff <milian.wolff@kdab.com>
CC:     <peterz@infradead.org>, <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>, Li Bin <huawei.libin@huawei.com>,
        "Xiexiuqi (Xie XiuQi)" <xiexiuqi@huawei.com>,
        "chengjian (D)" <cj.chengjian@huawei.com>
References: <1516106438-4143-1-git-send-email-cj.chengjian@huawei.com>
 <8597218.ZhpRet0H89@milian-kdab2>
From:   "chengjian (D)" <cj.chengjian@huawei.com>
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
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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