Re: Sampling on sched:sched_switch

[Arnaldo Carvalho de Melo <acme@kernel.org>]

Em Mon, Apr 13, 2015 at 06:34:38PM +0530, sahil aggarwal escreveu:
> Hi
> 
> I am enabling sampling on tracepoint: sched:sched_switch, during which
> i get no data points for a particular process but when i run:

"sampling" what target? System wide? How are you setting up
perf_event_attr?
 
> perf stat -e "context_switch" <some exec>

s/context_switch/sched:sched_switch/g, right?

> then it shows that exec was context switched.
> 
> How it could be possible.?

Why would it not?

[root@zoo ~]# perf stat -e sched:sched_switch usleep 1

 Performance counter stats for 'usleep 1':

                 1      sched:sched_switch                                          

       0.001180692 seconds time elapsed

[root@zoo ~]#

[root@zoo ~]# perf trace --ev sched:sched_switch usleep 1 | tail
  0.407 ( 0.004 ms): usleep/9676 mprotect(start: 0x601000, len: 4096, prot: READ      ) = 0
  0.417 ( 0.005 ms): usleep/9676 mprotect(start: 0x7f1649452000, len: 4096, prot: READ) = 0
  0.429 ( 0.010 ms): usleep/9676 munmap(addr: 0x7f1649436000, len: 108577             ) = 0
  0.495 ( 0.002 ms): usleep/9676 brk(                                                 ) = 0xe5b000
  0.500 ( 0.004 ms): usleep/9676 brk(brk: 0xe7c000                                    ) = 0xe7c000
  0.503 ( 0.001 ms): usleep/9676 brk(                                                 ) = 0xe7c000
  0.525 ( 0.005 ms): usleep/9676 nanosleep(rqtp: 0x7fffc0c7f7e0                       ) ...
  0.525 (         ): sched:sched_switch:usleep:9676 [120] S ==> swapper/2:0 [120])
  0.582 ( 0.062 ms): usleep/9676  ... [continued]: nanosleep()) = 0
  0.588 ( 0.000 ms): usleep/9676 exit_group(                                                           
[root@zoo ~]#

When we expected it to :-)

Now, this is how perf_event_attr is being set, in both cases (the code setting
up the perf_event_attr in 'perf trace' and 'perf stat' is the same):

[root@zoo ~]# perf stat -vv -e sched:sched_switch usleep 1
<SNIP>
perf_event_attr:
  type                             2
  size                             112
  config                           107
  { sample_period, sample_freq }   1
  sample_type                      TIME|CPU|PERIOD|RAW
  read_format                      TOTAL_TIME_ENABLED|TOTAL_TIME_RUNNING
  disabled                         1
  inherit                          1
  enable_on_exec                   1
  exclude_guest                    1
------------------------------------------------------------
sys_perf_event_open: pid 9685  cpu -1  group_fd -1  flags 0x8
sched:sched_switch: 1 688844 688844

 Performance counter stats for 'usleep 1':

                 1      sched:sched_switch                                          

       0.001368517 seconds time elapsed

[root@zoo ~]#

[root@zoo ~]# perf trace -vv --ev sched:sched_switch usleep 1 
<SNIP>
perf_event_attr:
  type                             2
  size                             112
  config                           107
  { sample_period, sample_freq }   1
  sample_type                      IP|TID|TIME|ID|CPU|PERIOD|RAW
  read_format                      ID
  disabled                         1
  inherit                          1
  mmap                             1
  comm                             1
  enable_on_exec                   1
  task                             1
  sample_id_all                    1
  exclude_guest                    1
  mmap2                            1
  comm_exec                        1
  { wakeup_events, wakeup_watermark } 1
<SNIP setting up the other events, for the syscall events>
  0.491 ( 0.002 ms): usleep/9693 brk(                                            ) = 0xd41000
  0.502 ( 0.004 ms): usleep/9693 brk(brk: 0xd62000                               ) = 0xd62000
  0.505 ( 0.002 ms): usleep/9693 brk(                                            ) = 0xd62000
  0.527 ( 0.005 ms): usleep/9693 nanosleep(rqtp: 0x7ffc7df44ee0                  ) ...
  0.527 (         ): sched:sched_switch:usleep:9693 [120] S ==> swapper/1:0 [120])
  0.583 ( 0.061 ms): usleep/9693  ... [continued]: nanosleep()) = 0
  0.589 ( 0.000 ms): usleep/9693 exit_group(                                                           
[root@zoo ~]# 

In the 'perf trace' case we need more stuff into sample_type, like ID, because
we need to map back to multiple events: sched:sched_switch, raw_syscalls:sys_e{nter,xit}, etc.

- Arnaldo