Re: Tracing sched_switch events for client application when process is switched back in

[Milian Wolff <milian.wolff@kdab.com>]

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

On Thursday, October 6, 2016 1:21:25 PM CEST Arnaldo Carvalho de Melo wrote:
> Em Thu, Oct 06, 2016 at 05:52:51PM +0200, Milian Wolff escreveu:
> > Hey all,
> > 
> > when you have an application like this:
> > 
> > ~~~~~~
> > #include <unistd.h>
> > 
> > int main()
> > {
> > 
> >    for (int i = 0; i < 100; ++i) {
> >    
> >        usleep(10);
> >    
> >    }
> > 
> > }
> > ~~~~~~
> > 
> > Then record sched:sched_switch events for it:
> > 
> > ~~~~~~
> > $ perf record -e sched:sched_switch ./a.out
> > [ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 0.031 MB perf.data (100 samples) ]
> > ~~~~~~
> > 
> > Note how it's only 100 samples, instead of 200 for both, the switch-out
> > and
> > switch-in events. Apparently we only get the switch-out events:
> > 
> > ~~~~~
> > $ perf script -F trace | uniq -c
> > 
> >      99 a.out:3994 [120] S ==> swapper/7:0 [120]
> >      
> >       1 a.out:3994 [120] S ==> swapper/7:0 [1
> > 
> > ~~~~~
> > 
> > Doing a global trace, or using LTTNG, we also see the switch-in events:
> > 
> > ~~~~~
> > $ perf record -e sched:sched_switch -a ./a.out
> > $ perf script -F trace | grep a.out | sort | uniq -c
> > 
> >     100 a.out:11570 [120] S ==> swapper/4:0 [120]
> >     
> >       1 a.out:11570 [120] x ==> swapper/4:0 [120]
> >     
> >     100 swapper/4:0 [120] R ==> a.out:11570 [120]
> > 
> > ~~~~~
> > 
> > Is there any way I can get both sched switch events, i.e. not only the one
> > with prev_tid=$client_tid, but also the one with next_tid=$client_tid? One
> > way
> > that seems to work is the following:
> Have you considered using PERF_RECORD_SWITCH?
> 
> [acme@jouet linux]$ perf record --switch-events sleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.020 MB perf.data (7 samples) ]
> [acme@jouet linux]$ perf script --show-switch-events
>   sleep 20679  5578.172409:          1 cycles:u:      7fb4e5a51c80
> _start+0x0 (/usr/lib64/ld-2.23.so) sleep 20679  5578.172411:          1
> cycles:u:      7fb4e5a51c80 _start+0x0 (/usr/lib64/ld-2.23.so) sleep 20679 
> 5578.172412:         12 cycles:u:      7fb4e5a51c80 _start+0x0
> (/usr/lib64/ld-2.23.so) sleep 20679  5578.172413:        397 cycles:u:     
> 7fb4e5a51c80 _start+0x0 (/usr/lib64/ld-2.23.so) sleep 20679  5578.172414:  
>    13936 cycles:u:  ffffffffb77ee7a0 page_fault+0x0
> (/usr/lib/debug/lib/modules/4.7.5-200.fc24.x86_64/vmlinux) sleep 20679 
> 5578.172431:     330542 cycles:u:      7fb4e5a5301f dl_main+0x6cf
> (/usr/lib64/ld-2.23.so) sleep 20679  5578.172700: PERF_RECORD_SWITCH OUT
>   sleep 20679  5579.172821: PERF_RECORD_SWITCH IN
>   sleep 20679  5579.172838:     802931 cycles:u:      7fb4e5a6122e
> _dl_fini+0x8e (/usr/lib64/ld-2.23.so) [acme@jouet linux]$

First time I read about it, and the documentation is scarce, to not say non-
existing. It seems to record cycles for the switch events. But why does it 
only find 7, whereas tracing sched_switch finds all 100 that actually take 
place?

The reason why I want sched_switch is that I want to build a "better" sleep 
time profiler. The existing script [1] is cumbersome to use, and only shows 
parts of what is going on:

- only looks at sched_stat_sleep, ignores sched_stat_iowait or sched_stat_wait
- requires one to enable the sched_stat tracepoints in newer kernels 
  $ echo 1 | sudo tee /proc/sys/kernel/sched_schedstats
- as a user-space developer, I actually care about the time between getting 
switched out and getting switched in, so using that in perf would actually 
give me the duration I got switched out

If I could do something like this:

$ perf record -e cycles:ppp,sched:sched_switch <my app>

And have both switch-in and switch-out traced, than a GUI could visualize this 
together and show me both, CPU hotspots as well as sleep/io/blocked time where 
I got switched out

[1] https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times

-- 
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 --]