| |
| ------------------------------ |
| ****** 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 |
| |
| |
