Re: [PATCH v3] perf/trace : Fix repetitious traces of perf on tracepoint

[Milian Wolff]

On Tuesday, January 16, 2018 1:40:38 PM CET Cheng Jian wrote:
> 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 :
> 
> 	#./test_fork
> 		parent pid : 1059
> 		child pid : 1060
> 	#perf record -e sched:sched_wakeup_new -p 1060
> 
> test_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) :
> 
>         test_fork  1059 [001]    62.913689: sched:sched_wakeup_new:
> comm=test_fork pid=1060 prio=120 target_cpu=002 test_fork  1059 [001]   
> 62.913698: sched:sched_wakeup_new: comm=test_fork pid=1060 prio=120
> target_cpu=002 test_fork  1059 [001]    62.913705: sched:sched_wakeup_new:
> comm=test_fork pid=1060 prio=120 target_cpu=002
> 
> but ftrace report this event only once :
> 
> 	test_fork-1059  [002] d...   62.913680: sched_wakeup_new: comm=test_fork
> pid=1060 prio=120 target_cpu=002
> 
> 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.
> 
> These events are registered as per cpu most of the time and attached
> to the task too, we will get all of them from the perf_event_context
> of this task, they will be matched success but are all the same event.
> So check the cpu number of this event to avoid matching them multiple
> times.
> 
> after this patch, perf script(parent-1040, child-1041):
> 
> 	test_fork  1040 [002]    36.536079: sched:sched_wakeup_new: comm=test_fork
> pid=1041 prio=120 target_cpu=003
> 
> It will match it only once for tracing task(child-1041).

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

Use 'sleep 1' as the debuggee. On my system, I get the period multiplied by 
nproc like you describe:

```
$ perf-sleep-record sleep 1
..
$ perf report --stdio --show-total-period | grep "Event count"
..
# Event count (approx.): 8000845488
$ nproc
8
```

The sleep-record script is available at: https://github.com/milianw/shell-helpers/blob/master/perf-sleep-record

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?

Thanks

-- 
Milian Wolff | milian.wolff@xxxxxxxx | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Attachment: smime.p7s
Description: S/MIME cryptographic signature