Re: [PATCH 0/4] perf_event: introduce 'perf timer' to analyze timer's behavior

Frederic Weisbecker
2009-12-15T14:23:35Z

On Tue, Dec 15, 2009 at 07:17:03PM +0800, Xiao Guangrong wrote:
> Hi,
>
> We introduce 'perf timer' in this patchset, it can analyze timer
> latency and timer function handle time, the usage and result is
> like below:
>
> # perf timer record
> # perf timer lat --print-lat --print-handle
> -------------------------------------------------------------------------------------------------------
> | Timer | TYPE | Avg-latency | Max-latency | Max-latency-at-TS |Max-lat-at-Task |
> |0xf7ad1f5c |hrtimer |996068.500 ns|1607650 ns|10270128658526 |init |
> |0xf7903f04 |timer |0.625 HZ|2 HZ|10270344082394 |swapper |
> |0xf787a05c |hrtimer |200239.500 ns|359929 ns|10269316024808 |main |
> |main :[ PROF]|itimer |0.000 HZ|0 HZ|10237021270557 |main |
> |main :[VIRTUAL]|itimer |0.000 HZ|0 HZ|10257314773501 |main |
>
> ......
>
> -------------------------------------------------------------------------------------------------------
> | Timer | TYPE | Avg-handle (ms)|Max-handle(ms)| Max-handle-at-TS(s)|Max-lat-at-func |
> |0xf7ad1f5c |hrtimer |0.025 |0.025 |10270.129 |0xc016b5b0 |
> |0xf7903f04 |timer |0.009 |0.011 |10260.342 |0xc0159240 |
> |0xf787a05c |hrtimer |0.031 |0.062 |10267.018 |0xc014cc40 |
>
> And, in current code, it'll complain with below message when we use
> 'perf timer lat':
>
> # ./perf timer lat
> Warning: unknown op '{'
> Warning: Error: expected type 5 but read 1
> Warning: failed to read event print fmt for hrtimer_start
> Warning: unknown op '{'
> Warning: Error: expected type 5 but read 1
> Warning: failed to read event print fmt for hrtimer_expire_entry

Oh and indeed we have some event format complexities to solve
there.

cat /debug/tracing/events/timer/hrtimer_start/format

print fmt: "hrtimer=%p function=%pf expires=%llu softexpires=%llu", REC->hrtimer, REC->function, (unsigned long
long)(((ktime_t) { .tv64 = REC->expires }).tv64), (unsigned long long)(((ktime_t) { .tv64 = REC->softexpires
}).tv64)

We should try to simplify this, may be we should just expose
__entry->expires as is.