Duplication of sched events

Duplication of sched events

[Milian Wolff]

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

Hey all,

I noticed the following strange behavior, which applies to most of the sched 
trace events, most notably sched_wakeup and sched_stat_*:

~~~~~~~~
#include <unistd.h>

int main()
{
   for (int i = 0; i < 100; ++i) {
       usleep(10);
   }
}
~~~~~~~~

~~~~~~~~
$ perf record -e sched:sched_wakeup --event=syscalls:sys_{enter,exit}
_nanosleep ./a.out
           a.out 16841 [007] 24360.139137: syscalls:sys_enter_nanosleep: rqtp: 
0x7ffda95e0c20, rmtp: 0x00000000
         swapper     0 [007] 24360.139201:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139201:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139202:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139202:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139202:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139202:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139203:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139203:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
           a.out 16841 [007] 24360.139206:  syscalls:sys_exit_nanosleep: 0x0
           a.out 16841 [007] 24360.139206: syscalls:sys_enter_nanosleep: rqtp: 
0x7ffda95e0c20, rmtp: 0x00000000
         swapper     0 [007] 24360.139267:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139268:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139268:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139268:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139268:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139269:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139269:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
         swapper     0 [007] 24360.139269:           sched:sched_wakeup: 
a.out:16841 [120] success=1 CPU:007
           a.out 16841 [007] 24360.139270:  syscalls:sys_exit_nanosleep: 0x0
...
# repeated like this
~~~~~~

Note how I get eight sched_wakeup events, all for the same cpu. This seems to 
be related to the number of cores on my system:

~~~~~
$ nproc
8
~~~~~

On a quad-core machine, I get them four times.

Interestingly, tracing system-wide "fixes" this behavior:

~~~~~
$ perf record -e sched:sched_wakeup --event=syscalls:sys_{enter,exit}
_nanosleep -a ./a.out
$ perf script |& grep a.out | head
           a.out 16978 [006] 24514.874484: syscalls:sys_enter_nanosleep: rqtp: 
0x7ffc44f450e0, rmtp: 0x00000000
         swapper     0 [006] 24514.874547:           sched:sched_wakeup: 
a.out:16978 [120] success=1 CPU:006
           a.out 16978 [006] 24514.874549:  syscalls:sys_exit_nanosleep: 0x0
           a.out 16978 [006] 24514.874549: syscalls:sys_enter_nanosleep: rqtp: 
0x7ffc44f450e0, rmtp: 0x00000000
         swapper     0 [006] 24514.874611:           sched:sched_wakeup: 
a.out:16978 [120] success=1 CPU:006
           a.out 16978 [006] 24514.874612:  syscalls:sys_exit_nanosleep: 0x0
~~~~~

I think this is a bug. Can someone clarify where it could come from, then I 
could try to fix it.

Thanks
-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

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