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

[Xiao Guangrong]

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'

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/