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

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

[Cheng Jian]

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).

Signed-off-by: Cheng Jian <cj.chengjian@huawei.com>
---
 kernel/events/core.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 4df5b69..a199c03 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -7924,6 +7924,8 @@ void perf_tp_event(u16 event_type, u64 count, void *record, int entry_size,
 				continue;
 			if (event->attr.config != entry->type)
 				continue;
+			if (event->cpu != task_cpu(task) && event->cpu != -1)
+				continue;
 			if (perf_tp_event_match(event, &data, regs))
 				perf_swevent_event(event, count, &data, regs);
 		}
-- 
1.8.3.1

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

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 3083 bytes --]

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@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]

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

[chengjian (D)]

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

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

[Jiri Olsa]

On Tue, Jan 16, 2018 at 08:40:38PM +0800, 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).
> 
> Signed-off-by: Cheng Jian <cj.chengjian@huawei.com>

the duplicated events are gone.. solution looks ok to me

Reviewed-and-Tested-by: Jiri Olsa <jolsa@kernel.org>

jirka

> ---
>  kernel/events/core.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/kernel/events/core.c b/kernel/events/core.c
> index 4df5b69..a199c03 100644
> --- a/kernel/events/core.c
> +++ b/kernel/events/core.c
> @@ -7924,6 +7924,8 @@ void perf_tp_event(u16 event_type, u64 count, void *record, int entry_size,
>  				continue;
>  			if (event->attr.config != entry->type)
>  				continue;
> +			if (event->cpu != task_cpu(task) && event->cpu != -1)
> +				continue;
>  			if (perf_tp_event_match(event, &data, regs))
>  				perf_swevent_event(event, count, &data, regs);
>  		}
> -- 
> 1.8.3.1
> 

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

[Arnaldo Carvalho de Melo]

Em Tue, Jan 16, 2018 at 04:06:22PM +0100, Jiri Olsa escreveu:
> On Tue, Jan 16, 2018 at 08:40:38PM +0800, 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).
> > 
> > Signed-off-by: Cheng Jian <cj.chengjian@huawei.com>
> 
> the duplicated events are gone.. solution looks ok to me
> 
> Reviewed-and-Tested-by: Jiri Olsa <jolsa@kernel.org>

I noticed that in the past as well, will try to test this too.

- Arnaldo

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

[Arnaldo Carvalho de Melo]

Em Wed, Jan 17, 2018 at 10:33:42AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Jan 16, 2018 at 04:06:22PM +0100, Jiri Olsa escreveu:
> > On Tue, Jan 16, 2018 at 08:40:38PM +0800, Cheng Jian wrote:
> > > 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).

> > > Signed-off-by: Cheng Jian <cj.chengjian@huawei.com>

> > the duplicated events are gone.. solution looks ok to me

> > Reviewed-and-Tested-by: Jiri Olsa <jolsa@kernel.org>

> I noticed that in the past as well, will try to test this too.

Unpatched kernel:

[root@jouet ~]# perf trace --no-syscalls -e sched:sched_wakeup_new time sleep 1
     0.000 sched:sched_wakeup_new:time:13571 [120] success=1 CPU:003)
18446744073709.547 sched:sched_wakeup_new:time:13571 [120] success=1 CPU:003)
18446744073709.551 sched:sched_wakeup_new:time:13571 [120] success=1 CPU:003)
18446744073709.551 sched:sched_wakeup_new:time:13571 [120] success=1 CPU:003)
18446744073709.551 sched:sched_wakeup_new:time:13571 [120] success=1 CPU:003)
0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 1996maxresident)k
0inputs+0outputs (0major+71minor)pagefaults 0swaps
[root@jouet ~]# 

Patched kernel:

[root@seventh ~]# perf trace --no-syscalls -e sched:sched_wakeup_new time sleep 1
     0.000 sched:sched_wakeup_new:comm=time pid=339 prio=120 target_cpu=002)
     0.001 sched:sched_wakeup_new:comm=time pid=339 prio=120 target_cpu=002)
0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 2084maxresident)k
0inputs+0outputs (0major+75minor)pagefaults 0swaps
[root@seventh ~]#