Re: timing information with perf

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

Em Thu, Nov 12, 2015 at 06:57:28PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Thu, Nov 12, 2015 at 09:07:20PM +0000, Kornievskaia, Olga escreveu:

> > Can somebody tell me if perf can do “timing-of-operation” type of
> > measurement? By that I mean, say there are two tracepoints
> > “foobar_enter” and “foobar_exit”. Each tracepoint logs a timestamp.
> > I’d like to be able to say that on average it takes that many
> > time-units between “enter” and “exit” tracepoints. I haven’t been
> > able to find something like that with “perf”.
 
> Well, you can do:
> 
>   # perf record -a -e sched:*waking*,sched:*wakeup* sleep 2
>   [ perf record: Woken up 1 times to write data ]
>   [ perf record: Captured and wrote 0.199 MB perf.data (156 samples) ]
>   # perf script -g python
>   generated Python script: perf-script.py
>   # grep '^def ' perf-script.py 
>   def trace_begin():
>   def trace_end():
>   def sched__sched_wakeup_new(event_name, context, common_cpu,
>   def sched__sched_wakeup(event_name, context, common_cpu,
>   def sched__sched_waking(event_name, context, common_cpu,
>   def trace_unhandled(event_name, context, event_fields_dict):
>   def print_header(event_name, cpu, secs, nsecs, pid, comm):
>   #
> 
> The prototype for sched__sched_wakeup(), for instance is:
> 
> def sched__sched_wakeup(event_name, context, common_cpu,
>         common_secs, common_nsecs, common_pid, common_comm,
>         common_callchain, comm, pid, prio, success,
>         target_cpu):
> 
> Then do some minimal coding for what you want, because you need
> to match it using some key, i.e. same pid is enough for some cases, for
> others you need pid + fd, etc.

If you do not change that script, then running it will produce:

  # perf script -s perf-script.p
  in trace_begin
  sched__sched_waking 2 09156.170326579 16181 perf comm=perf, pid=16182, prio=120, success=1, target_cpu=3
  sched__sched_wakeup 2 09156.170329797 16181 perf comm=perf, pid=16182, prio=120, success=1, target_cpu=3
  sched__sched_waking 3 09156.170446653 16182 perf comm=migration/3, pid=28, prio=0, success=1, target_cpu=3
<SNIP>
  in trace_end
 
- Arnaldo