RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[William Cohen]

Hi,

I was experimenting with the sched:sched_switch tracepoint to look at
the time that a process spend off the processor.  As a really simple
experiment record data with:

$ sudo perf record -e sched:sched_switch -- du

Then examine the data with:

$ sudo perf script

The output only shows the sched:sched_switch when the process is moved
off the processor.  However, there is no data showing when the process is
scheduled back onto the processor:

              du 20960 [007] 339893.429394: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.429411: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.429544: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.429556: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.429561: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.429567: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
              du 20960 [007] 339893.430150: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]

Would it be possible to make perf's process filtering more inclusive so
that output also includes sched:sched_switch tracepoints for pid that
are also being scheduled onto the processor?  The alternative of
recording all sched:sched_switch events system-wide and filtering out
all the unwanted pid's is undesirable.

-Will

Re: RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[David Ahern]

On 11/18/15 12:01 PM, William Cohen wrote:
> Hi,
>
> I was experimenting with the sched:sched_switch tracepoint to look at
> the time that a process spend off the processor.  As a really simple
> experiment record data with:
>
> $ sudo perf record -e sched:sched_switch -- du
>
> Then examine the data with:
>
> $ sudo perf script
>
> The output only shows the sched:sched_switch when the process is moved
> off the processor.  However, there is no data showing when the process is
> scheduled back onto the processor:
>
>                du 20960 [007] 339893.429394: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.429411: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.429544: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.429556: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.429561: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.429567: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>                du 20960 [007] 339893.430150: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>
> Would it be possible to make perf's process filtering more inclusive so
> that output also includes sched:sched_switch tracepoints for pid that
> are also being scheduled onto the processor?  The alternative of
> recording all sched:sched_switch events system-wide and filtering out
> all the unwanted pid's is undesirable.

Known pain point. I thought Adrian had new sched tracepoints added to 
handle it, but I lost track of whether it was accepted.

Re: RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[William Cohen]

On 11/18/2015 02:08 PM, David Ahern wrote:
> On 11/18/15 12:01 PM, William Cohen wrote:
>> Hi,
>>
>> I was experimenting with the sched:sched_switch tracepoint to look at
>> the time that a process spend off the processor.  As a really simple
>> experiment record data with:
>>
>> $ sudo perf record -e sched:sched_switch -- du
>>
>> Then examine the data with:
>>
>> $ sudo perf script
>>
>> The output only shows the sched:sched_switch when the process is moved
>> off the processor.  However, there is no data showing when the process is
>> scheduled back onto the processor:
>>
>>                du 20960 [007] 339893.429394: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.429411: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.429544: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.429556: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.429561: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.429567: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>                du 20960 [007] 339893.430150: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>>
>> Would it be possible to make perf's process filtering more inclusive so
>> that output also includes sched:sched_switch tracepoints for pid that
>> are also being scheduled onto the processor?  The alternative of
>> recording all sched:sched_switch events system-wide and filtering out
>> all the unwanted pid's is undesirable.
> 
> Known pain point. I thought Adrian had new sched tracepoints added to handle it, but I lost track of whether it was accepted.
> 

Okay,

As a workaround can use the filtering to cut down some of data being recorded with:

export PID=<process_of_interest>
sudo perf record -a -e sched:sched_switch --filter "next_pid == $PID || prev_pid == $PID" --

Is the following the correct thread discussing those new sched tracepoints?

https://lkml.org/lkml/2015/6/9/513

-Will

Re: RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[David Ahern]

On 11/18/15 12:16 PM, William Cohen wrote:
> Okay,
>
> As a workaround can use the filtering to cut down some of data being recorded with:
>
> export PID=<process_of_interest>
> sudo perf record -a -e sched:sched_switch --filter "next_pid == $PID || prev_pid == $PID" --
>
> Is the following the correct thread discussing those new sched tracepoints?
>
> https://lkml.org/lkml/2015/6/9/513
>
> -Will

I believe so

Re: RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[Arnaldo Carvalho de Melo]

Em Wed, Nov 18, 2015 at 12:18:20PM -0700, David Ahern escreveu:
> On 11/18/15 12:16 PM, William Cohen wrote:
> >As a workaround can use the filtering to cut down some of data being recorded with:

> >export PID=<process_of_interest>
> >sudo perf record -a -e sched:sched_switch --filter "next_pid == $PID || prev_pid == $PID" --

> >Is the following the correct thread discussing those new sched tracepoints?

> >https://lkml.org/lkml/2015/6/9/513

> I believe so

Right, take a look at:

commit ae938802443732e77d01f8d5b52b900b9327ff30
Author: Arnaldo Carvalho de Melo <acme@redhat.com>
Date:   Tue Oct 6 17:46:46 2015 -0300

    perf python: Support the PERF_RECORD_SWITCH event
    
    To test it check tools/perf/python/twatch.py, after following the
    instructions there to enable context_switch, output looks like:
    
      [root@zoo linux]# tools/perf/python/twatch.py
      cpu: 1, pid: 31463, tid: 31463 { type: context_switch, next_prev_pid: 31463, next_prev_tid: 31463, switch_out: 0 }
      cpu: 2, pid: 31463, tid: 31496 { type: context_switch, next_prev_pid: 31463, next_prev_tid: 31496, switch_out: 0 

- Arnaldo

Re: RFE: More inclusive pid filtering of sched:sched_switch tracepoint events

[Arnaldo Carvalho de Melo]

Em Wed, Nov 18, 2015 at 02:01:13PM -0500, William Cohen escreveu:
> I was experimenting with the sched:sched_switch tracepoint to look at
> the time that a process spend off the processor.  As a really simple
> experiment record data with:
> 
> $ sudo perf record -e sched:sched_switch -- du
> 
> Then examine the data with:
> 
> $ sudo perf script
> 
> The output only shows the sched:sched_switch when the process is moved
> off the processor.  However, there is no data showing when the process is
> scheduled back onto the processor:
> 
>               du 20960 [007] 339893.429394: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.429411: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.429544: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.429556: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.429561: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.429567: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
>               du 20960 [007] 339893.430150: sched:sched_switch: du:20960 [120] R ==> kworker/7:0:16805 [120]
> 
> Would it be possible to make perf's process filtering more inclusive so
> that output also includes sched:sched_switch tracepoints for pid that
> are also being scheduled onto the processor?  The alternative of
> recording all sched:sched_switch events system-wide and filtering out
> all the unwanted pid's is undesirable.

So, on a recent kernel, no need to run with sudo:

[acme@zoo linux]$ perf record --switch-events -e dummy -- du > /dev/null
^[[A[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.016 MB perf.data ]
[acme@zoo linux]$ perf script --show-switch-events
              du  4026 103867.891889: PERF_RECORD_SWITCH OUT
              du  4026 103867.891980: PERF_RECORD_SWITCH IN 
              du  4026 103867.984411: PERF_RECORD_SWITCH OUT
              du  4026 103867.984424: PERF_RECORD_SWITCH IN 
[acme@zoo linux]$

[acme@zoo linux]$ perf report -D | grep PERF_RECORD_SWITCH
103867891889845 0x4260 [0x18]: PERF_RECORD_SWITCH OUT
103867891980760 0x4278 [0x18]: PERF_RECORD_SWITCH IN 
103867984411995 0x4290 [0x18]: PERF_RECORD_SWITCH OUT
103867984424725 0x42a8 [0x18]: PERF_RECORD_SWITCH IN 
[acme@zoo linux]$ 

- Arnaldo