[PATCH v2 0/5] perf_event: introduce 'perf timer' to analyze timer's behavior

Xiao Guangrong
2009-12-22T13:01:52Z

Hi,

We introduce 'perf timer' in this patchset, it can report
number of activated/expired/canceled timers, timer latency
and timer function runtime.

Changlog v1->v2:
- export HZ in timer's tracepoint, we can use it to get
TIMER/ITIMER_VIRTUAL/ITIMER_PROF exact latency as Ingo's
suggestion

- rename 'perf timer latency' to 'perf timer report',
because it not only show timer latency but also show timer
function runtime, timer activated/canceled/expired statistics
and canceled timer list(TODO)

Below changes are all from Thomas's suggestion:
- fix a lot of typos and bad ideas

- use hash table instead of RB tree to record timer

- let output information more readable

- report number of activated/canceled/expired timers

- support to filter timer types:
'--type' can do it

TODO:
- Show canceled timer list that is suggested by Thomas

- Any suggestion are welcome.

===============================================
Usage:
- record timer events:
#perf timer record
#^C

- show timer statistics:
#perf timer report

Statistics
==========
Activated timers number:
HRTIMER: 37199 TIMER: 828 ITIMER_PROF: 2 ITIMER_VIRTUAL: 2 ITIMER_REAL: 18

Expired timers number:
HRTIMER: 34912 TIMER: 617 ITIMER_PROF: 1 ITIMER_VIRTUAL: 1 ITIMER_REAL: 1

Canceled timers number:
HRTIMER: 37200 TIMER: 829 ITIMER_PROF: 1 ITIMER_VIRTUAL: 1 ITIMER_REAL: 17

- show timer latency:
#perf timer report --print-lat
Timer Latency List
[ Abbreviations: Avg = average; lat = latency; ts = timestamp ]
-------------------------------------------------------------------------
Timer | TYPE | Avg-lat ms| Max-lat ms| Max-lat-ts s
-------------------------------------------------------------------------
smbd |HRTIMER |1.563 |1.563 |40666.379
irqbalance |HRTIMER |0.842 |2.484 |40670.231
......
vi |HRTIMER |0.123 |0.123 |40637.065
events/1 |TIMER |168.420 |1008.000 |40677.006
events/0 |TIMER |87.759 |1008.000 |40618.009
......
main |ITIMER_PROF |0.000 |0.000 |40661.023
main |ITIMER_VIRTUAL |0.000 |0.000 |40642.829
main |ITIMER_REAL |0.133 |0.133 |40622.731

- show timer function runtime:
#perf timer report --print-runtime
Timer Function Runtime List
[ Abbreviations: Avg = average; func = function; rt = runtime; ts = timestamp ]
-------------------------------------------------------------------------------
Timer | Type |Avg-rt ms|Max-rt ms| Max-rt-func | Max-rt-ts s
-------------------------------------------------------------------------------
smbd |HRTIMER|0.020 |0.020 |hrtimer_wakeup |40666.379
irqbalance |HRTIMER|0.012 |0.020 |hrtimer_wakeup |40670.231
......
events/1 |TIMER |0.009 |0.017 |delayed_work_timer_fn |40646.090
events/0 |TIMER |0.009 |0.091 |delayed_work_timer_fn |40651.105

- you can use '--print-lat' and '--print-runtime' at the same time:
#perf timer report --print-runtime --print-lat

Timer Latency List
[ Abbreviations: Avg = average; lat = latency; ts = timestamp ]
-------------------------------------------------------------------------
Timer | TYPE | Avg-lat ms| Max-lat ms| Max-lat-ts s
-------------------------------------------------------------------------
smbd |HRTIMER |1.563 |1.563 |40666.379
irqbalance |HRTIMER |0.842 |2.484 |40670.231
......
Timer Function Runtime List
[ Abbreviations: Avg = average; func = function; rt = runtime; ts = timestamp ]
-------------------------------------------------------------------------------
Timer | Type |Avg-rt ms|Max-rt ms| Max-rt-func | Max-rt-ts s
-------------------------------------------------------------------------------
smbd |HRTIMER|0.020 |0.020 |hrtimer_wakeup |40666.379
irqbalance |HRTIMER|0.012 |0.020 |hrtimer_wakeup |40670.231

- Select timer type which you are interesting:
#perf timer report --print-lat --type timer
Timer Latency List
[ Abbreviations: Avg = average; lat = latency; ts = timestamp ]
-------------------------------------------------------------------------
Timer | TYPE | Avg-lat ms| Max-lat ms| Max-lat-ts s
-------------------------------------------------------------------------
events/1 |TIMER |168.420 |1008.000 |40677.006
events/0 |TIMER |87.759 |1008.000 |40618.009
events/1 |TIMER |57.000 |153.000 |40634.571

You can specify more types, such as: '--type timer,hrtimer'