Home
Reading
Searching
Subscribe
Sponsors
Statistics
Posting
Contact
Spam
Lists
Links
About
Hosting
Filtering
Features Download
Marketing
Archives
FAQ
Blog
 
Gmane
From: Xiao Guangrong <xiaoguangrong <at> cn.fujitsu.com>
Subject: [PATCH v2 0/5] perf_event: introduce 'perf timer' to analyze timer's behavior
Newsgroups: gmane.linux.kernel
Date: Tuesday 22nd December 2009 13:00:01 UTC (over 6 years ago)
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'
 
CD: 3ms