0001
0002 ------------------------------
0003 ****** perf by examples ******
0004 ------------------------------
0005
0006 [ From an e-mail by Ingo Molnar, https://lore.kernel.org/lkml/20090804195717.GA5998@elte.hu ]
0007
0008
0009 First, discovery/enumeration of available counters can be done via
0010 'perf list':
0011
0012 titan:~> perf list
0013 [...]
0014 kmem:kmalloc [Tracepoint event]
0015 kmem:kmem_cache_alloc [Tracepoint event]
0016 kmem:kmalloc_node [Tracepoint event]
0017 kmem:kmem_cache_alloc_node [Tracepoint event]
0018 kmem:kfree [Tracepoint event]
0019 kmem:kmem_cache_free [Tracepoint event]
0020 kmem:mm_page_free [Tracepoint event]
0021 kmem:mm_page_free_batched [Tracepoint event]
0022 kmem:mm_page_alloc [Tracepoint event]
0023 kmem:mm_page_alloc_zone_locked [Tracepoint event]
0024 kmem:mm_page_pcpu_drain [Tracepoint event]
0025 kmem:mm_page_alloc_extfrag [Tracepoint event]
0026
0027 Then any (or all) of the above event sources can be activated and
0028 measured. For example the page alloc/free properties of a 'hackbench
0029 run' are:
0030
0031 titan:~> perf stat -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc
0032 -e kmem:mm_page_free_batched -e kmem:mm_page_free ./hackbench 10
0033 Time: 0.575
0034
0035 Performance counter stats for './hackbench 10':
0036
0037 13857 kmem:mm_page_pcpu_drain
0038 27576 kmem:mm_page_alloc
0039 6025 kmem:mm_page_free_batched
0040 20934 kmem:mm_page_free
0041
0042 0.613972165 seconds time elapsed
0043
0044 You can observe the statistical properties as well, by using the
0045 'repeat the workload N times' feature of perf stat:
0046
0047 titan:~> perf stat --repeat 5 -e kmem:mm_page_pcpu_drain -e
0048 kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
0049 kmem:mm_page_free ./hackbench 10
0050 Time: 0.627
0051 Time: 0.644
0052 Time: 0.564
0053 Time: 0.559
0054 Time: 0.626
0055
0056 Performance counter stats for './hackbench 10' (5 runs):
0057
0058 12920 kmem:mm_page_pcpu_drain ( +- 3.359% )
0059 25035 kmem:mm_page_alloc ( +- 3.783% )
0060 6104 kmem:mm_page_free_batched ( +- 0.934% )
0061 18376 kmem:mm_page_free ( +- 4.941% )
0062
0063 0.643954516 seconds time elapsed ( +- 2.363% )
0064
0065 Furthermore, these tracepoints can be used to sample the workload as
0066 well. For example the page allocations done by a 'git gc' can be
0067 captured the following way:
0068
0069 titan:~/git> perf record -e kmem:mm_page_alloc -c 1 ./git gc
0070 Counting objects: 1148, done.
0071 Delta compression using up to 2 threads.
0072 Compressing objects: 100% (450/450), done.
0073 Writing objects: 100% (1148/1148), done.
0074 Total 1148 (delta 690), reused 1148 (delta 690)
0075 [ perf record: Captured and wrote 0.267 MB perf.data (~11679 samples) ]
0076
0077 To check which functions generated page allocations:
0078
0079 titan:~/git> perf report
0080 # Samples: 10646
0081 #
0082 # Overhead Command Shared Object
0083 # ........ ............... ..........................
0084 #
0085 23.57% git-repack /lib64/libc-2.5.so
0086 21.81% git /lib64/libc-2.5.so
0087 14.59% git ./git
0088 11.79% git-repack ./git
0089 7.12% git /lib64/ld-2.5.so
0090 3.16% git-repack /lib64/libpthread-2.5.so
0091 2.09% git-repack /bin/bash
0092 1.97% rm /lib64/libc-2.5.so
0093 1.39% mv /lib64/ld-2.5.so
0094 1.37% mv /lib64/libc-2.5.so
0095 1.12% git-repack /lib64/ld-2.5.so
0096 0.95% rm /lib64/ld-2.5.so
0097 0.90% git-update-serv /lib64/libc-2.5.so
0098 0.73% git-update-serv /lib64/ld-2.5.so
0099 0.68% perf /lib64/libpthread-2.5.so
0100 0.64% git-repack /usr/lib64/libz.so.1.2.3
0101
0102 Or to see it on a more finegrained level:
0103
0104 titan:~/git> perf report --sort comm,dso,symbol
0105 # Samples: 10646
0106 #
0107 # Overhead Command Shared Object Symbol
0108 # ........ ............... .......................... ......
0109 #
0110 9.35% git-repack ./git [.] insert_obj_hash
0111 9.12% git ./git [.] insert_obj_hash
0112 7.31% git /lib64/libc-2.5.so [.] memcpy
0113 6.34% git-repack /lib64/libc-2.5.so [.] _int_malloc
0114 6.24% git-repack /lib64/libc-2.5.so [.] memcpy
0115 5.82% git-repack /lib64/libc-2.5.so [.] __GI___fork
0116 5.47% git /lib64/libc-2.5.so [.] _int_malloc
0117 2.99% git /lib64/libc-2.5.so [.] memset
0118
0119 Furthermore, call-graph sampling can be done too, of page
0120 allocations - to see precisely what kind of page allocations there
0121 are:
0122
0123 titan:~/git> perf record -g -e kmem:mm_page_alloc -c 1 ./git gc
0124 Counting objects: 1148, done.
0125 Delta compression using up to 2 threads.
0126 Compressing objects: 100% (450/450), done.
0127 Writing objects: 100% (1148/1148), done.
0128 Total 1148 (delta 690), reused 1148 (delta 690)
0129 [ perf record: Captured and wrote 0.963 MB perf.data (~42069 samples) ]
0130
0131 titan:~/git> perf report -g
0132 # Samples: 10686
0133 #
0134 # Overhead Command Shared Object
0135 # ........ ............... ..........................
0136 #
0137 23.25% git-repack /lib64/libc-2.5.so
0138 |
0139 |--50.00%-- _int_free
0140 |
0141 |--37.50%-- __GI___fork
0142 | make_child
0143 |
0144 |--12.50%-- ptmalloc_unlock_all2
0145 | make_child
0146 |
0147 --6.25%-- __GI_strcpy
0148 21.61% git /lib64/libc-2.5.so
0149 |
0150 |--30.00%-- __GI_read
0151 | |
0152 | --83.33%-- git_config_from_file
0153 | git_config
0154 | |
0155 [...]
0156
0157 Or you can observe the whole system's page allocations for 10
0158 seconds:
0159
0160 titan:~/git> perf stat -a -e kmem:mm_page_pcpu_drain -e
0161 kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
0162 kmem:mm_page_free sleep 10
0163
0164 Performance counter stats for 'sleep 10':
0165
0166 171585 kmem:mm_page_pcpu_drain
0167 322114 kmem:mm_page_alloc
0168 73623 kmem:mm_page_free_batched
0169 254115 kmem:mm_page_free
0170
0171 10.000591410 seconds time elapsed
0172
0173 Or observe how fluctuating the page allocations are, via statistical
0174 analysis done over ten 1-second intervals:
0175
0176 titan:~/git> perf stat --repeat 10 -a -e kmem:mm_page_pcpu_drain -e
0177 kmem:mm_page_alloc -e kmem:mm_page_free_batched -e
0178 kmem:mm_page_free sleep 1
0179
0180 Performance counter stats for 'sleep 1' (10 runs):
0181
0182 17254 kmem:mm_page_pcpu_drain ( +- 3.709% )
0183 34394 kmem:mm_page_alloc ( +- 4.617% )
0184 7509 kmem:mm_page_free_batched ( +- 4.820% )
0185 25653 kmem:mm_page_free ( +- 3.672% )
0186
0187 1.058135029 seconds time elapsed ( +- 3.089% )
0188
0189 Or you can annotate the recorded 'git gc' run on a per symbol basis
0190 and check which instructions/source-code generated page allocations:
0191
0192 titan:~/git> perf annotate __GI___fork
0193 ------------------------------------------------
0194 Percent | Source code & Disassembly of libc-2.5.so
0195 ------------------------------------------------
0196 :
0197 :
0198 : Disassembly of section .plt:
0199 : Disassembly of section .text:
0200 :
0201 : 00000031a2e95560 <__fork>:
0202 [...]
0203 0.00 : 31a2e95602: b8 38 00 00 00 mov $0x38,%eax
0204 0.00 : 31a2e95607: 0f 05 syscall
0205 83.42 : 31a2e95609: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
0206 0.00 : 31a2e9560f: 0f 87 4d 01 00 00 ja 31a2e95762 <__fork+0x202>
0207 0.00 : 31a2e95615: 85 c0 test %eax,%eax
0208
0209 ( this shows that 83.42% of __GI___fork's page allocations come from
0210 the 0x38 system call it performs. )
0211
0212 etc. etc. - a lot more is possible. I could list a dozen of
0213 other different usecases straight away - neither of which is
0214 possible via /proc/vmstat.
0215
0216 /proc/vmstat is not in the same league really, in terms of
0217 expressive power of system analysis and performance
0218 analysis.
0219
0220 All that the above results needed were those new tracepoints
0221 in include/tracing/events/kmem.h.
0222
0223 Ingo
0224
0225
