Skip to contentSkip to conversation

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

DISCUSSION William Cohen 3 participants 6 messages Nov 18, 2015 – Nov 19, 2015

lore
Share & tools
lore

William Cohen

author
#0 lore raw

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

#1 lore raw
Quoted 24 lines · 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]
Quoted 5 lines

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.

author
#2 lore raw
Quoted 25 lines · David Ahern
Quoted 24 lines · 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]
Quoted 8 lines
Quoted 5 lines

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

#3 lore raw
Quoted 4 lines · William Cohen

Okay,

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

Quoted 8 lines

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

#4 lore raw

Em Wed, Nov 18, 2015 at 12:18:20PM -0700, David Ahern escreveu:

Quoted 11 lines · William Cohen
Quoted 8 lines

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 <[email protected]>
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

#5 lore raw
In reply to William Cohen

Em Wed, Nov 18, 2015 at 02:01:13PM -0500, William Cohen escreveu:

Quoted 22 lines

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]
Quoted 5 lines

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