lkml.org 
[lkml]   [2018]   [Jan]   [27]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH v3] perf/trace : Fix repetitious traces of perf on tracepoint
From
Date
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

\
 
 \ /
  Last update: 2018-01-27 10:43    [W:0.079 / U:2.104 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site