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
