[deliverable/linux.git] / tools / perf / Documentation / examples.txt


		------------------------------
		****** perf by examples ******
		------------------------------

[ From an e-mail by Ingo Molnar, http://lkml.org/lkml/2009/8/4/346 ]


First, discovery/enumeration of available counters can be done via
'perf list':

titan:~> perf list
  [...]
  kmem:kmalloc                             [Tracepoint event]
  kmem:kmem_cache_alloc                    [Tracepoint event]
  kmem:kmalloc_node                        [Tracepoint event]
  kmem:kmem_cache_alloc_node               [Tracepoint event]
  kmem:kfree                               [Tracepoint event]
  kmem:kmem_cache_free                     [Tracepoint event]
  kmem:mm_page_free                        [Tracepoint event]
  kmem:mm_page_free_batched                [Tracepoint event]
  kmem:mm_page_alloc                       [Tracepoint event]
  kmem:mm_page_alloc_zone_locked           [Tracepoint event]
  kmem:mm_page_pcpu_drain                  [Tracepoint event]
  kmem:mm_page_alloc_extfrag               [Tracepoint event]

Then any (or all) of the above event sources can be activated and
measured. For example the page alloc/free properties of a 'hackbench
run' are:

 titan:~> perf stat -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc
 -e kmem:mm_page_free_batched -e kmem:mm_page_free ./hackbench 10
 Time: 0.575

 Performance counter stats for './hackbench 10':

          13857  kmem:mm_page_pcpu_drain
          27576  kmem:mm_page_alloc
           6025  kmem:mm_page_free_batched
          20934  kmem:mm_page_free

    0.613972165  seconds time elapsed

You can observe the statistical properties as well, by using the
'repeat the workload N times' feature of perf stat:

 titan:~> perf stat --repeat 5 -e kmem:mm_page_pcpu_drain -e
   kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
   kmem:mm_page_free ./hackbench 10
 Time: 0.627
 Time: 0.644
 Time: 0.564
 Time: 0.559
 Time: 0.626

 Performance counter stats for './hackbench 10' (5 runs):

          12920  kmem:mm_page_pcpu_drain    ( +-   3.359% )
          25035  kmem:mm_page_alloc         ( +-   3.783% )
           6104  kmem:mm_page_free_batched  ( +-   0.934% )
          18376  kmem:mm_page_free	    ( +-   4.941% )

    0.643954516  seconds time elapsed   ( +-   2.363% )

Furthermore, these tracepoints can be used to sample the workload as
well. For example the page allocations done by a 'git gc' can be
captured the following way:

 titan:~/git> perf record -e kmem:mm_page_alloc -c 1 ./git gc
 Counting objects: 1148, done.
 Delta compression using up to 2 threads.
 Compressing objects: 100% (450/450), done.
 Writing objects: 100% (1148/1148), done.
 Total 1148 (delta 690), reused 1148 (delta 690)
 [ perf record: Captured and wrote 0.267 MB perf.data (~11679 samples) ]

To check which functions generated page allocations:

 titan:~/git> perf report
 # Samples: 10646
 #
 # Overhead          Command               Shared Object
 # ........  ...............  ..........................
 #
    23.57%       git-repack  /lib64/libc-2.5.so
    21.81%              git  /lib64/libc-2.5.so
    14.59%              git  ./git
    11.79%       git-repack  ./git
     7.12%              git  /lib64/ld-2.5.so
     3.16%       git-repack  /lib64/libpthread-2.5.so
     2.09%       git-repack  /bin/bash
     1.97%               rm  /lib64/libc-2.5.so
     1.39%               mv  /lib64/ld-2.5.so
     1.37%               mv  /lib64/libc-2.5.so
     1.12%       git-repack  /lib64/ld-2.5.so
     0.95%               rm  /lib64/ld-2.5.so
     0.90%  git-update-serv  /lib64/libc-2.5.so
     0.73%  git-update-serv  /lib64/ld-2.5.so
     0.68%             perf  /lib64/libpthread-2.5.so
     0.64%       git-repack  /usr/lib64/libz.so.1.2.3

Or to see it on a more finegrained level:

titan:~/git> perf report --sort comm,dso,symbol
# Samples: 10646
#
# Overhead          Command               Shared Object  Symbol
# ........  ...............  ..........................  ......
#
     9.35%       git-repack  ./git                       [.] insert_obj_hash
     9.12%              git  ./git                       [.] insert_obj_hash
     7.31%              git  /lib64/libc-2.5.so          [.] memcpy
     6.34%       git-repack  /lib64/libc-2.5.so          [.] _int_malloc
     6.24%       git-repack  /lib64/libc-2.5.so          [.] memcpy
     5.82%       git-repack  /lib64/libc-2.5.so          [.] __GI___fork
     5.47%              git  /lib64/libc-2.5.so          [.] _int_malloc
     2.99%              git  /lib64/libc-2.5.so          [.] memset

Furthermore, call-graph sampling can be done too, of page
allocations - to see precisely what kind of page allocations there
are:

 titan:~/git> perf record -g -e kmem:mm_page_alloc -c 1 ./git gc
 Counting objects: 1148, done.
 Delta compression using up to 2 threads.
 Compressing objects: 100% (450/450), done.
 Writing objects: 100% (1148/1148), done.
 Total 1148 (delta 690), reused 1148 (delta 690)
 [ perf record: Captured and wrote 0.963 MB perf.data (~42069 samples) ]

 titan:~/git> perf report -g
 # Samples: 10686
 #
 # Overhead          Command               Shared Object
 # ........  ...............  ..........................
 #
    23.25%       git-repack  /lib64/libc-2.5.so
                |
                |--50.00%-- _int_free
                |
                |--37.50%-- __GI___fork
                |          make_child
                |
                |--12.50%-- ptmalloc_unlock_all2
                |          make_child
                |
                 --6.25%-- __GI_strcpy
    21.61%              git  /lib64/libc-2.5.so
                |
                |--30.00%-- __GI_read
                |          |
                |           --83.33%-- git_config_from_file
                |                     git_config
                |                     |
   [...]

Or you can observe the whole system's page allocations for 10
seconds:

titan:~/git> perf stat -a -e kmem:mm_page_pcpu_drain -e
kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
kmem:mm_page_free sleep 10

 Performance counter stats for 'sleep 10':

         171585  kmem:mm_page_pcpu_drain
         322114  kmem:mm_page_alloc
          73623  kmem:mm_page_free_batched
         254115  kmem:mm_page_free

   10.000591410  seconds time elapsed

Or observe how fluctuating the page allocations are, via statistical
analysis done over ten 1-second intervals:

 titan:~/git> perf stat --repeat 10 -a -e kmem:mm_page_pcpu_drain -e
   kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
   kmem:mm_page_free sleep 1

 Performance counter stats for 'sleep 1' (10 runs):

          17254  kmem:mm_page_pcpu_drain    ( +-   3.709% )
          34394  kmem:mm_page_alloc         ( +-   4.617% )
           7509  kmem:mm_page_free_batched  ( +-   4.820% )
          25653  kmem:mm_page_free	    ( +-   3.672% )

    1.058135029  seconds time elapsed   ( +-   3.089% )

Or you can annotate the recorded 'git gc' run on a per symbol basis
and check which instructions/source-code generated page allocations:

 titan:~/git> perf annotate __GI___fork
 ------------------------------------------------
  Percent |      Source code & Disassembly of libc-2.5.so
 ------------------------------------------------
          :
          :
          :      Disassembly of section .plt:
          :      Disassembly of section .text:
          :
          :      00000031a2e95560 <__fork>:
 [...]
     0.00 :        31a2e95602:   b8 38 00 00 00          mov    $0x38,%eax
     0.00 :        31a2e95607:   0f 05                   syscall
    83.42 :        31a2e95609:   48 3d 00 f0 ff ff       cmp    $0xfffffffffffff000,%rax
     0.00 :        31a2e9560f:   0f 87 4d 01 00 00       ja     31a2e95762 <__fork+0x202>
     0.00 :        31a2e95615:   85 c0                   test   %eax,%eax

( this shows that 83.42% of __GI___fork's page allocations come from
  the 0x38 system call it performs. )

etc. etc. - a lot more is possible. I could list a dozen of
other different usecases straight away - neither of which is
possible via /proc/vmstat.

/proc/vmstat is not in the same league really, in terms of
expressive power of system analysis and performance
analysis.

All that the above results needed were those new tracepoints
in include/tracing/events/kmem.h.

	Ingo
Commit	Line	Data
c24b5133 CM	1
	2	------------------------------
	3	**** perf by examples ****
	4	------------------------------
	5
	6	[ From an e-mail by Ingo Molnar, http://lkml.org/lkml/2009/8/4/346 ]
	7
	8
	9	First, discovery/enumeration of available counters can be done via
	10	'perf list':
	11
	12	titan:~> perf list
	13	[...]
	14	kmem:kmalloc [Tracepoint event]
	15	kmem:kmem_cache_alloc [Tracepoint event]
	16	kmem:kmalloc_node [Tracepoint event]
	17	kmem:kmem_cache_alloc_node [Tracepoint event]
	18	kmem:kfree [Tracepoint event]
	19	kmem:kmem_cache_free [Tracepoint event]
90a5d5af KK	20	kmem:mm_page_free [Tracepoint event]
90a5d5af KK	21	kmem:mm_page_free_batched [Tracepoint event]
c24b5133 CM	22	kmem:mm_page_alloc [Tracepoint event]
	23	kmem:mm_page_alloc_zone_locked [Tracepoint event]
	24	kmem:mm_page_pcpu_drain [Tracepoint event]
	25	kmem:mm_page_alloc_extfrag [Tracepoint event]
	26
	27	Then any (or all) of the above event sources can be activated and
	28	measured. For example the page alloc/free properties of a 'hackbench
	29	run' are:
	30
	31	titan:~> perf stat -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc
90a5d5af	32	-e kmem:mm_page_free_batched -e kmem:mm_page_free ./hackbench 10
c24b5133 CM	33	Time: 0.575
	34
	35	Performance counter stats for './hackbench 10':
	36
	37	13857 kmem:mm_page_pcpu_drain
	38	27576 kmem:mm_page_alloc
90a5d5af KK	39	6025 kmem:mm_page_free_batched
90a5d5af KK	40	20934 kmem:mm_page_free
c24b5133 CM	41
	42	0.613972165 seconds time elapsed
	43
	44	You can observe the statistical properties as well, by using the
	45	'repeat the workload N times' feature of perf stat:
	46
	47	titan:~> perf stat --repeat 5 -e kmem:mm_page_pcpu_drain -e
90a5d5af KK	48	kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
90a5d5af KK	49	kmem:mm_page_free ./hackbench 10
c24b5133 CM	50	Time: 0.627
	51	Time: 0.644
	52	Time: 0.564
	53	Time: 0.559
	54	Time: 0.626
	55
	56	Performance counter stats for './hackbench 10' (5 runs):
	57
	58	12920 kmem:mm_page_pcpu_drain ( +- 3.359% )
	59	25035 kmem:mm_page_alloc ( +- 3.783% )
90a5d5af KK	60	6104 kmem:mm_page_free_batched ( +- 0.934% )
90a5d5af KK	61	18376 kmem:mm_page_free ( +- 4.941% )
c24b5133 CM	62
	63	0.643954516 seconds time elapsed ( +- 2.363% )
	64
	65	Furthermore, these tracepoints can be used to sample the workload as
	66	well. For example the page allocations done by a 'git gc' can be
	67	captured the following way:
	68
4a4d371a	69	titan:~/git> perf record -e kmem:mm_page_alloc -c 1 ./git gc
c24b5133 CM	70	Counting objects: 1148, done.
	71	Delta compression using up to 2 threads.
	72	Compressing objects: 100% (450/450), done.
	73	Writing objects: 100% (1148/1148), done.
	74	Total 1148 (delta 690), reused 1148 (delta 690)
	75	[ perf record: Captured and wrote 0.267 MB perf.data (~11679 samples) ]
	76
	77	To check which functions generated page allocations:
	78
	79	titan:~/git> perf report
	80	# Samples: 10646
	81	#
	82	# Overhead Command Shared Object
	83	# ........ ............... ..........................
	84	#
	85	23.57% git-repack /lib64/libc-2.5.so
	86	21.81% git /lib64/libc-2.5.so
	87	14.59% git ./git
	88	11.79% git-repack ./git
	89	7.12% git /lib64/ld-2.5.so
	90	3.16% git-repack /lib64/libpthread-2.5.so
	91	2.09% git-repack /bin/bash
	92	1.97% rm /lib64/libc-2.5.so
	93	1.39% mv /lib64/ld-2.5.so
	94	1.37% mv /lib64/libc-2.5.so
	95	1.12% git-repack /lib64/ld-2.5.so
	96	0.95% rm /lib64/ld-2.5.so
	97	0.90% git-update-serv /lib64/libc-2.5.so
	98	0.73% git-update-serv /lib64/ld-2.5.so
	99	0.68% perf /lib64/libpthread-2.5.so
	100	0.64% git-repack /usr/lib64/libz.so.1.2.3
	101
	102	Or to see it on a more finegrained level:
	103
	104	titan:~/git> perf report --sort comm,dso,symbol
	105	# Samples: 10646
	106	#
	107	# Overhead Command Shared Object Symbol
	108	# ........ ............... .......................... ......
	109	#
	110	9.35% git-repack ./git [.] insert_obj_hash
	111	9.12% git ./git [.] insert_obj_hash
	112	7.31% git /lib64/libc-2.5.so [.] memcpy
	113	6.34% git-repack /lib64/libc-2.5.so [.] _int_malloc
	114	6.24% git-repack /lib64/libc-2.5.so [.] memcpy
	115	5.82% git-repack /lib64/libc-2.5.so [.] __GI___fork
	116	5.47% git /lib64/libc-2.5.so [.] _int_malloc
	117	2.99% git /lib64/libc-2.5.so [.] memset
	118
	119	Furthermore, call-graph sampling can be done too, of page
	120	allocations - to see precisely what kind of page allocations there
	121	are:
	122
4a4d371a	123	titan:~/git> perf record -g -e kmem:mm_page_alloc -c 1 ./git gc
c24b5133 CM	124	Counting objects: 1148, done.
	125	Delta compression using up to 2 threads.
	126	Compressing objects: 100% (450/450), done.
	127	Writing objects: 100% (1148/1148), done.
	128	Total 1148 (delta 690), reused 1148 (delta 690)
	129	[ perf record: Captured and wrote 0.963 MB perf.data (~42069 samples) ]
	130
	131	titan:~/git> perf report -g
	132	# Samples: 10686
	133	#
	134	# Overhead Command Shared Object
	135	# ........ ............... ..........................
	136	#
	137	23.25% git-repack /lib64/libc-2.5.so
	138	\|
	139	\|--50.00%-- _int_free
	140	\|
	141	\|--37.50%-- __GI___fork
	142	\| make_child
	143	\|
	144	\|--12.50%-- ptmalloc_unlock_all2
	145	\| make_child
	146	\|
	147	--6.25%-- __GI_strcpy
	148	21.61% git /lib64/libc-2.5.so
	149	\|
	150	\|--30.00%-- __GI_read
	151	\| \|
	152	\| --83.33%-- git_config_from_file
	153	\| git_config
	154	\| \|
	155	[...]
	156
	157	Or you can observe the whole system's page allocations for 10
	158	seconds:
	159
	160	titan:~/git> perf stat -a -e kmem:mm_page_pcpu_drain -e
90a5d5af KK	161	kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
90a5d5af KK	162	kmem:mm_page_free sleep 10
c24b5133 CM	163
	164	Performance counter stats for 'sleep 10':
	165
	166	171585 kmem:mm_page_pcpu_drain
	167	322114 kmem:mm_page_alloc
90a5d5af KK	168	73623 kmem:mm_page_free_batched
90a5d5af KK	169	254115 kmem:mm_page_free
c24b5133 CM	170
	171	10.000591410 seconds time elapsed
	172
	173	Or observe how fluctuating the page allocations are, via statistical
	174	analysis done over ten 1-second intervals:
	175
	176	titan:~/git> perf stat --repeat 10 -a -e kmem:mm_page_pcpu_drain -e
90a5d5af KK	177	kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
90a5d5af KK	178	kmem:mm_page_free sleep 1
c24b5133 CM	179
	180	Performance counter stats for 'sleep 1' (10 runs):
	181
	182	17254 kmem:mm_page_pcpu_drain ( +- 3.709% )
	183	34394 kmem:mm_page_alloc ( +- 4.617% )
90a5d5af KK	184	7509 kmem:mm_page_free_batched ( +- 4.820% )
90a5d5af KK	185	25653 kmem:mm_page_free ( +- 3.672% )
c24b5133 CM	186
	187	1.058135029 seconds time elapsed ( +- 3.089% )
	188
	189	Or you can annotate the recorded 'git gc' run on a per symbol basis
	190	and check which instructions/source-code generated page allocations:
	191
	192	titan:~/git> perf annotate __GI___fork
	193	------------------------------------------------
	194	Percent \| Source code & Disassembly of libc-2.5.so
	195	------------------------------------------------
	196	:
	197	:
	198	: Disassembly of section .plt:
	199	: Disassembly of section .text:
	200	:
	201	: 00000031a2e95560 <__fork>:
	202	[...]
	203	0.00 : 31a2e95602: b8 38 00 00 00 mov $0x38,%eax
	204	0.00 : 31a2e95607: 0f 05 syscall
	205	83.42 : 31a2e95609: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
	206	0.00 : 31a2e9560f: 0f 87 4d 01 00 00 ja 31a2e95762 <__fork+0x202>
	207	0.00 : 31a2e95615: 85 c0 test %eax,%eax
	208
	209	( this shows that 83.42% of __GI___fork's page allocations come from
	210	the 0x38 system call it performs. )
	211
	212	etc. etc. - a lot more is possible. I could list a dozen of
	213	other different usecases straight away - neither of which is
	214	possible via /proc/vmstat.
	215
	216	/proc/vmstat is not in the same league really, in terms of
	217	expressive power of system analysis and performance
	218	analysis.
	219
	220	All that the above results needed were those new tracepoints
	221	in include/tracing/events/kmem.h.
	222
	223	Ingo
	224
	225