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: 4821 bytes --]

On Monday, October 10, 2016 9:36:55 PM CET Arnaldo Carvalho de Melo wrote:
> Em Thu, Oct 06, 2016 at 06:38:28PM +0200, Milian Wolff escreveu:
> > 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?

Hey there,

long delay but I looked at this again today.

> This is looking only for the sched switches for the monitored workload,
> which in this case is 'sleep 1', this wasn't a system wide session.
>
> add -a and you'll get those other switches, if I got what you described.

I've used the sources of the simple C application I showed in the first email 
of this thread (still quoted above). Then I try:

perf record --switch-events -a ./a.out

And indeed, I get all switch events. But I now also profile all applications 
on the machine, which is not what I want. I want to combine the following 
features:

- sample CPU events for a given application with backtraces
	perf record --call-graph dwarf ./foo
- record switch-out events with backtraces (`-e sched:sched_switch/fp=dwarf/`)
- somehow record the switch-in events, which are associated with a different 
process and thus currently discarded

Any advise on where to look for the filtering? Not discarding the sched_switch 
of a different process based on matching next_tid can't be that hard, or is 
it?

Cheers

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