Re: timing information with perf

[David Ahern <dsahern@gmail.com>]

On 11/12/15 3:04 PM, Arnaldo Carvalho de Melo wrote:
> 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

I think he wants to average the time difference between 2 tracepoints. 
You should be able to run the output of perf script through an awk 
script to get it.