summaryrefslogtreecommitdiffstats
path: root/documentation/profile-manual
diff options
context:
space:
mode:
authorNicolas Dechesne <nicolas.dechesne@linaro.org>2020-09-15 11:21:58 +0200
committerRichard Purdie <richard.purdie@linuxfoundation.org>2020-09-17 10:09:35 +0100
commitc526975d28102905d4eddc1cf3520a71f0971ea9 (patch)
treee6d218ffe47ea24259103e06b7cb3cd14ee0ac5f /documentation/profile-manual
parent9f0a31c6073fc9832a5119875b1a4a1032e525eb (diff)
downloadpoky-c526975d28102905d4eddc1cf3520a71f0971ea9.tar.gz
sphinx: profile-manual: convert profile-manual
Last round of manual fixes for remaining links and conversion problems left after the automatic conversion. (From yocto-docs rev: 071bca4573bc8c60aef1d89896d6536867fe46e5) Signed-off-by: Nicolas Dechesne <nicolas.dechesne@linaro.org> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Diffstat (limited to 'documentation/profile-manual')
-rw-r--r--documentation/profile-manual/profile-manual-arch.rst3
-rw-r--r--documentation/profile-manual/profile-manual-examples.rst2
-rw-r--r--documentation/profile-manual/profile-manual-intro.rst40
-rw-r--r--documentation/profile-manual/profile-manual-usage.rst2720
4 files changed, 1657 insertions, 1108 deletions
diff --git a/documentation/profile-manual/profile-manual-arch.rst b/documentation/profile-manual/profile-manual-arch.rst
index 74355a5ab9..9e1e400e42 100644
--- a/documentation/profile-manual/profile-manual-arch.rst
+++ b/documentation/profile-manual/profile-manual-arch.rst
@@ -22,9 +22,8 @@ has started to converge on a 'core' set of underlying mechanisms:
22- the perf_events subsystem 22- the perf_events subsystem
23- debugfs 23- debugfs
24 24
25.. container:: informalexample 25.. admonition:: Tying it Together
26 26
27 Tying it Together:
28 Rather than enumerating here how each tool makes use of these common 27 Rather than enumerating here how each tool makes use of these common
29 mechanisms, textboxes like this will make note of the specific usages 28 mechanisms, textboxes like this will make note of the specific usages
30 in each tool as they come up in the course of the text. 29 in each tool as they come up in the course of the text.
diff --git a/documentation/profile-manual/profile-manual-examples.rst b/documentation/profile-manual/profile-manual-examples.rst
index 0787394ba1..32ccd37b88 100644
--- a/documentation/profile-manual/profile-manual-examples.rst
+++ b/documentation/profile-manual/profile-manual-examples.rst
@@ -4,6 +4,8 @@
4Real-World Examples 4Real-World Examples
5******************* 5*******************
6 6
7|
8
7This chapter contains real-world examples. 9This chapter contains real-world examples.
8 10
9Slow Write Speed on Live Images 11Slow Write Speed on Live Images
diff --git a/documentation/profile-manual/profile-manual-intro.rst b/documentation/profile-manual/profile-manual-intro.rst
index 5d51df74dc..994b1c5086 100644
--- a/documentation/profile-manual/profile-manual-intro.rst
+++ b/documentation/profile-manual/profile-manual-intro.rst
@@ -38,12 +38,19 @@ General Setup
38Most of the tools are available only in 'sdk' images or in images built 38Most of the tools are available only in 'sdk' images or in images built
39after adding 'tools-profile' to your local.conf. So, in order to be able 39after adding 'tools-profile' to your local.conf. So, in order to be able
40to access all of the tools described here, please first build and boot 40to access all of the tools described here, please first build and boot
41an 'sdk' image e.g. $ bitbake core-image-sato-sdk or alternatively by 41an 'sdk' image e.g. ::
42adding 'tools-profile' to the EXTRA_IMAGE_FEATURES line in your 42
43local.conf: EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile" If you 43 $ bitbake core-image-sato-sdk
44use the 'tools-profile' method, you don't need to build an sdk image - 44
45the tracing and profiling tools will be included in non-sdk images as 45or alternatively by adding 'tools-profile' to the EXTRA_IMAGE_FEATURES line in
46well e.g.: $ bitbake core-image-sato 46your local.conf: ::
47
48 EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile"
49
50If you use the 'tools-profile' method, you don't need to build an sdk image -
51the tracing and profiling tools will be included in non-sdk images as well e.g.: ::
52
53 $ bitbake core-image-sato
47 54
48.. note:: 55.. note::
49 56
@@ -52,18 +59,21 @@ well e.g.: $ bitbake core-image-sato
52 59
53 You can prevent that by setting the 60 You can prevent that by setting the
54 :term:`INHIBIT_PACKAGE_STRIP` 61 :term:`INHIBIT_PACKAGE_STRIP`
55 variable to "1" in your ``local.conf`` when you build the image: 62 variable to "1" in your ``local.conf`` when you build the image: ::
56 63
57INHIBIT_PACKAGE_STRIP = "1" The above setting will noticeably increase 64 INHIBIT_PACKAGE_STRIP = "1"
58the size of your image. 65
66 The above setting will noticeably increase the size of your image.
59 67
60If you've already built a stripped image, you can generate debug 68If you've already built a stripped image, you can generate debug
61packages (xxx-dbg) which you can manually install as needed. 69packages (xxx-dbg) which you can manually install as needed.
62 70
63To generate debug info for packages, you can add dbg-pkgs to 71To generate debug info for packages, you can add dbg-pkgs to
64EXTRA_IMAGE_FEATURES in local.conf. For example: EXTRA_IMAGE_FEATURES = 72EXTRA_IMAGE_FEATURES in local.conf. For example: ::
65"debug-tweaks tools-profile dbg-pkgs" Additionally, in order to generate 73
66the right type of debuginfo, we also need to set 74 EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile dbg-pkgs"
67:term:`PACKAGE_DEBUG_SPLIT_STYLE` 75
68in the ``local.conf`` file: PACKAGE_DEBUG_SPLIT_STYLE = 76Additionally, in order to generate the right type of debuginfo, we also need to
69'debug-file-directory' 77set :term:`PACKAGE_DEBUG_SPLIT_STYLE` in the ``local.conf`` file: ::
78
79 PACKAGE_DEBUG_SPLIT_STYLE = 'debug-file-directory'
diff --git a/documentation/profile-manual/profile-manual-usage.rst b/documentation/profile-manual/profile-manual-usage.rst
index 1c96a4d7f2..32b04f6ff7 100644
--- a/documentation/profile-manual/profile-manual-usage.rst
+++ b/documentation/profile-manual/profile-manual-usage.rst
@@ -1,9 +1,12 @@
1.. SPDX-License-Identifier: CC-BY-2.0-UK 1.. SPDX-License-Identifier: CC-BY-2.0-UK
2.. highlight:: shell
2 3
3*************************************************************** 4***************************************************************
4Basic Usage (with examples) for each of the Yocto Tracing Tools 5Basic Usage (with examples) for each of the Yocto Tracing Tools
5*************************************************************** 6***************************************************************
6 7
8|
9
7This chapter presents basic usage examples for each of the tracing 10This chapter presents basic usage examples for each of the tracing
8tools. 11tools.
9 12
@@ -42,16 +45,16 @@ the tool itself or in the man pages at
42 45
43.. _perf-setup: 46.. _perf-setup:
44 47
45Setup 48Perf Setup
46----- 49----------
47 50
48For this section, we'll assume you've already performed the basic setup 51For this section, we'll assume you've already performed the basic setup
49outlined in the General Setup section. 52outlined in the ":ref:`profile-manual/profile-manual-intro:General Setup`" section.
50 53
51In particular, you'll get the most mileage out of perf if you profile an 54In particular, you'll get the most mileage out of perf if you profile an
52image built with the following in your ``local.conf`` file: 55image built with the following in your ``local.conf`` file: ::
53:term:`INHIBIT_PACKAGE_STRIP` 56
54= "1" 57 INHIBIT_PACKAGE_STRIP = "1"
55 58
56perf runs on the target system for the most part. You can archive 59perf runs on the target system for the most part. You can archive
57profile data and copy it to the host for analysis, but for the rest of 60profile data and copy it to the host for analysis, but for the rest of
@@ -60,31 +63,42 @@ the perf commands on the target.
60 63
61.. _perf-basic-usage: 64.. _perf-basic-usage:
62 65
63Basic Usage 66Basic Perf Usage
64----------- 67----------------
65 68
66The perf tool is pretty much self-documenting. To remind yourself of the 69The perf tool is pretty much self-documenting. To remind yourself of the
67available commands, simply type 'perf', which will show you basic usage 70available commands, simply type 'perf', which will show you basic usage
68along with the available perf subcommands: root@crownbay:~# perf usage: 71along with the available perf subcommands: ::
69perf [--version] [--help] COMMAND [ARGS] The most commonly used perf 72
70commands are: annotate Read perf.data (created by perf record) and 73 root@crownbay:~# perf
71display annotated code archive Create archive with object files with 74
72build-ids found in perf.data file bench General framework for benchmark 75 usage: perf [--version] [--help] COMMAND [ARGS]
73suites buildid-cache Manage build-id cache. buildid-list List the 76
74buildids in a perf.data file diff Read two perf.data files and display 77 The most commonly used perf commands are:
75the differential profile evlist List the event names in a perf.data file 78 annotate Read perf.data (created by perf record) and display annotated code
76inject Filter to augment the events stream with additional information 79 archive Create archive with object files with build-ids found in perf.data file
77kmem Tool to trace/measure kernel memory(slab) properties kvm Tool to 80 bench General framework for benchmark suites
78trace/measure kvm guest os list List all symbolic event types lock 81 buildid-cache Manage build-id cache.
79Analyze lock events probe Define new dynamic tracepoints record Run a 82 buildid-list List the buildids in a perf.data file
80command and record its profile into perf.data report Read perf.data 83 diff Read two perf.data files and display the differential profile
81(created by perf record) and display the profile sched Tool to 84 evlist List the event names in a perf.data file
82trace/measure scheduler properties (latencies) script Read perf.data 85 inject Filter to augment the events stream with additional information
83(created by perf record) and display trace output stat Run a command and 86 kmem Tool to trace/measure kernel memory(slab) properties
84gather performance counter statistics test Runs sanity tests. timechart 87 kvm Tool to trace/measure kvm guest os
85Tool to visualize total system behavior during a workload top System 88 list List all symbolic event types
86profiling tool. See 'perf help COMMAND' for more information on a 89 lock Analyze lock events
87specific command. 90 probe Define new dynamic tracepoints
91 record Run a command and record its profile into perf.data
92 report Read perf.data (created by perf record) and display the profile
93 sched Tool to trace/measure scheduler properties (latencies)
94 script Read perf.data (created by perf record) and display trace output
95 stat Run a command and gather performance counter statistics
96 test Runs sanity tests.
97 timechart Tool to visualize total system behavior during a workload
98 top System profiling tool.
99
100 See 'perf help COMMAND' for more information on a specific command.
101
88 102
89Using perf to do Basic Profiling 103Using perf to do Basic Profiling
90~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 104~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@@ -94,25 +108,36 @@ which is a minimally interesting case because it has both file and
94network I/O aspects, and at least in the case of standard Yocto images, 108network I/O aspects, and at least in the case of standard Yocto images,
95it's implemented as part of busybox, so the methods we use to analyze it 109it's implemented as part of busybox, so the methods we use to analyze it
96can be used in a very similar way to the whole host of supported busybox 110can be used in a very similar way to the whole host of supported busybox
97applets in Yocto. root@crownbay:~# rm linux-2.6.19.2.tar.bz2; \\ wget 111applets in Yocto. ::
98http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 112
113 root@crownbay:~# rm linux-2.6.19.2.tar.bz2; \
114 wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
115
99The quickest and easiest way to get some basic overall data about what's 116The quickest and easiest way to get some basic overall data about what's
100going on for a particular workload is to profile it using 'perf stat'. 117going on for a particular workload is to profile it using 'perf stat'.
101'perf stat' basically profiles using a few default counters and displays 118'perf stat' basically profiles using a few default counters and displays
102the summed counts at the end of the run: root@crownbay:~# perf stat wget 119the summed counts at the end of the run: ::
103http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 120
104Connecting to downloads.yoctoproject.org (140.211.169.59:80) 121 root@crownbay:~# perf stat wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
105linux-2.6.19.2.tar.b 100% 122 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
106\|***************************************************\| 41727k 0:00:00 123 linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA
107ETA Performance counter stats for 'wget 124
108http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': 125 Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2':
1094597.223902 task-clock # 0.077 CPUs utilized 23568 context-switches # 126
1100.005 M/sec 68 CPU-migrations # 0.015 K/sec 241 page-faults # 0.052 127 4597.223902 task-clock # 0.077 CPUs utilized
111K/sec 3045817293 cycles # 0.663 GHz <not supported> 128 23568 context-switches # 0.005 M/sec
112stalled-cycles-frontend <not supported> stalled-cycles-backend 858909167 129 68 CPU-migrations # 0.015 K/sec
113instructions # 0.28 insns per cycle 165441165 branches # 35.987 M/sec 130 241 page-faults # 0.052 K/sec
11419550329 branch-misses # 11.82% of all branches 59.836627620 seconds 131 3045817293 cycles # 0.663 GHz
115time elapsed Many times such a simple-minded test doesn't yield much of 132 <not supported> stalled-cycles-frontend
133 <not supported> stalled-cycles-backend
134 858909167 instructions # 0.28 insns per cycle
135 165441165 branches # 35.987 M/sec
136 19550329 branch-misses # 11.82% of all branches
137
138 59.836627620 seconds time elapsed
139
140Many times such a simple-minded test doesn't yield much of
116interest, but sometimes it does (see Real-world Yocto bug (slow 141interest, but sometimes it does (see Real-world Yocto bug (slow
117loop-mounted write speed)). 142loop-mounted write speed)).
118 143
@@ -120,21 +145,32 @@ Also, note that 'perf stat' isn't restricted to a fixed set of counters
120- basically any event listed in the output of 'perf list' can be tallied 145- basically any event listed in the output of 'perf list' can be tallied
121by 'perf stat'. For example, suppose we wanted to see a summary of all 146by 'perf stat'. For example, suppose we wanted to see a summary of all
122the events related to kernel memory allocation/freeing along with cache 147the events related to kernel memory allocation/freeing along with cache
123hits and misses: root@crownbay:~# perf stat -e kmem:\* -e 148hits and misses: ::
124cache-references -e cache-misses wget 149
125http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 150 root@crownbay:~# perf stat -e kmem:* -e cache-references -e cache-misses wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
126Connecting to downloads.yoctoproject.org (140.211.169.59:80) 151 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
127linux-2.6.19.2.tar.b 100% 152 linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA
128\|***************************************************\| 41727k 0:00:00 153
129ETA Performance counter stats for 'wget 154 Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2':
130http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': 155
1315566 kmem:kmalloc 125517 kmem:kmem_cache_alloc 0 kmem:kmalloc_node 0 156 5566 kmem:kmalloc
132kmem:kmem_cache_alloc_node 34401 kmem:kfree 69920 kmem:kmem_cache_free 157 125517 kmem:kmem_cache_alloc
133133 kmem:mm_page_free 41 kmem:mm_page_free_batched 11502 158 0 kmem:kmalloc_node
134kmem:mm_page_alloc 11375 kmem:mm_page_alloc_zone_locked 0 159 0 kmem:kmem_cache_alloc_node
135kmem:mm_page_pcpu_drain 0 kmem:mm_page_alloc_extfrag 66848602 160 34401 kmem:kfree
136cache-references 2917740 cache-misses # 4.365 % of all cache refs 161 69920 kmem:kmem_cache_free
13744.831023415 seconds time elapsed So 'perf stat' gives us a nice easy 162 133 kmem:mm_page_free
163 41 kmem:mm_page_free_batched
164 11502 kmem:mm_page_alloc
165 11375 kmem:mm_page_alloc_zone_locked
166 0 kmem:mm_page_pcpu_drain
167 0 kmem:mm_page_alloc_extfrag
168 66848602 cache-references
169 2917740 cache-misses # 4.365 % of all cache refs
170
171 44.831023415 seconds time elapsed
172
173So 'perf stat' gives us a nice easy
138way to get a quick overview of what might be happening for a set of 174way to get a quick overview of what might be happening for a set of
139events, but normally we'd need a little more detail in order to 175events, but normally we'd need a little more detail in order to
140understand what's going on in a way that we can act on in a useful way. 176understand what's going on in a way that we can act on in a useful way.
@@ -149,16 +185,21 @@ record', handing it the workload we want to profile (everything after
149'perf record' and any perf options we hand it - here none - will be 185'perf record' and any perf options we hand it - here none - will be
150executed in a new shell). perf collects samples until the process exits 186executed in a new shell). perf collects samples until the process exits
151and records them in a file named 'perf.data' in the current working 187and records them in a file named 'perf.data' in the current working
152directory. root@crownbay:~# perf record wget 188directory. ::
153http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 189
154Connecting to downloads.yoctoproject.org (140.211.169.59:80) 190 root@crownbay:~# perf record wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
155linux-2.6.19.2.tar.b 100% 191
156\|************************************************\| 41727k 0:00:00 ETA 192 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
157[ perf record: Woken up 1 times to write data ] [ perf record: Captured 193 linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA
158and wrote 0.176 MB perf.data (~7700 samples) ] To see the results in a 194 [ perf record: Woken up 1 times to write data ]
195 [ perf record: Captured and wrote 0.176 MB perf.data (~7700 samples) ]
196
197To see the results in a
159'text-based UI' (tui), simply run 'perf report', which will read the 198'text-based UI' (tui), simply run 'perf report', which will read the
160perf.data file in the current working directory and display the results 199perf.data file in the current working directory and display the results
161in an interactive UI: root@crownbay:~# perf report 200in an interactive UI: ::
201
202 root@crownbay:~# perf report
162 203
163.. image:: figures/perf-wget-flat-stripped.png 204.. image:: figures/perf-wget-flat-stripped.png
164 :align: center 205 :align: center
@@ -182,15 +223,16 @@ Before we do that, however, let's try running a different profile, one
182which shows something a little more interesting. The only difference 223which shows something a little more interesting. The only difference
183between the new profile and the previous one is that we'll add the -g 224between the new profile and the previous one is that we'll add the -g
184option, which will record not just the address of a sampled function, 225option, which will record not just the address of a sampled function,
185but the entire callchain to the sampled function as well: 226but the entire callchain to the sampled function as well: ::
186root@crownbay:~# perf record -g wget 227
187http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 228 root@crownbay:~# perf record -g wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
188Connecting to downloads.yoctoproject.org (140.211.169.59:80) 229 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
189linux-2.6.19.2.tar.b 100% 230 linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA
190\|************************************************\| 41727k 0:00:00 ETA 231 [ perf record: Woken up 3 times to write data ]
191[ perf record: Woken up 3 times to write data ] [ perf record: Captured 232 [ perf record: Captured and wrote 0.652 MB perf.data (~28476 samples) ]
192and wrote 0.652 MB perf.data (~28476 samples) ] root@crownbay:~# perf 233
193report 234
235 root@crownbay:~# perf report
194 236
195.. image:: figures/perf-wget-g-copy-to-user-expanded-stripped.png 237.. image:: figures/perf-wget-g-copy-to-user-expanded-stripped.png
196 :align: center 238 :align: center
@@ -206,9 +248,9 @@ into the callchains that feed into that entry. Pressing 'enter' on any
206one of them will expand the callchain (you can also press 'E' to expand 248one of them will expand the callchain (you can also press 'E' to expand
207them all at the same time or 'C' to collapse them all). 249them all at the same time or 'C' to collapse them all).
208 250
209In the screenshot above, we've toggled the \__copy_to_user_ll() entry 251In the screenshot above, we've toggled the ``__copy_to_user_ll()`` entry
210and several subnodes all the way down. This lets us see which callchains 252and several subnodes all the way down. This lets us see which callchains
211contributed to the profiled \__copy_to_user_ll() function which 253contributed to the profiled ``__copy_to_user_ll()`` function which
212contributed 1.77% to the total profile. 254contributed 1.77% to the total profile.
213 255
214As a bit of background explanation for these callchains, think about 256As a bit of background explanation for these callchains, think about
@@ -224,7 +266,7 @@ is the part where the kernel passes the data it's read from the socket
224down to wget i.e. a copy-to-user. 266down to wget i.e. a copy-to-user.
225 267
226Notice also that here there's also a case where the hex value is 268Notice also that here there's also a case where the hex value is
227displayed in the callstack, here in the expanded sys_clock_gettime() 269displayed in the callstack, here in the expanded ``sys_clock_gettime()``
228function. Later we'll see it resolve to a userspace function call in 270function. Later we'll see it resolve to a userspace function call in
229busybox. 271busybox.
230 272
@@ -233,7 +275,7 @@ busybox.
233 275
234The above screenshot shows the other half of the journey for the data - 276The above screenshot shows the other half of the journey for the data -
235from the wget program's userspace buffers to disk. To get the buffers to 277from the wget program's userspace buffers to disk. To get the buffers to
236disk, the wget program issues a write(2), which does a copy-from-user to 278disk, the wget program issues a ``write(2)``, which does a ``copy-from-user`` to
237the kernel, which then takes care via some circuitous path (probably 279the kernel, which then takes care via some circuitous path (probably
238also present somewhere in the profile data), to get it safely to disk. 280also present somewhere in the profile data), to get it safely to disk.
239 281
@@ -257,30 +299,40 @@ busybox binary, which is actually stripped out by the Yocto build
257system. 299system.
258 300
259One way around that is to put the following in your ``local.conf`` file 301One way around that is to put the following in your ``local.conf`` file
260when you build the image: 302when you build the image: ::
261:term:`INHIBIT_PACKAGE_STRIP` 303
262= "1" However, we already have an image with the binaries stripped, so 304 INHIBIT_PACKAGE_STRIP = "1"
305
306However, we already have an image with the binaries stripped, so
263what can we do to get perf to resolve the symbols? Basically we need to 307what can we do to get perf to resolve the symbols? Basically we need to
264install the debuginfo for the busybox package. 308install the debuginfo for the busybox package.
265 309
266To generate the debug info for the packages in the image, we can add 310To generate the debug info for the packages in the image, we can add
267dbg-pkgs to EXTRA_IMAGE_FEATURES in local.conf. For example: 311``dbg-pkgs`` to :term:`EXTRA_IMAGE_FEATURES` in ``local.conf``. For example: ::
268EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile dbg-pkgs" 312
313 EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile dbg-pkgs"
314
269Additionally, in order to generate the type of debuginfo that perf 315Additionally, in order to generate the type of debuginfo that perf
270understands, we also need to set 316understands, we also need to set
271:term:`PACKAGE_DEBUG_SPLIT_STYLE` 317:term:`PACKAGE_DEBUG_SPLIT_STYLE`
272in the ``local.conf`` file: PACKAGE_DEBUG_SPLIT_STYLE = 318in the ``local.conf`` file: ::
273'debug-file-directory' Once we've done that, we can install the 319
320 PACKAGE_DEBUG_SPLIT_STYLE = 'debug-file-directory'
321
322Once we've done that, we can install the
274debuginfo for busybox. The debug packages once built can be found in 323debuginfo for busybox. The debug packages once built can be found in
275build/tmp/deploy/rpm/\* on the host system. Find the busybox-dbg-...rpm 324``build/tmp/deploy/rpm/*`` on the host system. Find the busybox-dbg-...rpm
276file and copy it to the target. For example: [trz@empanada core2]$ scp 325file and copy it to the target. For example: ::
277/home/trz/yocto/crownbay-tracing-dbg/build/tmp/deploy/rpm/core2_32/busybox-dbg-1.20.2-r2.core2_32.rpm 326
278root@192.168.1.31: root@192.168.1.31's password: 327 [trz@empanada core2]$ scp /home/trz/yocto/crownbay-tracing-dbg/build/tmp/deploy/rpm/core2_32/busybox-dbg-1.20.2-r2.core2_32.rpm root@192.168.1.31:
279busybox-dbg-1.20.2-r2.core2_32.rpm 100% 1826KB 1.8MB/s 00:01 Now install 328 busybox-dbg-1.20.2-r2.core2_32.rpm 100% 1826KB 1.8MB/s 00:01
280the debug rpm on the target: root@crownbay:~# rpm -i 329
281busybox-dbg-1.20.2-r2.core2_32.rpm Now that the debuginfo is installed, 330Now install the debug rpm on the target: ::
282we see that the busybox entries now display their functions 331
283symbolically: 332 root@crownbay:~# rpm -i busybox-dbg-1.20.2-r2.core2_32.rpm
333
334Now that the debuginfo is installed, we see that the busybox entries now display
335their functions symbolically:
284 336
285.. image:: figures/perf-wget-busybox-debuginfo.png 337.. image:: figures/perf-wget-busybox-debuginfo.png
286 :align: center 338 :align: center
@@ -300,10 +352,10 @@ expanded all the nodes using the 'E' key):
300 :align: center 352 :align: center
301 353
302Finally, we can see that now that the busybox debuginfo is installed, 354Finally, we can see that now that the busybox debuginfo is installed,
303the previously unresolved symbol in the sys_clock_gettime() entry 355the previously unresolved symbol in the ``sys_clock_gettime()`` entry
304mentioned previously is now resolved, and shows that the 356mentioned previously is now resolved, and shows that the
305sys_clock_gettime system call that was the source of 6.75% of the 357sys_clock_gettime system call that was the source of 6.75% of the
306copy-to-user overhead was initiated by the handle_input() busybox 358copy-to-user overhead was initiated by the ``handle_input()`` busybox
307function: 359function:
308 360
309.. image:: figures/perf-wget-g-copy-to-user-expanded-debuginfo.png 361.. image:: figures/perf-wget-g-copy-to-user-expanded-debuginfo.png
@@ -336,85 +388,141 @@ traditional tools can also make use of the expanded possibilities now
336available to them, and in some cases have, as mentioned previously). 388available to them, and in some cases have, as mentioned previously).
337 389
338We can get a list of the available events that can be used to profile a 390We can get a list of the available events that can be used to profile a
339workload via 'perf list': root@crownbay:~# perf list List of pre-defined 391workload via 'perf list': ::
340events (to be used in -e): cpu-cycles OR cycles [Hardware event] 392
341stalled-cycles-frontend OR idle-cycles-frontend [Hardware event] 393 root@crownbay:~# perf list
342stalled-cycles-backend OR idle-cycles-backend [Hardware event] 394
343instructions [Hardware event] cache-references [Hardware event] 395 List of pre-defined events (to be used in -e):
344cache-misses [Hardware event] branch-instructions OR branches [Hardware 396 cpu-cycles OR cycles [Hardware event]
345event] branch-misses [Hardware event] bus-cycles [Hardware event] 397 stalled-cycles-frontend OR idle-cycles-frontend [Hardware event]
346ref-cycles [Hardware event] cpu-clock [Software event] task-clock 398 stalled-cycles-backend OR idle-cycles-backend [Hardware event]
347[Software event] page-faults OR faults [Software event] minor-faults 399 instructions [Hardware event]
348[Software event] major-faults [Software event] context-switches OR cs 400 cache-references [Hardware event]
349[Software event] cpu-migrations OR migrations [Software event] 401 cache-misses [Hardware event]
350alignment-faults [Software event] emulation-faults [Software event] 402 branch-instructions OR branches [Hardware event]
351L1-dcache-loads [Hardware cache event] L1-dcache-load-misses [Hardware 403 branch-misses [Hardware event]
352cache event] L1-dcache-prefetch-misses [Hardware cache event] 404 bus-cycles [Hardware event]
353L1-icache-loads [Hardware cache event] L1-icache-load-misses [Hardware 405 ref-cycles [Hardware event]
354cache event] . . . rNNN [Raw hardware event descriptor] 406
355cpu/t1=v1[,t2=v2,t3 ...]/modifier [Raw hardware event descriptor] (see 407 cpu-clock [Software event]
356'perf list --help' on how to encode it) mem:<addr>[:access] [Hardware 408 task-clock [Software event]
357breakpoint] sunrpc:rpc_call_status [Tracepoint event] 409 page-faults OR faults [Software event]
358sunrpc:rpc_bind_status [Tracepoint event] sunrpc:rpc_connect_status 410 minor-faults [Software event]
359[Tracepoint event] sunrpc:rpc_task_begin [Tracepoint event] 411 major-faults [Software event]
360skb:kfree_skb [Tracepoint event] skb:consume_skb [Tracepoint event] 412 context-switches OR cs [Software event]
361skb:skb_copy_datagram_iovec [Tracepoint event] net:net_dev_xmit 413 cpu-migrations OR migrations [Software event]
362[Tracepoint event] net:net_dev_queue [Tracepoint event] 414 alignment-faults [Software event]
363net:netif_receive_skb [Tracepoint event] net:netif_rx [Tracepoint event] 415 emulation-faults [Software event]
364napi:napi_poll [Tracepoint event] sock:sock_rcvqueue_full [Tracepoint 416
365event] sock:sock_exceed_buf_limit [Tracepoint event] 417 L1-dcache-loads [Hardware cache event]
366udp:udp_fail_queue_rcv_skb [Tracepoint event] hda:hda_send_cmd 418 L1-dcache-load-misses [Hardware cache event]
367[Tracepoint event] hda:hda_get_response [Tracepoint event] 419 L1-dcache-prefetch-misses [Hardware cache event]
368hda:hda_bus_reset [Tracepoint event] scsi:scsi_dispatch_cmd_start 420 L1-icache-loads [Hardware cache event]
369[Tracepoint event] scsi:scsi_dispatch_cmd_error [Tracepoint event] 421 L1-icache-load-misses [Hardware cache event]
370scsi:scsi_eh_wakeup [Tracepoint event] drm:drm_vblank_event [Tracepoint 422 .
371event] drm:drm_vblank_event_queued [Tracepoint event] 423 .
372drm:drm_vblank_event_delivered [Tracepoint event] random:mix_pool_bytes 424 .
373[Tracepoint event] random:mix_pool_bytes_nolock [Tracepoint event] 425 rNNN [Raw hardware event descriptor]
374random:credit_entropy_bits [Tracepoint event] gpio:gpio_direction 426 cpu/t1=v1[,t2=v2,t3 ...]/modifier [Raw hardware event descriptor]
375[Tracepoint event] gpio:gpio_value [Tracepoint event] 427 (see 'perf list --help' on how to encode it)
376block:block_rq_abort [Tracepoint event] block:block_rq_requeue 428
377[Tracepoint event] block:block_rq_issue [Tracepoint event] 429 mem:<addr>[:access] [Hardware breakpoint]
378block:block_bio_bounce [Tracepoint event] block:block_bio_complete 430
379[Tracepoint event] block:block_bio_backmerge [Tracepoint event] . . 431 sunrpc:rpc_call_status [Tracepoint event]
380writeback:writeback_wake_thread [Tracepoint event] 432 sunrpc:rpc_bind_status [Tracepoint event]
381writeback:writeback_wake_forker_thread [Tracepoint event] 433 sunrpc:rpc_connect_status [Tracepoint event]
382writeback:writeback_bdi_register [Tracepoint event] . . 434 sunrpc:rpc_task_begin [Tracepoint event]
383writeback:writeback_single_inode_requeue [Tracepoint event] 435 skb:kfree_skb [Tracepoint event]
384writeback:writeback_single_inode [Tracepoint event] kmem:kmalloc 436 skb:consume_skb [Tracepoint event]
385[Tracepoint event] kmem:kmem_cache_alloc [Tracepoint event] 437 skb:skb_copy_datagram_iovec [Tracepoint event]
386kmem:mm_page_alloc [Tracepoint event] kmem:mm_page_alloc_zone_locked 438 net:net_dev_xmit [Tracepoint event]
387[Tracepoint event] kmem:mm_page_pcpu_drain [Tracepoint event] 439 net:net_dev_queue [Tracepoint event]
388kmem:mm_page_alloc_extfrag [Tracepoint event] 440 net:netif_receive_skb [Tracepoint event]
389vmscan:mm_vmscan_kswapd_sleep [Tracepoint event] 441 net:netif_rx [Tracepoint event]
390vmscan:mm_vmscan_kswapd_wake [Tracepoint event] 442 napi:napi_poll [Tracepoint event]
391vmscan:mm_vmscan_wakeup_kswapd [Tracepoint event] 443 sock:sock_rcvqueue_full [Tracepoint event]
392vmscan:mm_vmscan_direct_reclaim_begin [Tracepoint event] . . 444 sock:sock_exceed_buf_limit [Tracepoint event]
393module:module_get [Tracepoint event] module:module_put [Tracepoint 445 udp:udp_fail_queue_rcv_skb [Tracepoint event]
394event] module:module_request [Tracepoint event] sched:sched_kthread_stop 446 hda:hda_send_cmd [Tracepoint event]
395[Tracepoint event] sched:sched_wakeup [Tracepoint event] 447 hda:hda_get_response [Tracepoint event]
396sched:sched_wakeup_new [Tracepoint event] sched:sched_process_fork 448 hda:hda_bus_reset [Tracepoint event]
397[Tracepoint event] sched:sched_process_exec [Tracepoint event] 449 scsi:scsi_dispatch_cmd_start [Tracepoint event]
398sched:sched_stat_runtime [Tracepoint event] rcu:rcu_utilization 450 scsi:scsi_dispatch_cmd_error [Tracepoint event]
399[Tracepoint event] workqueue:workqueue_queue_work [Tracepoint event] 451 scsi:scsi_eh_wakeup [Tracepoint event]
400workqueue:workqueue_execute_end [Tracepoint event] 452 drm:drm_vblank_event [Tracepoint event]
401signal:signal_generate [Tracepoint event] signal:signal_deliver 453 drm:drm_vblank_event_queued [Tracepoint event]
402[Tracepoint event] timer:timer_init [Tracepoint event] timer:timer_start 454 drm:drm_vblank_event_delivered [Tracepoint event]
403[Tracepoint event] timer:hrtimer_cancel [Tracepoint event] 455 random:mix_pool_bytes [Tracepoint event]
404timer:itimer_state [Tracepoint event] timer:itimer_expire [Tracepoint 456 random:mix_pool_bytes_nolock [Tracepoint event]
405event] irq:irq_handler_entry [Tracepoint event] irq:irq_handler_exit 457 random:credit_entropy_bits [Tracepoint event]
406[Tracepoint event] irq:softirq_entry [Tracepoint event] irq:softirq_exit 458 gpio:gpio_direction [Tracepoint event]
407[Tracepoint event] irq:softirq_raise [Tracepoint event] printk:console 459 gpio:gpio_value [Tracepoint event]
408[Tracepoint event] task:task_newtask [Tracepoint event] task:task_rename 460 block:block_rq_abort [Tracepoint event]
409[Tracepoint event] syscalls:sys_enter_socketcall [Tracepoint event] 461 block:block_rq_requeue [Tracepoint event]
410syscalls:sys_exit_socketcall [Tracepoint event] . . . 462 block:block_rq_issue [Tracepoint event]
411syscalls:sys_enter_unshare [Tracepoint event] syscalls:sys_exit_unshare 463 block:block_bio_bounce [Tracepoint event]
412[Tracepoint event] raw_syscalls:sys_enter [Tracepoint event] 464 block:block_bio_complete [Tracepoint event]
413raw_syscalls:sys_exit [Tracepoint event] 465 block:block_bio_backmerge [Tracepoint event]
414 466 .
415.. container:: informalexample 467 .
416 468 writeback:writeback_wake_thread [Tracepoint event]
417 **Tying it Together**: 469 writeback:writeback_wake_forker_thread [Tracepoint event]
470 writeback:writeback_bdi_register [Tracepoint event]
471 .
472 .
473 writeback:writeback_single_inode_requeue [Tracepoint event]
474 writeback:writeback_single_inode [Tracepoint event]
475 kmem:kmalloc [Tracepoint event]
476 kmem:kmem_cache_alloc [Tracepoint event]
477 kmem:mm_page_alloc [Tracepoint event]
478 kmem:mm_page_alloc_zone_locked [Tracepoint event]
479 kmem:mm_page_pcpu_drain [Tracepoint event]
480 kmem:mm_page_alloc_extfrag [Tracepoint event]
481 vmscan:mm_vmscan_kswapd_sleep [Tracepoint event]
482 vmscan:mm_vmscan_kswapd_wake [Tracepoint event]
483 vmscan:mm_vmscan_wakeup_kswapd [Tracepoint event]
484 vmscan:mm_vmscan_direct_reclaim_begin [Tracepoint event]
485 .
486 .
487 module:module_get [Tracepoint event]
488 module:module_put [Tracepoint event]
489 module:module_request [Tracepoint event]
490 sched:sched_kthread_stop [Tracepoint event]
491 sched:sched_wakeup [Tracepoint event]
492 sched:sched_wakeup_new [Tracepoint event]
493 sched:sched_process_fork [Tracepoint event]
494 sched:sched_process_exec [Tracepoint event]
495 sched:sched_stat_runtime [Tracepoint event]
496 rcu:rcu_utilization [Tracepoint event]
497 workqueue:workqueue_queue_work [Tracepoint event]
498 workqueue:workqueue_execute_end [Tracepoint event]
499 signal:signal_generate [Tracepoint event]
500 signal:signal_deliver [Tracepoint event]
501 timer:timer_init [Tracepoint event]
502 timer:timer_start [Tracepoint event]
503 timer:hrtimer_cancel [Tracepoint event]
504 timer:itimer_state [Tracepoint event]
505 timer:itimer_expire [Tracepoint event]
506 irq:irq_handler_entry [Tracepoint event]
507 irq:irq_handler_exit [Tracepoint event]
508 irq:softirq_entry [Tracepoint event]
509 irq:softirq_exit [Tracepoint event]
510 irq:softirq_raise [Tracepoint event]
511 printk:console [Tracepoint event]
512 task:task_newtask [Tracepoint event]
513 task:task_rename [Tracepoint event]
514 syscalls:sys_enter_socketcall [Tracepoint event]
515 syscalls:sys_exit_socketcall [Tracepoint event]
516 .
517 .
518 .
519 syscalls:sys_enter_unshare [Tracepoint event]
520 syscalls:sys_exit_unshare [Tracepoint event]
521 raw_syscalls:sys_enter [Tracepoint event]
522 raw_syscalls:sys_exit [Tracepoint event]
523
524.. admonition:: Tying it Together
525
418 These are exactly the same set of events defined by the trace event 526 These are exactly the same set of events defined by the trace event
419 subsystem and exposed by ftrace/tracecmd/kernelshark as files in 527 subsystem and exposed by ftrace/tracecmd/kernelshark as files in
420 /sys/kernel/debug/tracing/events, by SystemTap as 528 /sys/kernel/debug/tracing/events, by SystemTap as
@@ -423,36 +531,71 @@ raw_syscalls:sys_exit [Tracepoint event]
423Only a subset of these would be of interest to us when looking at this 531Only a subset of these would be of interest to us when looking at this
424workload, so let's choose the most likely subsystems (identified by the 532workload, so let's choose the most likely subsystems (identified by the
425string before the colon in the Tracepoint events) and do a 'perf stat' 533string before the colon in the Tracepoint events) and do a 'perf stat'
426run using only those wildcarded subsystems: root@crownbay:~# perf stat 534run using only those wildcarded subsystems: ::
427-e skb:\* -e net:\* -e napi:\* -e sched:\* -e workqueue:\* -e irq:\* -e 535
428syscalls:\* wget 536 root@crownbay:~# perf stat -e skb:* -e net:* -e napi:* -e sched:* -e workqueue:* -e irq:* -e syscalls:* wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
429http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 537 Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2':
430Performance counter stats for 'wget 538
431http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': 539 23323 skb:kfree_skb
43223323 skb:kfree_skb 0 skb:consume_skb 49897 skb:skb_copy_datagram_iovec 540 0 skb:consume_skb
4336217 net:net_dev_xmit 6217 net:net_dev_queue 7962 net:netif_receive_skb 541 49897 skb:skb_copy_datagram_iovec
4342 net:netif_rx 8340 napi:napi_poll 0 sched:sched_kthread_stop 0 542 6217 net:net_dev_xmit
435sched:sched_kthread_stop_ret 3749 sched:sched_wakeup 0 543 6217 net:net_dev_queue
436sched:sched_wakeup_new 0 sched:sched_switch 29 sched:sched_migrate_task 544 7962 net:netif_receive_skb
4370 sched:sched_process_free 1 sched:sched_process_exit 0 545 2 net:netif_rx
438sched:sched_wait_task 0 sched:sched_process_wait 0 546 8340 napi:napi_poll
439sched:sched_process_fork 1 sched:sched_process_exec 0 547 0 sched:sched_kthread_stop
440sched:sched_stat_wait 2106519415641 sched:sched_stat_sleep 0 548 0 sched:sched_kthread_stop_ret
441sched:sched_stat_iowait 147453613 sched:sched_stat_blocked 12903026955 549 3749 sched:sched_wakeup
442sched:sched_stat_runtime 0 sched:sched_pi_setprio 3574 550 0 sched:sched_wakeup_new
443workqueue:workqueue_queue_work 3574 workqueue:workqueue_activate_work 0 551 0 sched:sched_switch
444workqueue:workqueue_execute_start 0 workqueue:workqueue_execute_end 552 29 sched:sched_migrate_task
44516631 irq:irq_handler_entry 16631 irq:irq_handler_exit 28521 553 0 sched:sched_process_free
446irq:softirq_entry 28521 irq:softirq_exit 28728 irq:softirq_raise 1 554 1 sched:sched_process_exit
447syscalls:sys_enter_sendmmsg 1 syscalls:sys_exit_sendmmsg 0 555 0 sched:sched_wait_task
448syscalls:sys_enter_recvmmsg 0 syscalls:sys_exit_recvmmsg 14 556 0 sched:sched_process_wait
449syscalls:sys_enter_socketcall 14 syscalls:sys_exit_socketcall . . . 557 0 sched:sched_process_fork
45016965 syscalls:sys_enter_read 16965 syscalls:sys_exit_read 12854 558 1 sched:sched_process_exec
451syscalls:sys_enter_write 12854 syscalls:sys_exit_write . . . 559 0 sched:sched_stat_wait
45258.029710972 seconds time elapsed Let's pick one of these tracepoints 560 2106519415641 sched:sched_stat_sleep
453and tell perf to do a profile using it as the sampling event: 561 0 sched:sched_stat_iowait
454root@crownbay:~# perf record -g -e sched:sched_wakeup wget 562 147453613 sched:sched_stat_blocked
455http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 563 12903026955 sched:sched_stat_runtime
564 0 sched:sched_pi_setprio
565 3574 workqueue:workqueue_queue_work
566 3574 workqueue:workqueue_activate_work
567 0 workqueue:workqueue_execute_start
568 0 workqueue:workqueue_execute_end
569 16631 irq:irq_handler_entry
570 16631 irq:irq_handler_exit
571 28521 irq:softirq_entry
572 28521 irq:softirq_exit
573 28728 irq:softirq_raise
574 1 syscalls:sys_enter_sendmmsg
575 1 syscalls:sys_exit_sendmmsg
576 0 syscalls:sys_enter_recvmmsg
577 0 syscalls:sys_exit_recvmmsg
578 14 syscalls:sys_enter_socketcall
579 14 syscalls:sys_exit_socketcall
580 .
581 .
582 .
583 16965 syscalls:sys_enter_read
584 16965 syscalls:sys_exit_read
585 12854 syscalls:sys_enter_write
586 12854 syscalls:sys_exit_write
587 .
588 .
589 .
590
591 58.029710972 seconds time elapsed
592
593
594
595Let's pick one of these tracepoints
596and tell perf to do a profile using it as the sampling event: ::
597
598 root@crownbay:~# perf record -g -e sched:sched_wakeup wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
456 599
457.. image:: figures/sched-wakeup-profile.png 600.. image:: figures/sched-wakeup-profile.png
458 :align: center 601 :align: center
@@ -461,10 +604,23 @@ The screenshot above shows the results of running a profile using
461sched:sched_switch tracepoint, which shows the relative costs of various 604sched:sched_switch tracepoint, which shows the relative costs of various
462paths to sched_wakeup (note that sched_wakeup is the name of the 605paths to sched_wakeup (note that sched_wakeup is the name of the
463tracepoint - it's actually defined just inside ttwu_do_wakeup(), which 606tracepoint - it's actually defined just inside ttwu_do_wakeup(), which
464accounts for the function name actually displayed in the profile: /\* \* 607accounts for the function name actually displayed in the profile:
465Mark the task runnable and perform wakeup-preemption. \*/ static void 608
466ttwu_do_wakeup(struct rq \*rq, struct task_struct \*p, int wake_flags) { 609.. code-block:: c
467trace_sched_wakeup(p, true); . . . } A couple of the more interesting 610
611 /*
612 * Mark the task runnable and perform wakeup-preemption.
613 */
614 static void
615 ttwu_do_wakeup(struct rq *rq, struct task_struct *p, int wake_flags)
616 {
617 trace_sched_wakeup(p, true);
618 .
619 .
620 .
621 }
622
623A couple of the more interesting
468callchains are expanded and displayed above, basically some network 624callchains are expanded and displayed above, basically some network
469receive paths that presumably end up waking up wget (busybox) when 625receive paths that presumably end up waking up wget (busybox) when
470network data is ready. 626network data is ready.
@@ -494,37 +650,41 @@ individual steps that go into the higher-level behavior exposed by the
494coarse-grained profiling data. 650coarse-grained profiling data.
495 651
496As a concrete example, we can trace all the events we think might be 652As a concrete example, we can trace all the events we think might be
497applicable to our workload: root@crownbay:~# perf record -g -e skb:\* -e 653applicable to our workload: ::
498net:\* -e napi:\* -e sched:sched_switch -e sched:sched_wakeup -e irq:\* 654
499-e syscalls:sys_enter_read -e syscalls:sys_exit_read -e 655 root@crownbay:~# perf record -g -e skb:* -e net:* -e napi:* -e sched:sched_switch -e sched:sched_wakeup -e irq:*
500syscalls:sys_enter_write -e syscalls:sys_exit_write wget 656 -e syscalls:sys_enter_read -e syscalls:sys_exit_read -e syscalls:sys_enter_write -e syscalls:sys_exit_write
501http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 657 wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
658
502We can look at the raw trace output using 'perf script' with no 659We can look at the raw trace output using 'perf script' with no
503arguments: root@crownbay:~# perf script perf 1262 [000] 11624.857082: 660arguments: ::
504sys_exit_read: 0x0 perf 1262 [000] 11624.857193: sched_wakeup: 661
505comm=migration/0 pid=6 prio=0 success=1 target_cpu=000 wget 1262 [001] 662 root@crownbay:~# perf script
50611624.858021: softirq_raise: vec=1 [action=TIMER] wget 1262 [001] 663
50711624.858074: softirq_entry: vec=1 [action=TIMER] wget 1262 [001] 664 perf 1262 [000] 11624.857082: sys_exit_read: 0x0
50811624.858081: softirq_exit: vec=1 [action=TIMER] wget 1262 [001] 665 perf 1262 [000] 11624.857193: sched_wakeup: comm=migration/0 pid=6 prio=0 success=1 target_cpu=000
50911624.858166: sys_enter_read: fd: 0x0003, buf: 0xbf82c940, count: 0x0200 666 wget 1262 [001] 11624.858021: softirq_raise: vec=1 [action=TIMER]
510wget 1262 [001] 11624.858177: sys_exit_read: 0x200 wget 1262 [001] 667 wget 1262 [001] 11624.858074: softirq_entry: vec=1 [action=TIMER]
51111624.858878: kfree_skb: skbaddr=0xeb248d80 protocol=0 668 wget 1262 [001] 11624.858081: softirq_exit: vec=1 [action=TIMER]
512location=0xc15a5308 wget 1262 [001] 11624.858945: kfree_skb: 669 wget 1262 [001] 11624.858166: sys_enter_read: fd: 0x0003, buf: 0xbf82c940, count: 0x0200
513skbaddr=0xeb248000 protocol=0 location=0xc15a5308 wget 1262 [001] 670 wget 1262 [001] 11624.858177: sys_exit_read: 0x200
51411624.859020: softirq_raise: vec=1 [action=TIMER] wget 1262 [001] 671 wget 1262 [001] 11624.858878: kfree_skb: skbaddr=0xeb248d80 protocol=0 location=0xc15a5308
51511624.859076: softirq_entry: vec=1 [action=TIMER] wget 1262 [001] 672 wget 1262 [001] 11624.858945: kfree_skb: skbaddr=0xeb248000 protocol=0 location=0xc15a5308
51611624.859083: softirq_exit: vec=1 [action=TIMER] wget 1262 [001] 673 wget 1262 [001] 11624.859020: softirq_raise: vec=1 [action=TIMER]
51711624.859167: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400 674 wget 1262 [001] 11624.859076: softirq_entry: vec=1 [action=TIMER]
518wget 1262 [001] 11624.859192: sys_exit_read: 0x1d7 wget 1262 [001] 675 wget 1262 [001] 11624.859083: softirq_exit: vec=1 [action=TIMER]
51911624.859228: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400 676 wget 1262 [001] 11624.859167: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400
520wget 1262 [001] 11624.859233: sys_exit_read: 0x0 wget 1262 [001] 677 wget 1262 [001] 11624.859192: sys_exit_read: 0x1d7
52111624.859573: sys_enter_read: fd: 0x0003, buf: 0xbf82c580, count: 0x0200 678 wget 1262 [001] 11624.859228: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400
522wget 1262 [001] 11624.859584: sys_exit_read: 0x200 wget 1262 [001] 679 wget 1262 [001] 11624.859233: sys_exit_read: 0x0
52311624.859864: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400 680 wget 1262 [001] 11624.859573: sys_enter_read: fd: 0x0003, buf: 0xbf82c580, count: 0x0200
524wget 1262 [001] 11624.859888: sys_exit_read: 0x400 wget 1262 [001] 681 wget 1262 [001] 11624.859584: sys_exit_read: 0x200
52511624.859935: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400 682 wget 1262 [001] 11624.859864: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400
526wget 1262 [001] 11624.859944: sys_exit_read: 0x400 This gives us a 683 wget 1262 [001] 11624.859888: sys_exit_read: 0x400
527detailed timestamped sequence of events that occurred within the 684 wget 1262 [001] 11624.859935: sys_enter_read: fd: 0x0003, buf: 0xb7720000, count: 0x0400
685 wget 1262 [001] 11624.859944: sys_exit_read: 0x400
686
687This gives us a detailed timestamped sequence of events that occurred within the
528workload with respect to those events. 688workload with respect to those events.
529 689
530In many ways, profiling can be viewed as a subset of tracing - 690In many ways, profiling can be viewed as a subset of tracing -
@@ -566,9 +726,8 @@ to apply to such problems given the specific format of data is called a
566'programming language binding' for that data and language. Perf supports 726'programming language binding' for that data and language. Perf supports
567two programming language bindings, one for Python and one for Perl. 727two programming language bindings, one for Python and one for Perl.
568 728
569.. container:: informalexample 729.. admonition:: Tying it Together
570 730
571 **Tying it Together**:
572 Language bindings for manipulating and aggregating trace data are of 731 Language bindings for manipulating and aggregating trace data are of
573 course not a new idea. One of the first projects to do this was IBM's 732 course not a new idea. One of the first projects to do this was IBM's
574 DProbes dpcc compiler, an ANSI C compiler which targeted a low-level 733 DProbes dpcc compiler, an ANSI C compiler which targeted a low-level
@@ -582,45 +741,57 @@ two programming language bindings, one for Python and one for Perl.
582 741
583Now that we have the trace data in perf.data, we can use 'perf script 742Now that we have the trace data in perf.data, we can use 'perf script
584-g' to generate a skeleton script with handlers for the read/write 743-g' to generate a skeleton script with handlers for the read/write
585entry/exit events we recorded: root@crownbay:~# perf script -g python 744entry/exit events we recorded: ::
586generated Python script: perf-script.py The skeleton script simply 745
587creates a python function for each event type in the perf.data file. The 746 root@crownbay:~# perf script -g python
588body of each function simply prints the event name along with its 747 generated Python script: perf-script.py
589parameters. For example: def net__netif_rx(event_name, context, 748
590common_cpu, common_secs, common_nsecs, common_pid, common_comm, skbaddr, 749The skeleton script simply creates a python function for each event type in the
591len, name): print_header(event_name, common_cpu, common_secs, 750perf.data file. The body of each function simply prints the event name along
592common_nsecs, common_pid, common_comm) print "skbaddr=%u, len=%u, 751with its parameters. For example:
593name=%s\n" % (skbaddr, len, name), We can run that script directly to 752
594print all of the events contained in the perf.data file: 753.. code-block:: python
595root@crownbay:~# perf script -s perf-script.py in trace_begin 754
596syscalls__sys_exit_read 0 11624.857082795 1262 perf nr=3, ret=0 755 def net__netif_rx(event_name, context, common_cpu,
597sched__sched_wakeup 0 11624.857193498 1262 perf comm=migration/0, pid=6, 756 common_secs, common_nsecs, common_pid, common_comm,
598prio=0, success=1, target_cpu=0 irq__softirq_raise 1 11624.858021635 757 skbaddr, len, name):
5991262 wget vec=TIMER irq__softirq_entry 1 11624.858074075 1262 wget 758 print_header(event_name, common_cpu, common_secs, common_nsecs,
600vec=TIMER irq__softirq_exit 1 11624.858081389 1262 wget vec=TIMER 759 common_pid, common_comm)
601syscalls__sys_enter_read 1 11624.858166434 1262 wget nr=3, fd=3, 760
602buf=3213019456, count=512 syscalls__sys_exit_read 1 11624.858177924 1262 761 print "skbaddr=%u, len=%u, name=%s\n" % (skbaddr, len, name),
603wget nr=3, ret=512 skb__kfree_skb 1 11624.858878188 1262 wget 762
604skbaddr=3945041280, location=3243922184, protocol=0 skb__kfree_skb 1 763We can run that script directly to print all of the events contained in the
60511624.858945608 1262 wget skbaddr=3945037824, location=3243922184, 764perf.data file: ::
606protocol=0 irq__softirq_raise 1 11624.859020942 1262 wget vec=TIMER 765
607irq__softirq_entry 1 11624.859076935 1262 wget vec=TIMER 766 root@crownbay:~# perf script -s perf-script.py
608irq__softirq_exit 1 11624.859083469 1262 wget vec=TIMER 767
609syscalls__sys_enter_read 1 11624.859167565 1262 wget nr=3, fd=3, 768 in trace_begin
610buf=3077701632, count=1024 syscalls__sys_exit_read 1 11624.859192533 769 syscalls__sys_exit_read 0 11624.857082795 1262 perf nr=3, ret=0
6111262 wget nr=3, ret=471 syscalls__sys_enter_read 1 11624.859228072 1262 770 sched__sched_wakeup 0 11624.857193498 1262 perf comm=migration/0, pid=6, prio=0, success=1, target_cpu=0
612wget nr=3, fd=3, buf=3077701632, count=1024 syscalls__sys_exit_read 1 771 irq__softirq_raise 1 11624.858021635 1262 wget vec=TIMER
61311624.859233707 1262 wget nr=3, ret=0 syscalls__sys_enter_read 1 772 irq__softirq_entry 1 11624.858074075 1262 wget vec=TIMER
61411624.859573008 1262 wget nr=3, fd=3, buf=3213018496, count=512 773 irq__softirq_exit 1 11624.858081389 1262 wget vec=TIMER
615syscalls__sys_exit_read 1 11624.859584818 1262 wget nr=3, ret=512 774 syscalls__sys_enter_read 1 11624.858166434 1262 wget nr=3, fd=3, buf=3213019456, count=512
616syscalls__sys_enter_read 1 11624.859864562 1262 wget nr=3, fd=3, 775 syscalls__sys_exit_read 1 11624.858177924 1262 wget nr=3, ret=512
617buf=3077701632, count=1024 syscalls__sys_exit_read 1 11624.859888770 776 skb__kfree_skb 1 11624.858878188 1262 wget skbaddr=3945041280, location=3243922184, protocol=0
6181262 wget nr=3, ret=1024 syscalls__sys_enter_read 1 11624.859935140 1262 777 skb__kfree_skb 1 11624.858945608 1262 wget skbaddr=3945037824, location=3243922184, protocol=0
619wget nr=3, fd=3, buf=3077701632, count=1024 syscalls__sys_exit_read 1 778 irq__softirq_raise 1 11624.859020942 1262 wget vec=TIMER
62011624.859944032 1262 wget nr=3, ret=1024 That in itself isn't very 779 irq__softirq_entry 1 11624.859076935 1262 wget vec=TIMER
621useful; after all, we can accomplish pretty much the same thing by 780 irq__softirq_exit 1 11624.859083469 1262 wget vec=TIMER
622simply running 'perf script' without arguments in the same directory as 781 syscalls__sys_enter_read 1 11624.859167565 1262 wget nr=3, fd=3, buf=3077701632, count=1024
623the perf.data file. 782 syscalls__sys_exit_read 1 11624.859192533 1262 wget nr=3, ret=471
783 syscalls__sys_enter_read 1 11624.859228072 1262 wget nr=3, fd=3, buf=3077701632, count=1024
784 syscalls__sys_exit_read 1 11624.859233707 1262 wget nr=3, ret=0
785 syscalls__sys_enter_read 1 11624.859573008 1262 wget nr=3, fd=3, buf=3213018496, count=512
786 syscalls__sys_exit_read 1 11624.859584818 1262 wget nr=3, ret=512
787 syscalls__sys_enter_read 1 11624.859864562 1262 wget nr=3, fd=3, buf=3077701632, count=1024
788 syscalls__sys_exit_read 1 11624.859888770 1262 wget nr=3, ret=1024
789 syscalls__sys_enter_read 1 11624.859935140 1262 wget nr=3, fd=3, buf=3077701632, count=1024
790 syscalls__sys_exit_read 1 11624.859944032 1262 wget nr=3, ret=1024
791
792That in itself isn't very useful; after all, we can accomplish pretty much the
793same thing by simply running 'perf script' without arguments in the same
794directory as the perf.data file.
624 795
625We can however replace the print statements in the generated function 796We can however replace the print statements in the generated function
626bodies with whatever we want, and thereby make it infinitely more 797bodies with whatever we want, and thereby make it infinitely more
@@ -630,29 +801,65 @@ As a simple example, let's just replace the print statements in the
630function bodies with a simple function that does nothing but increment a 801function bodies with a simple function that does nothing but increment a
631per-event count. When the program is run against a perf.data file, each 802per-event count. When the program is run against a perf.data file, each
632time a particular event is encountered, a tally is incremented for that 803time a particular event is encountered, a tally is incremented for that
633event. For example: def net__netif_rx(event_name, context, common_cpu, 804event. For example:
634common_secs, common_nsecs, common_pid, common_comm, skbaddr, len, name): 805
635inc_counts(event_name) Each event handler function in the generated code 806.. code-block:: python
807
808 def net__netif_rx(event_name, context, common_cpu,
809 common_secs, common_nsecs, common_pid, common_comm,
810 skbaddr, len, name):
811 inc_counts(event_name)
812
813Each event handler function in the generated code
636is modified to do this. For convenience, we define a common function 814is modified to do this. For convenience, we define a common function
637called inc_counts() that each handler calls; inc_counts() simply tallies 815called inc_counts() that each handler calls; inc_counts() simply tallies
638a count for each event using the 'counts' hash, which is a specialized 816a count for each event using the 'counts' hash, which is a specialized
639hash function that does Perl-like autovivification, a capability that's 817hash function that does Perl-like autovivification, a capability that's
640extremely useful for kinds of multi-level aggregation commonly used in 818extremely useful for kinds of multi-level aggregation commonly used in
641processing traces (see perf's documentation on the Python language 819processing traces (see perf's documentation on the Python language
642binding for details): counts = autodict() def inc_counts(event_name): 820binding for details):
643try: counts[event_name] += 1 except TypeError: counts[event_name] = 1 821
822.. code-block:: python
823
824 counts = autodict()
825
826 def inc_counts(event_name):
827 try:
828 counts[event_name] += 1
829 except TypeError:
830 counts[event_name] = 1
831
644Finally, at the end of the trace processing run, we want to print the 832Finally, at the end of the trace processing run, we want to print the
645result of all the per-event tallies. For that, we use the special 833result of all the per-event tallies. For that, we use the special
646'trace_end()' function: def trace_end(): for event_name, count in 834'trace_end()' function:
647counts.iteritems(): print "%-40s %10s\n" % (event_name, count) The end 835
648result is a summary of all the events recorded in the trace: 836.. code-block:: python
649skb__skb_copy_datagram_iovec 13148 irq__softirq_entry 4796 837
650irq__irq_handler_exit 3805 irq__softirq_exit 4795 838 def trace_end():
651syscalls__sys_enter_write 8990 net__net_dev_xmit 652 skb__kfree_skb 4047 839 for event_name, count in counts.iteritems():
652sched__sched_wakeup 1155 irq__irq_handler_entry 3804 irq__softirq_raise 840 print "%-40s %10s\n" % (event_name, count)
6534799 net__net_dev_queue 652 syscalls__sys_enter_read 17599 841
654net__netif_receive_skb 1743 syscalls__sys_exit_read 17598 net__netif_rx 842The end result is a summary of all the events recorded in the trace: ::
6552 napi__napi_poll 1877 syscalls__sys_exit_write 8990 Note that this is 843
844 skb__skb_copy_datagram_iovec 13148
845 irq__softirq_entry 4796
846 irq__irq_handler_exit 3805
847 irq__softirq_exit 4795
848 syscalls__sys_enter_write 8990
849 net__net_dev_xmit 652
850 skb__kfree_skb 4047
851 sched__sched_wakeup 1155
852 irq__irq_handler_entry 3804
853 irq__softirq_raise 4799
854 net__net_dev_queue 652
855 syscalls__sys_enter_read 17599
856 net__netif_receive_skb 1743
857 syscalls__sys_exit_read 17598
858 net__netif_rx 2
859 napi__napi_poll 1877
860 syscalls__sys_exit_write 8990
861
862Note that this is
656pretty much exactly the same information we get from 'perf stat', which 863pretty much exactly the same information we get from 'perf stat', which
657goes a little way to support the idea mentioned previously that given 864goes a little way to support the idea mentioned previously that given
658the right kind of trace data, higher-level profiling-type summaries can 865the right kind of trace data, higher-level profiling-type summaries can
@@ -676,14 +883,19 @@ To do system-wide profiling or tracing, you typically use the -a flag to
676'perf record'. 883'perf record'.
677 884
678To demonstrate this, open up one window and start the profile using the 885To demonstrate this, open up one window and start the profile using the
679-a flag (press Ctrl-C to stop tracing): root@crownbay:~# perf record -g 886-a flag (press Ctrl-C to stop tracing): ::
680-a ^C[ perf record: Woken up 6 times to write data ] [ perf record: 887
681Captured and wrote 1.400 MB perf.data (~61172 samples) ] In another 888 root@crownbay:~# perf record -g -a
682window, run the wget test: root@crownbay:~# wget 889 ^C[ perf record: Woken up 6 times to write data ]
683http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 890 [ perf record: Captured and wrote 1.400 MB perf.data (~61172 samples) ]
684Connecting to downloads.yoctoproject.org (140.211.169.59:80) 891
685linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 892In another window, run the wget test: ::
6860:00:00 ETA Here we see entries not only for our wget load, but for 893
894 root@crownbay:~# wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
895 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
896 linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA
897
898Here we see entries not only for our wget load, but for
687other processes running on the system as well: 899other processes running on the system as well:
688 900
689.. image:: figures/perf-systemwide.png 901.. image:: figures/perf-systemwide.png
@@ -697,9 +909,11 @@ unresolvable symbols in the expanded Xorg callchain).
697Note also that we have both kernel and userspace entries in the above 909Note also that we have both kernel and userspace entries in the above
698snapshot. We can also tell perf to focus on userspace but providing a 910snapshot. We can also tell perf to focus on userspace but providing a
699modifier, in this case 'u', to the 'cycles' hardware counter when we 911modifier, in this case 'u', to the 'cycles' hardware counter when we
700record a profile: root@crownbay:~# perf record -g -a -e cycles:u ^C[ 912record a profile: ::
701perf record: Woken up 2 times to write data ] [ perf record: Captured 913
702and wrote 0.376 MB perf.data (~16443 samples) ] 914 root@crownbay:~# perf record -g -a -e cycles:u
915 ^C[ perf record: Woken up 2 times to write data ]
916 [ perf record: Captured and wrote 0.376 MB perf.data (~16443 samples) ]
703 917
704.. image:: figures/perf-report-cycles-u.png 918.. image:: figures/perf-report-cycles-u.png
705 :align: center 919 :align: center
@@ -715,32 +929,26 @@ the entries associated with the libc-xxx.so DSO.
715 :align: center 929 :align: center
716 930
717We can also use the system-wide -a switch to do system-wide tracing. 931We can also use the system-wide -a switch to do system-wide tracing.
718Here we'll trace a couple of scheduler events: root@crownbay:~# perf 932Here we'll trace a couple of scheduler events: ::
719record -a -e sched:sched_switch -e sched:sched_wakeup ^C[ perf record: 933
720Woken up 38 times to write data ] [ perf record: Captured and wrote 934 root@crownbay:~# perf record -a -e sched:sched_switch -e sched:sched_wakeup
7219.780 MB perf.data (~427299 samples) ] We can look at the raw output 935 ^C[ perf record: Woken up 38 times to write data ]
722using 'perf script' with no arguments: root@crownbay:~# perf script perf 936 [ perf record: Captured and wrote 9.780 MB perf.data (~427299 samples) ]
7231383 [001] 6171.460045: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 937
724success=1 target_cpu=001 perf 1383 [001] 6171.460066: sched_switch: 938We can look at the raw output using 'perf script' with no arguments: ::
725prev_comm=perf prev_pid=1383 prev_prio=120 prev_state=R+ ==> 939
726next_comm=kworker/1:1 next_pid=21 next_prio=120 kworker/1:1 21 [001] 940 root@crownbay:~# perf script
7276171.460093: sched_switch: prev_comm=kworker/1:1 prev_pid=21 941
728prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1383 942 perf 1383 [001] 6171.460045: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
729next_prio=120 swapper 0 [000] 6171.468063: sched_wakeup: 943 perf 1383 [001] 6171.460066: sched_switch: prev_comm=perf prev_pid=1383 prev_prio=120 prev_state=R+ ==> next_comm=kworker/1:1 next_pid=21 next_prio=120
730comm=kworker/0:3 pid=1209 prio=120 success=1 target_cpu=000 swapper 0 944 kworker/1:1 21 [001] 6171.460093: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1383 next_prio=120
731[000] 6171.468107: sched_switch: prev_comm=swapper/0 prev_pid=0 945 swapper 0 [000] 6171.468063: sched_wakeup: comm=kworker/0:3 pid=1209 prio=120 success=1 target_cpu=000
732prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 946 swapper 0 [000] 6171.468107: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120
733next_prio=120 kworker/0:3 1209 [000] 6171.468143: sched_switch: 947 kworker/0:3 1209 [000] 6171.468143: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
734prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> 948 perf 1383 [001] 6171.470039: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
735next_comm=swapper/0 next_pid=0 next_prio=120 perf 1383 [001] 949 perf 1383 [001] 6171.470058: sched_switch: prev_comm=perf prev_pid=1383 prev_prio=120 prev_state=R+ ==> next_comm=kworker/1:1 next_pid=21 next_prio=120
7366171.470039: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 950 kworker/1:1 21 [001] 6171.470082: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=1383 next_prio=120
737target_cpu=001 perf 1383 [001] 6171.470058: sched_switch: prev_comm=perf 951 perf 1383 [001] 6171.480035: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
738prev_pid=1383 prev_prio=120 prev_state=R+ ==> next_comm=kworker/1:1
739next_pid=21 next_prio=120 kworker/1:1 21 [001] 6171.470082:
740sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120
741prev_state=S ==> next_comm=perf next_pid=1383 next_prio=120 perf 1383
742[001] 6171.480035: sched_wakeup: comm=kworker/1:1 pid=21 prio=120
743success=1 target_cpu=001
744 952
745.. _perf-filtering: 953.. _perf-filtering:
746 954
@@ -752,54 +960,45 @@ do with what we're interested in, namely events that schedule 'perf'
752itself in and out or that wake perf up. We can get rid of those by using 960itself in and out or that wake perf up. We can get rid of those by using
753the '--filter' option - for each event we specify using -e, we can add a 961the '--filter' option - for each event we specify using -e, we can add a
754--filter after that to filter out trace events that contain fields with 962--filter after that to filter out trace events that contain fields with
755specific values: root@crownbay:~# perf record -a -e sched:sched_switch 963specific values: ::
756--filter 'next_comm != perf && prev_comm != perf' -e sched:sched_wakeup 964
757--filter 'comm != perf' ^C[ perf record: Woken up 38 times to write data 965 root@crownbay:~# perf record -a -e sched:sched_switch --filter 'next_comm != perf && prev_comm != perf' -e sched:sched_wakeup --filter 'comm != perf'
758] [ perf record: Captured and wrote 9.688 MB perf.data (~423279 samples) 966 ^C[ perf record: Woken up 38 times to write data ]
759] root@crownbay:~# perf script swapper 0 [000] 7932.162180: 967 [ perf record: Captured and wrote 9.688 MB perf.data (~423279 samples) ]
760sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R 968
761==> next_comm=kworker/0:3 next_pid=1209 next_prio=120 kworker/0:3 1209 969
762[000] 7932.162236: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 970 root@crownbay:~# perf script
763prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 971
764next_prio=120 perf 1407 [001] 7932.170048: sched_wakeup: 972 swapper 0 [000] 7932.162180: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120
765comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001 perf 1407 973 kworker/0:3 1209 [000] 7932.162236: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
766[001] 7932.180044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 974 perf 1407 [001] 7932.170048: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
767success=1 target_cpu=001 perf 1407 [001] 7932.190038: sched_wakeup: 975 perf 1407 [001] 7932.180044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
768comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001 perf 1407 976 perf 1407 [001] 7932.190038: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
769[001] 7932.200044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 977 perf 1407 [001] 7932.200044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
770success=1 target_cpu=001 perf 1407 [001] 7932.210044: sched_wakeup: 978 perf 1407 [001] 7932.210044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
771comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001 perf 1407 979 perf 1407 [001] 7932.220044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
772[001] 7932.220044: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 980 swapper 0 [001] 7932.230111: sched_wakeup: comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001
773success=1 target_cpu=001 swapper 0 [001] 7932.230111: sched_wakeup: 981 swapper 0 [001] 7932.230146: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=21 next_prio=120
774comm=kworker/1:1 pid=21 prio=120 success=1 target_cpu=001 swapper 0 982 kworker/1:1 21 [001] 7932.230205: sched_switch: prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
775[001] 7932.230146: sched_switch: prev_comm=swapper/1 prev_pid=0 983 swapper 0 [000] 7932.326109: sched_wakeup: comm=kworker/0:3 pid=1209 prio=120 success=1 target_cpu=000
776prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=21 984 swapper 0 [000] 7932.326171: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=1209 next_prio=120
777next_prio=120 kworker/1:1 21 [001] 7932.230205: sched_switch: 985 kworker/0:3 1209 [000] 7932.326214: sched_switch: prev_comm=kworker/0:3 prev_pid=1209 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
778prev_comm=kworker/1:1 prev_pid=21 prev_prio=120 prev_state=S ==> 986
779next_comm=swapper/1 next_pid=0 next_prio=120 swapper 0 [000] 987In this case, we've filtered out all events that have
7807932.326109: sched_wakeup: comm=kworker/0:3 pid=1209 prio=120 success=1
781target_cpu=000 swapper 0 [000] 7932.326171: sched_switch:
782prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==>
783next_comm=kworker/0:3 next_pid=1209 next_prio=120 kworker/0:3 1209 [000]
7847932.326214: sched_switch: prev_comm=kworker/0:3 prev_pid=1209
785prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0
786next_prio=120 In this case, we've filtered out all events that have
787'perf' in their 'comm' or 'comm_prev' or 'comm_next' fields. Notice that 988'perf' in their 'comm' or 'comm_prev' or 'comm_next' fields. Notice that
788there are still events recorded for perf, but notice that those events 989there are still events recorded for perf, but notice that those events
789don't have values of 'perf' for the filtered fields. To completely 990don't have values of 'perf' for the filtered fields. To completely
790filter out anything from perf will require a bit more work, but for the 991filter out anything from perf will require a bit more work, but for the
791purpose of demonstrating how to use filters, it's close enough. 992purpose of demonstrating how to use filters, it's close enough.
792 993
793.. container:: informalexample 994.. admonition:: Tying it Together
794 995
795 **Tying it Together**:
796 These are exactly the same set of event filters defined by the trace 996 These are exactly the same set of event filters defined by the trace
797 event subsystem. See the ftrace/tracecmd/kernelshark section for more 997 event subsystem. See the ftrace/tracecmd/kernelshark section for more
798 discussion about these event filters. 998 discussion about these event filters.
799 999
800.. container:: informalexample 1000.. admonition:: Tying it Together
801 1001
802 **Tying it Together**:
803 These event filters are implemented by a special-purpose 1002 These event filters are implemented by a special-purpose
804 pseudo-interpreter in the kernel and are an integral and 1003 pseudo-interpreter in the kernel and are an integral and
805 indispensable part of the perf design as it relates to tracing. 1004 indispensable part of the perf design as it relates to tracing.
@@ -826,82 +1025,123 @@ perf isn't restricted to the fixed set of static tracepoints listed by
826'perf list'. Users can also add their own 'dynamic' tracepoints anywhere 1025'perf list'. Users can also add their own 'dynamic' tracepoints anywhere
827in the kernel. For instance, suppose we want to define our own 1026in the kernel. For instance, suppose we want to define our own
828tracepoint on do_fork(). We can do that using the 'perf probe' perf 1027tracepoint on do_fork(). We can do that using the 'perf probe' perf
829subcommand: root@crownbay:~# perf probe do_fork Added new event: 1028subcommand: ::
830probe:do_fork (on do_fork) You can now use it in all perf tools, such 1029
831as: perf record -e probe:do_fork -aR sleep 1 Adding a new tracepoint via 1030 root@crownbay:~# perf probe do_fork
1031 Added new event:
1032 probe:do_fork (on do_fork)
1033
1034 You can now use it in all perf tools, such as:
1035
1036 perf record -e probe:do_fork -aR sleep 1
1037
1038Adding a new tracepoint via
832'perf probe' results in an event with all the expected files and format 1039'perf probe' results in an event with all the expected files and format
833in /sys/kernel/debug/tracing/events, just the same as for static 1040in /sys/kernel/debug/tracing/events, just the same as for static
834tracepoints (as discussed in more detail in the trace events subsystem 1041tracepoints (as discussed in more detail in the trace events subsystem
835section: root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# 1042section: ::
836ls -al drwxr-xr-x 2 root root 0 Oct 28 11:42 . drwxr-xr-x 3 root root 0 1043
837Oct 28 11:42 .. -rw-r--r-- 1 root root 0 Oct 28 11:42 enable -rw-r--r-- 1044 root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# ls -al
8381 root root 0 Oct 28 11:42 filter -r--r--r-- 1 root root 0 Oct 28 11:42 1045 drwxr-xr-x 2 root root 0 Oct 28 11:42 .
839format -r--r--r-- 1 root root 0 Oct 28 11:42 id 1046 drwxr-xr-x 3 root root 0 Oct 28 11:42 ..
840root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# cat format 1047 -rw-r--r-- 1 root root 0 Oct 28 11:42 enable
841name: do_fork ID: 944 format: field:unsigned short common_type; 1048 -rw-r--r-- 1 root root 0 Oct 28 11:42 filter
842offset:0; size:2; signed:0; field:unsigned char common_flags; offset:2; 1049 -r--r--r-- 1 root root 0 Oct 28 11:42 format
843size:1; signed:0; field:unsigned char common_preempt_count; offset:3; 1050 -r--r--r-- 1 root root 0 Oct 28 11:42 id
844size:1; signed:0; field:int common_pid; offset:4; size:4; signed:1; 1051
845field:int common_padding; offset:8; size:4; signed:1; field:unsigned 1052 root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# cat format
846long \__probe_ip; offset:12; size:4; signed:0; print fmt: "(%lx)", 1053 name: do_fork
847REC->__probe_ip We can list all dynamic tracepoints currently in 1054 ID: 944
848existence: root@crownbay:~# perf probe -l probe:do_fork (on do_fork) 1055 format:
849probe:schedule (on schedule) Let's record system-wide ('sleep 30' is a 1056 field:unsigned short common_type; offset:0; size:2; signed:0;
1057 field:unsigned char common_flags; offset:2; size:1; signed:0;
1058 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
1059 field:int common_pid; offset:4; size:4; signed:1;
1060 field:int common_padding; offset:8; size:4; signed:1;
1061
1062 field:unsigned long __probe_ip; offset:12; size:4; signed:0;
1063
1064 print fmt: "(%lx)", REC->__probe_ip
1065
1066We can list all dynamic tracepoints currently in
1067existence: ::
1068
1069 root@crownbay:~# perf probe -l
1070 probe:do_fork (on do_fork)
1071 probe:schedule (on schedule)
1072
1073Let's record system-wide ('sleep 30' is a
850trick for recording system-wide but basically do nothing and then wake 1074trick for recording system-wide but basically do nothing and then wake
851up after 30 seconds): root@crownbay:~# perf record -g -a -e 1075up after 30 seconds): ::
852probe:do_fork sleep 30 [ perf record: Woken up 1 times to write data ] [ 1076
853perf record: Captured and wrote 0.087 MB perf.data (~3812 samples) ] 1077 root@crownbay:~# perf record -g -a -e probe:do_fork sleep 30
854Using 'perf script' we can see each do_fork event that fired: 1078 [ perf record: Woken up 1 times to write data ]
855root@crownbay:~# perf script # ======== # captured on: Sun Oct 28 1079 [ perf record: Captured and wrote 0.087 MB perf.data (~3812 samples) ]
85611:55:18 2012 # hostname : crownbay # os release : 3.4.11-yocto-standard 1080
857# perf version : 3.4.11 # arch : i686 # nrcpus online : 2 # nrcpus avail 1081Using 'perf script' we can see each do_fork event that fired: ::
858: 2 # cpudesc : Intel(R) Atom(TM) CPU E660 @ 1.30GHz # cpuid : 1082
859GenuineIntel,6,38,1 # total memory : 1017184 kB # cmdline : 1083 root@crownbay:~# perf script
860/usr/bin/perf record -g -a -e probe:do_fork sleep 30 # event : name = 1084
861probe:do_fork, type = 2, config = 0x3b0, config1 = 0x0, config2 = 0x0, 1085 # ========
862excl_usr = 0, excl_kern = 0, id = { 5, 6 } # HEADER_CPU_TOPOLOGY info 1086 # captured on: Sun Oct 28 11:55:18 2012
863available, use -I to display # ======== # matchbox-deskto 1197 [001] 1087 # hostname : crownbay
86434211.378318: do_fork: (c1028460) matchbox-deskto 1295 [001] 1088 # os release : 3.4.11-yocto-standard
86534211.380388: do_fork: (c1028460) pcmanfm 1296 [000] 34211.632350: 1089 # perf version : 3.4.11
866do_fork: (c1028460) pcmanfm 1296 [000] 34211.639917: do_fork: (c1028460) 1090 # arch : i686
867matchbox-deskto 1197 [001] 34217.541603: do_fork: (c1028460) 1091 # nrcpus online : 2
868matchbox-deskto 1299 [001] 34217.543584: do_fork: (c1028460) gthumb 1300 1092 # nrcpus avail : 2
869[001] 34217.697451: do_fork: (c1028460) gthumb 1300 [001] 34219.085734: 1093 # cpudesc : Intel(R) Atom(TM) CPU E660 @ 1.30GHz
870do_fork: (c1028460) gthumb 1300 [000] 34219.121351: do_fork: (c1028460) 1094 # cpuid : GenuineIntel,6,38,1
871gthumb 1300 [001] 34219.264551: do_fork: (c1028460) pcmanfm 1296 [000] 1095 # total memory : 1017184 kB
87234219.590380: do_fork: (c1028460) matchbox-deskto 1197 [001] 1096 # cmdline : /usr/bin/perf record -g -a -e probe:do_fork sleep 30
87334224.955965: do_fork: (c1028460) matchbox-deskto 1306 [001] 1097 # event : name = probe:do_fork, type = 2, config = 0x3b0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern
87434224.957972: do_fork: (c1028460) matchbox-termin 1307 [000] 1098 = 0, id = { 5, 6 }
87534225.038214: do_fork: (c1028460) matchbox-termin 1307 [001] 1099 # HEADER_CPU_TOPOLOGY info available, use -I to display
87634225.044218: do_fork: (c1028460) matchbox-termin 1307 [000] 1100 # ========
87734225.046442: do_fork: (c1028460) matchbox-deskto 1197 [001] 1101 #
87834237.112138: do_fork: (c1028460) matchbox-deskto 1311 [001] 1102 matchbox-deskto 1197 [001] 34211.378318: do_fork: (c1028460)
87934237.114106: do_fork: (c1028460) gaku 1312 [000] 34237.202388: do_fork: 1103 matchbox-deskto 1295 [001] 34211.380388: do_fork: (c1028460)
880(c1028460) And using 'perf report' on the same file, we can see the 1104 pcmanfm 1296 [000] 34211.632350: do_fork: (c1028460)
1105 pcmanfm 1296 [000] 34211.639917: do_fork: (c1028460)
1106 matchbox-deskto 1197 [001] 34217.541603: do_fork: (c1028460)
1107 matchbox-deskto 1299 [001] 34217.543584: do_fork: (c1028460)
1108 gthumb 1300 [001] 34217.697451: do_fork: (c1028460)
1109 gthumb 1300 [001] 34219.085734: do_fork: (c1028460)
1110 gthumb 1300 [000] 34219.121351: do_fork: (c1028460)
1111 gthumb 1300 [001] 34219.264551: do_fork: (c1028460)
1112 pcmanfm 1296 [000] 34219.590380: do_fork: (c1028460)
1113 matchbox-deskto 1197 [001] 34224.955965: do_fork: (c1028460)
1114 matchbox-deskto 1306 [001] 34224.957972: do_fork: (c1028460)
1115 matchbox-termin 1307 [000] 34225.038214: do_fork: (c1028460)
1116 matchbox-termin 1307 [001] 34225.044218: do_fork: (c1028460)
1117 matchbox-termin 1307 [000] 34225.046442: do_fork: (c1028460)
1118 matchbox-deskto 1197 [001] 34237.112138: do_fork: (c1028460)
1119 matchbox-deskto 1311 [001] 34237.114106: do_fork: (c1028460)
1120 gaku 1312 [000] 34237.202388: do_fork: (c1028460)
1121
1122And using 'perf report' on the same file, we can see the
881callgraphs from starting a few programs during those 30 seconds: 1123callgraphs from starting a few programs during those 30 seconds:
882 1124
883.. image:: figures/perf-probe-do_fork-profile.png 1125.. image:: figures/perf-probe-do_fork-profile.png
884 :align: center 1126 :align: center
885 1127
886.. container:: informalexample 1128.. admonition:: Tying it Together
887 1129
888 **Tying it Together**:
889 The trace events subsystem accommodate static and dynamic tracepoints 1130 The trace events subsystem accommodate static and dynamic tracepoints
890 in exactly the same way - there's no difference as far as the 1131 in exactly the same way - there's no difference as far as the
891 infrastructure is concerned. See the ftrace section for more details 1132 infrastructure is concerned. See the ftrace section for more details
892 on the trace event subsystem. 1133 on the trace event subsystem.
893 1134
894.. container:: informalexample 1135.. admonition:: Tying it Together
895 1136
896 **Tying it Together**:
897 Dynamic tracepoints are implemented under the covers by kprobes and 1137 Dynamic tracepoints are implemented under the covers by kprobes and
898 uprobes. kprobes and uprobes are also used by and in fact are the 1138 uprobes. kprobes and uprobes are also used by and in fact are the
899 main focus of SystemTap. 1139 main focus of SystemTap.
900 1140
901.. _perf-documentation: 1141.. _perf-documentation:
902 1142
903Documentation 1143Perf Documentation
904------------- 1144------------------
905 1145
906Online versions of the man pages for the commands discussed in this 1146Online versions of the man pages for the commands discussed in this
907section can be found here: 1147section can be found here:
@@ -934,8 +1174,11 @@ addressed by a Yocto bug: `Bug 3388 - perf: enable man pages for basic
934functionality <https://bugzilla.yoctoproject.org/show_bug.cgi?id=3388>`__. 1174functionality <https://bugzilla.yoctoproject.org/show_bug.cgi?id=3388>`__.
935 1175
936The man pages in text form, along with some other files, such as a set 1176The man pages in text form, along with some other files, such as a set
937of examples, can be found in the 'perf' directory of the kernel tree: 1177of examples, can be found in the 'perf' directory of the kernel tree: ::
938tools/perf/Documentation There's also a nice perf tutorial on the perf 1178
1179 tools/perf/Documentation
1180
1181There's also a nice perf tutorial on the perf
939wiki that goes into more detail than we do here in certain areas: `Perf 1182wiki that goes into more detail than we do here in certain areas: `Perf
940Tutorial <https://perf.wiki.kernel.org/index.php/Tutorial>`__ 1183Tutorial <https://perf.wiki.kernel.org/index.php/Tutorial>`__
941 1184
@@ -950,11 +1193,11 @@ infrastructure that they all make use of.
950 1193
951.. _ftrace-setup: 1194.. _ftrace-setup:
952 1195
953Setup 1196ftrace Setup
954----- 1197------------
955 1198
956For this section, we'll assume you've already performed the basic setup 1199For this section, we'll assume you've already performed the basic setup
957outlined in the General Setup section. 1200outlined in the ":ref:`profile-manual/profile-manual-intro:General Setup`" section.
958 1201
959ftrace, trace-cmd, and kernelshark run on the target system, and are 1202ftrace, trace-cmd, and kernelshark run on the target system, and are
960ready to go out-of-the-box - no additional setup is necessary. For the 1203ready to go out-of-the-box - no additional setup is necessary. For the
@@ -969,15 +1212,22 @@ Basic ftrace usage
969'ftrace' essentially refers to everything included in the /tracing 1212'ftrace' essentially refers to everything included in the /tracing
970directory of the mounted debugfs filesystem (Yocto follows the standard 1213directory of the mounted debugfs filesystem (Yocto follows the standard
971convention and mounts it at /sys/kernel/debug). Here's a listing of all 1214convention and mounts it at /sys/kernel/debug). Here's a listing of all
972the files found in /sys/kernel/debug/tracing on a Yocto system: 1215the files found in /sys/kernel/debug/tracing on a Yocto system: ::
973root@sugarbay:/sys/kernel/debug/tracing# ls README kprobe_events trace 1216
974available_events kprobe_profile trace_clock available_filter_functions 1217 root@sugarbay:/sys/kernel/debug/tracing# ls
975options trace_marker available_tracers per_cpu trace_options 1218 README kprobe_events trace
976buffer_size_kb printk_formats trace_pipe buffer_total_size_kb 1219 available_events kprobe_profile trace_clock
977saved_cmdlines tracing_cpumask current_tracer set_event tracing_enabled 1220 available_filter_functions options trace_marker
978dyn_ftrace_total_info set_ftrace_filter tracing_on enabled_functions 1221 available_tracers per_cpu trace_options
979set_ftrace_notrace tracing_thresh events set_ftrace_pid free_buffer 1222 buffer_size_kb printk_formats trace_pipe
980set_graph_function The files listed above are used for various purposes 1223 buffer_total_size_kb saved_cmdlines tracing_cpumask
1224 current_tracer set_event tracing_enabled
1225 dyn_ftrace_total_info set_ftrace_filter tracing_on
1226 enabled_functions set_ftrace_notrace tracing_thresh
1227 events set_ftrace_pid
1228 free_buffer set_graph_function
1229
1230The files listed above are used for various purposes
981- some relate directly to the tracers themselves, others are used to set 1231- some relate directly to the tracers themselves, others are used to set
982tracing options, and yet others actually contain the tracing output when 1232tracing options, and yet others actually contain the tracing output when
983a tracer is in effect. Some of the functions can be guessed from their 1233a tracer is in effect. Some of the functions can be guessed from their
@@ -987,118 +1237,206 @@ the ftrace documentation.
987 1237
988We'll start by looking at some of the available built-in tracers. 1238We'll start by looking at some of the available built-in tracers.
989 1239
990cat'ing the 'available_tracers' file lists the set of available tracers: 1240cat'ing the 'available_tracers' file lists the set of available tracers: ::
991root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers blk 1241
992function_graph function nop The 'current_tracer' file contains the 1242 root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers
993tracer currently in effect: root@sugarbay:/sys/kernel/debug/tracing# cat 1243 blk function_graph function nop
994current_tracer nop The above listing of current_tracer shows that the 1244
1245The 'current_tracer' file contains the tracer currently in effect: ::
1246
1247 root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer
1248 nop
1249
1250The above listing of current_tracer shows that the
995'nop' tracer is in effect, which is just another way of saying that 1251'nop' tracer is in effect, which is just another way of saying that
996there's actually no tracer currently in effect. 1252there's actually no tracer currently in effect.
997 1253
998echo'ing one of the available_tracers into current_tracer makes the 1254echo'ing one of the available_tracers into current_tracer makes the
999specified tracer the current tracer: 1255specified tracer the current tracer: ::
1000root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer 1256
1001root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer function The 1257 root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer
1002above sets the current tracer to be the 'function tracer'. This tracer 1258 root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer
1259 function
1260
1261The above sets the current tracer to be the 'function tracer'. This tracer
1003traces every function call in the kernel and makes it available as the 1262traces every function call in the kernel and makes it available as the
1004contents of the 'trace' file. Reading the 'trace' file lists the 1263contents of the 'trace' file. Reading the 'trace' file lists the
1005currently buffered function calls that have been traced by the function 1264currently buffered function calls that have been traced by the function
1006tracer: root@sugarbay:/sys/kernel/debug/tracing# cat trace \| less # 1265tracer: ::
1007tracer: function # # entries-in-buffer/entries-written: 310629/766471 1266
1008#P:8 # # \_-----=> irqs-off # / \_----=> need-resched # \| / \_---=> 1267 root@sugarbay:/sys/kernel/debug/tracing# cat trace | less
1009hardirq/softirq # \|\| / \_--=> preempt-depth # \||\| / delay # TASK-PID 1268
1010CPU# \|||\| TIMESTAMP FUNCTION # \| \| \| \|||\| \| \| <idle>-0 [004] 1269 # tracer: function
1011d..1 470.867169: ktime_get_real <-intel_idle <idle>-0 [004] d..1 1270 #
1012470.867170: getnstimeofday <-ktime_get_real <idle>-0 [004] d..1 1271 # entries-in-buffer/entries-written: 310629/766471 #P:8
1013470.867171: ns_to_timeval <-intel_idle <idle>-0 [004] d..1 470.867171: 1272 #
1014ns_to_timespec <-ns_to_timeval <idle>-0 [004] d..1 470.867172: 1273 # _-----=> irqs-off
1015smp_apic_timer_interrupt <-apic_timer_interrupt <idle>-0 [004] d..1 1274 # / _----=> need-resched
1016470.867172: native_apic_mem_write <-smp_apic_timer_interrupt <idle>-0 1275 # | / _---=> hardirq/softirq
1017[004] d..1 470.867172: irq_enter <-smp_apic_timer_interrupt <idle>-0 1276 # || / _--=> preempt-depth
1018[004] d..1 470.867172: rcu_irq_enter <-irq_enter <idle>-0 [004] d..1 1277 # ||| / delay
1019470.867173: rcu_idle_exit_common.isra.33 <-rcu_irq_enter <idle>-0 [004] 1278 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1020d..1 470.867173: local_bh_disable <-irq_enter <idle>-0 [004] d..1 1279 # | | | |||| | |
1021470.867173: add_preempt_count <-local_bh_disable <idle>-0 [004] d.s1 1280 <idle>-0 [004] d..1 470.867169: ktime_get_real <-intel_idle
1022470.867174: tick_check_idle <-irq_enter <idle>-0 [004] d.s1 470.867174: 1281 <idle>-0 [004] d..1 470.867170: getnstimeofday <-ktime_get_real
1023tick_check_oneshot_broadcast <-tick_check_idle <idle>-0 [004] d.s1 1282 <idle>-0 [004] d..1 470.867171: ns_to_timeval <-intel_idle
1024470.867174: ktime_get <-tick_check_idle <idle>-0 [004] d.s1 470.867174: 1283 <idle>-0 [004] d..1 470.867171: ns_to_timespec <-ns_to_timeval
1025tick_nohz_stop_idle <-tick_check_idle <idle>-0 [004] d.s1 470.867175: 1284 <idle>-0 [004] d..1 470.867172: smp_apic_timer_interrupt <-apic_timer_interrupt
1026update_ts_time_stats <-tick_nohz_stop_idle <idle>-0 [004] d.s1 1285 <idle>-0 [004] d..1 470.867172: native_apic_mem_write <-smp_apic_timer_interrupt
1027470.867175: nr_iowait_cpu <-update_ts_time_stats <idle>-0 [004] d.s1 1286 <idle>-0 [004] d..1 470.867172: irq_enter <-smp_apic_timer_interrupt
1028470.867175: tick_do_update_jiffies64 <-tick_check_idle <idle>-0 [004] 1287 <idle>-0 [004] d..1 470.867172: rcu_irq_enter <-irq_enter
1029d.s1 470.867175: \_raw_spin_lock <-tick_do_update_jiffies64 <idle>-0 1288 <idle>-0 [004] d..1 470.867173: rcu_idle_exit_common.isra.33 <-rcu_irq_enter
1030[004] d.s1 470.867176: add_preempt_count <-_raw_spin_lock <idle>-0 [004] 1289 <idle>-0 [004] d..1 470.867173: local_bh_disable <-irq_enter
1031d.s2 470.867176: do_timer <-tick_do_update_jiffies64 <idle>-0 [004] d.s2 1290 <idle>-0 [004] d..1 470.867173: add_preempt_count <-local_bh_disable
1032470.867176: \_raw_spin_lock <-do_timer <idle>-0 [004] d.s2 470.867176: 1291 <idle>-0 [004] d.s1 470.867174: tick_check_idle <-irq_enter
1033add_preempt_count <-_raw_spin_lock <idle>-0 [004] d.s3 470.867177: 1292 <idle>-0 [004] d.s1 470.867174: tick_check_oneshot_broadcast <-tick_check_idle
1034ntp_tick_length <-do_timer <idle>-0 [004] d.s3 470.867177: 1293 <idle>-0 [004] d.s1 470.867174: ktime_get <-tick_check_idle
1035\_raw_spin_lock_irqsave <-ntp_tick_length . . . Each line in the trace 1294 <idle>-0 [004] d.s1 470.867174: tick_nohz_stop_idle <-tick_check_idle
1036above shows what was happening in the kernel on a given cpu, to the 1295 <idle>-0 [004] d.s1 470.867175: update_ts_time_stats <-tick_nohz_stop_idle
1037level of detail of function calls. Each entry shows the function called, 1296 <idle>-0 [004] d.s1 470.867175: nr_iowait_cpu <-update_ts_time_stats
1038followed by its caller (after the arrow). 1297 <idle>-0 [004] d.s1 470.867175: tick_do_update_jiffies64 <-tick_check_idle
1298 <idle>-0 [004] d.s1 470.867175: _raw_spin_lock <-tick_do_update_jiffies64
1299 <idle>-0 [004] d.s1 470.867176: add_preempt_count <-_raw_spin_lock
1300 <idle>-0 [004] d.s2 470.867176: do_timer <-tick_do_update_jiffies64
1301 <idle>-0 [004] d.s2 470.867176: _raw_spin_lock <-do_timer
1302 <idle>-0 [004] d.s2 470.867176: add_preempt_count <-_raw_spin_lock
1303 <idle>-0 [004] d.s3 470.867177: ntp_tick_length <-do_timer
1304 <idle>-0 [004] d.s3 470.867177: _raw_spin_lock_irqsave <-ntp_tick_length
1305 .
1306 .
1307 .
1308
1309Each line in the trace above shows what was happening in the kernel on a given
1310cpu, to the level of detail of function calls. Each entry shows the function
1311called, followed by its caller (after the arrow).
1039 1312
1040The function tracer gives you an extremely detailed idea of what the 1313The function tracer gives you an extremely detailed idea of what the
1041kernel was doing at the point in time the trace was taken, and is a 1314kernel was doing at the point in time the trace was taken, and is a
1042great way to learn about how the kernel code works in a dynamic sense. 1315great way to learn about how the kernel code works in a dynamic sense.
1043 1316
1044.. container:: informalexample 1317.. admonition:: Tying it Together
1045 1318
1046 **Tying it Together**:
1047 The ftrace function tracer is also available from within perf, as the 1319 The ftrace function tracer is also available from within perf, as the
1048 ftrace:function tracepoint. 1320 ftrace:function tracepoint.
1049 1321
1050It is a little more difficult to follow the call chains than it needs to 1322It is a little more difficult to follow the call chains than it needs to
1051be - luckily there's a variant of the function tracer that displays the 1323be - luckily there's a variant of the function tracer that displays the
1052callchains explicitly, called the 'function_graph' tracer: 1324callchains explicitly, called the 'function_graph' tracer: ::
1053root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > 1325
1054current_tracer root@sugarbay:/sys/kernel/debug/tracing# cat trace \| 1326 root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer
1055less tracer: function_graph CPU DURATION FUNCTION CALLS \| \| \| \| \| 1327 root@sugarbay:/sys/kernel/debug/tracing# cat trace | less
1056\| \| 7) 0.046 us \| pick_next_task_fair(); 7) 0.043 us \| 1328
1057pick_next_task_stop(); 7) 0.042 us \| pick_next_task_rt(); 7) 0.032 us 1329 tracer: function_graph
1058\| pick_next_task_fair(); 7) 0.030 us \| pick_next_task_idle(); 7) \| 1330
1059\_raw_spin_unlock_irq() { 7) 0.033 us \| sub_preempt_count(); 7) 0.258 1331 CPU DURATION FUNCTION CALLS
1060us \| } 7) 0.032 us \| sub_preempt_count(); 7) + 13.341 us \| } /\* 1332 | | | | | | |
1061\__schedule \*/ 7) 0.095 us \| } /\* sub_preempt_count \*/ 7) \| 1333 7) 0.046 us | pick_next_task_fair();
1062schedule() { 7) \| \__schedule() { 7) 0.060 us \| add_preempt_count(); 1334 7) 0.043 us | pick_next_task_stop();
10637) 0.044 us \| rcu_note_context_switch(); 7) \| \_raw_spin_lock_irq() { 1335 7) 0.042 us | pick_next_task_rt();
10647) 0.033 us \| add_preempt_count(); 7) 0.247 us \| } 7) \| 1336 7) 0.032 us | pick_next_task_fair();
1065idle_balance() { 7) \| \_raw_spin_unlock() { 7) 0.031 us \| 1337 7) 0.030 us | pick_next_task_idle();
1066sub_preempt_count(); 7) 0.246 us \| } 7) \| update_shares() { 7) 0.030 1338 7) | _raw_spin_unlock_irq() {
1067us \| \__rcu_read_lock(); 7) 0.029 us \| \__rcu_read_unlock(); 7) 0.484 1339 7) 0.033 us | sub_preempt_count();
1068us \| } 7) 0.030 us \| \__rcu_read_lock(); 7) \| load_balance() { 7) \| 1340 7) 0.258 us | }
1069find_busiest_group() { 7) 0.031 us \| idle_cpu(); 7) 0.029 us \| 1341 7) 0.032 us | sub_preempt_count();
1070idle_cpu(); 7) 0.035 us \| idle_cpu(); 7) 0.906 us \| } 7) 1.141 us \| } 1342 7) + 13.341 us | } /* __schedule */
10717) 0.022 us \| msecs_to_jiffies(); 7) \| load_balance() { 7) \| 1343 7) 0.095 us | } /* sub_preempt_count */
1072find_busiest_group() { 7) 0.031 us \| idle_cpu(); . . . 4) 0.062 us \| 1344 7) | schedule() {
1073msecs_to_jiffies(); 4) 0.062 us \| \__rcu_read_unlock(); 4) \| 1345 7) | __schedule() {
1074\_raw_spin_lock() { 4) 0.073 us \| add_preempt_count(); 4) 0.562 us \| } 1346 7) 0.060 us | add_preempt_count();
10754) + 17.452 us \| } 4) 0.108 us \| put_prev_task_fair(); 4) 0.102 us \| 1347 7) 0.044 us | rcu_note_context_switch();
1076pick_next_task_fair(); 4) 0.084 us \| pick_next_task_stop(); 4) 0.075 us 1348 7) | _raw_spin_lock_irq() {
1077\| pick_next_task_rt(); 4) 0.062 us \| pick_next_task_fair(); 4) 0.066 1349 7) 0.033 us | add_preempt_count();
1078us \| pick_next_task_idle(); ------------------------------------------ 1350 7) 0.247 us | }
10794) kworker-74 => <idle>-0 ------------------------------------------ 4) 1351 7) | idle_balance() {
1080\| finish_task_switch() { 4) \| \_raw_spin_unlock_irq() { 4) 0.100 us \| 1352 7) | _raw_spin_unlock() {
1081sub_preempt_count(); 4) 0.582 us \| } 4) 1.105 us \| } 4) 0.088 us \| 1353 7) 0.031 us | sub_preempt_count();
1082sub_preempt_count(); 4) ! 100.066 us \| } . . . 3) \| sys_ioctl() { 3) 1354 7) 0.246 us | }
10830.083 us \| fget_light(); 3) \| security_file_ioctl() { 3) 0.066 us \| 1355 7) | update_shares() {
1084cap_file_ioctl(); 3) 0.562 us \| } 3) \| do_vfs_ioctl() { 3) \| 1356 7) 0.030 us | __rcu_read_lock();
1085drm_ioctl() { 3) 0.075 us \| drm_ut_debug_printk(); 3) \| 1357 7) 0.029 us | __rcu_read_unlock();
1086i915_gem_pwrite_ioctl() { 3) \| i915_mutex_lock_interruptible() { 3) 1358 7) 0.484 us | }
10870.070 us \| mutex_lock_interruptible(); 3) 0.570 us \| } 3) \| 1359 7) 0.030 us | __rcu_read_lock();
1088drm_gem_object_lookup() { 3) \| \_raw_spin_lock() { 3) 0.080 us \| 1360 7) | load_balance() {
1089add_preempt_count(); 3) 0.620 us \| } 3) \| \_raw_spin_unlock() { 3) 1361 7) | find_busiest_group() {
10900.085 us \| sub_preempt_count(); 3) 0.562 us \| } 3) 2.149 us \| } 3) 1362 7) 0.031 us | idle_cpu();
10910.133 us \| i915_gem_object_pin(); 3) \| 1363 7) 0.029 us | idle_cpu();
1092i915_gem_object_set_to_gtt_domain() { 3) 0.065 us \| 1364 7) 0.035 us | idle_cpu();
1093i915_gem_object_flush_gpu_write_domain(); 3) 0.065 us \| 1365 7) 0.906 us | }
1094i915_gem_object_wait_rendering(); 3) 0.062 us \| 1366 7) 1.141 us | }
1095i915_gem_object_flush_cpu_write_domain(); 3) 1.612 us \| } 3) \| 1367 7) 0.022 us | msecs_to_jiffies();
1096i915_gem_object_put_fence() { 3) 0.097 us \| 1368 7) | load_balance() {
1097i915_gem_object_flush_fence.constprop.36(); 3) 0.645 us \| } 3) 0.070 us 1369 7) | find_busiest_group() {
1098\| add_preempt_count(); 3) 0.070 us \| sub_preempt_count(); 3) 0.073 us 1370 7) 0.031 us | idle_cpu();
1099\| i915_gem_object_unpin(); 3) 0.068 us \| mutex_unlock(); 3) 9.924 us 1371 .
1100\| } 3) + 11.236 us \| } 3) + 11.770 us \| } 3) + 13.784 us \| } 3) \| 1372 .
1101sys_ioctl() { As you can see, the function_graph display is much easier 1373 .
1374 4) 0.062 us | msecs_to_jiffies();
1375 4) 0.062 us | __rcu_read_unlock();
1376 4) | _raw_spin_lock() {
1377 4) 0.073 us | add_preempt_count();
1378 4) 0.562 us | }
1379 4) + 17.452 us | }
1380 4) 0.108 us | put_prev_task_fair();
1381 4) 0.102 us | pick_next_task_fair();
1382 4) 0.084 us | pick_next_task_stop();
1383 4) 0.075 us | pick_next_task_rt();
1384 4) 0.062 us | pick_next_task_fair();
1385 4) 0.066 us | pick_next_task_idle();
1386 ------------------------------------------
1387 4) kworker-74 => <idle>-0
1388 ------------------------------------------
1389
1390 4) | finish_task_switch() {
1391 4) | _raw_spin_unlock_irq() {
1392 4) 0.100 us | sub_preempt_count();
1393 4) 0.582 us | }
1394 4) 1.105 us | }
1395 4) 0.088 us | sub_preempt_count();
1396 4) ! 100.066 us | }
1397 .
1398 .
1399 .
1400 3) | sys_ioctl() {
1401 3) 0.083 us | fget_light();
1402 3) | security_file_ioctl() {
1403 3) 0.066 us | cap_file_ioctl();
1404 3) 0.562 us | }
1405 3) | do_vfs_ioctl() {
1406 3) | drm_ioctl() {
1407 3) 0.075 us | drm_ut_debug_printk();
1408 3) | i915_gem_pwrite_ioctl() {
1409 3) | i915_mutex_lock_interruptible() {
1410 3) 0.070 us | mutex_lock_interruptible();
1411 3) 0.570 us | }
1412 3) | drm_gem_object_lookup() {
1413 3) | _raw_spin_lock() {
1414 3) 0.080 us | add_preempt_count();
1415 3) 0.620 us | }
1416 3) | _raw_spin_unlock() {
1417 3) 0.085 us | sub_preempt_count();
1418 3) 0.562 us | }
1419 3) 2.149 us | }
1420 3) 0.133 us | i915_gem_object_pin();
1421 3) | i915_gem_object_set_to_gtt_domain() {
1422 3) 0.065 us | i915_gem_object_flush_gpu_write_domain();
1423 3) 0.065 us | i915_gem_object_wait_rendering();
1424 3) 0.062 us | i915_gem_object_flush_cpu_write_domain();
1425 3) 1.612 us | }
1426 3) | i915_gem_object_put_fence() {
1427 3) 0.097 us | i915_gem_object_flush_fence.constprop.36();
1428 3) 0.645 us | }
1429 3) 0.070 us | add_preempt_count();
1430 3) 0.070 us | sub_preempt_count();
1431 3) 0.073 us | i915_gem_object_unpin();
1432 3) 0.068 us | mutex_unlock();
1433 3) 9.924 us | }
1434 3) + 11.236 us | }
1435 3) + 11.770 us | }
1436 3) + 13.784 us | }
1437 3) | sys_ioctl() {
1438
1439As you can see, the function_graph display is much easier
1102to follow. Also note that in addition to the function calls and 1440to follow. Also note that in addition to the function calls and
1103associated braces, other events such as scheduler events are displayed 1441associated braces, other events such as scheduler events are displayed
1104in context. In fact, you can freely include any tracepoint available in 1442in context. In fact, you can freely include any tracepoint available in
@@ -1119,197 +1457,196 @@ One especially important directory contained within the
1119/sys/kernel/debug/tracing directory is the 'events' subdirectory, which 1457/sys/kernel/debug/tracing directory is the 'events' subdirectory, which
1120contains representations of every tracepoint in the system. Listing out 1458contains representations of every tracepoint in the system. Listing out
1121the contents of the 'events' subdirectory, we see mainly another set of 1459the contents of the 'events' subdirectory, we see mainly another set of
1122subdirectories: root@sugarbay:/sys/kernel/debug/tracing# cd events 1460subdirectories: ::
1123root@sugarbay:/sys/kernel/debug/tracing/events# ls -al drwxr-xr-x 38 1461
1124root root 0 Nov 14 23:19 . drwxr-xr-x 5 root root 0 Nov 14 23:19 .. 1462 root@sugarbay:/sys/kernel/debug/tracing# cd events
1125drwxr-xr-x 19 root root 0 Nov 14 23:19 block drwxr-xr-x 32 root root 0 1463 root@sugarbay:/sys/kernel/debug/tracing/events# ls -al
1126Nov 14 23:19 btrfs drwxr-xr-x 5 root root 0 Nov 14 23:19 drm -rw-r--r-- 1464 drwxr-xr-x 38 root root 0 Nov 14 23:19 .
11271 root root 0 Nov 14 23:19 enable drwxr-xr-x 40 root root 0 Nov 14 23:19 1465 drwxr-xr-x 5 root root 0 Nov 14 23:19 ..
1128ext3 drwxr-xr-x 79 root root 0 Nov 14 23:19 ext4 drwxr-xr-x 14 root root 1466 drwxr-xr-x 19 root root 0 Nov 14 23:19 block
11290 Nov 14 23:19 ftrace drwxr-xr-x 8 root root 0 Nov 14 23:19 hda 1467 drwxr-xr-x 32 root root 0 Nov 14 23:19 btrfs
1130-r--r--r-- 1 root root 0 Nov 14 23:19 header_event -r--r--r-- 1 root 1468 drwxr-xr-x 5 root root 0 Nov 14 23:19 drm
1131root 0 Nov 14 23:19 header_page drwxr-xr-x 25 root root 0 Nov 14 23:19 1469 -rw-r--r-- 1 root root 0 Nov 14 23:19 enable
1132i915 drwxr-xr-x 7 root root 0 Nov 14 23:19 irq drwxr-xr-x 12 root root 0 1470 drwxr-xr-x 40 root root 0 Nov 14 23:19 ext3
1133Nov 14 23:19 jbd drwxr-xr-x 14 root root 0 Nov 14 23:19 jbd2 drwxr-xr-x 1471 drwxr-xr-x 79 root root 0 Nov 14 23:19 ext4
113414 root root 0 Nov 14 23:19 kmem drwxr-xr-x 7 root root 0 Nov 14 23:19 1472 drwxr-xr-x 14 root root 0 Nov 14 23:19 ftrace
1135module drwxr-xr-x 3 root root 0 Nov 14 23:19 napi drwxr-xr-x 6 root root 1473 drwxr-xr-x 8 root root 0 Nov 14 23:19 hda
11360 Nov 14 23:19 net drwxr-xr-x 3 root root 0 Nov 14 23:19 oom drwxr-xr-x 1474 -r--r--r-- 1 root root 0 Nov 14 23:19 header_event
113712 root root 0 Nov 14 23:19 power drwxr-xr-x 3 root root 0 Nov 14 23:19 1475 -r--r--r-- 1 root root 0 Nov 14 23:19 header_page
1138printk drwxr-xr-x 8 root root 0 Nov 14 23:19 random drwxr-xr-x 4 root 1476 drwxr-xr-x 25 root root 0 Nov 14 23:19 i915
1139root 0 Nov 14 23:19 raw_syscalls drwxr-xr-x 3 root root 0 Nov 14 23:19 1477 drwxr-xr-x 7 root root 0 Nov 14 23:19 irq
1140rcu drwxr-xr-x 6 root root 0 Nov 14 23:19 rpm drwxr-xr-x 20 root root 0 1478 drwxr-xr-x 12 root root 0 Nov 14 23:19 jbd
1141Nov 14 23:19 sched drwxr-xr-x 7 root root 0 Nov 14 23:19 scsi drwxr-xr-x 1479 drwxr-xr-x 14 root root 0 Nov 14 23:19 jbd2
11424 root root 0 Nov 14 23:19 signal drwxr-xr-x 5 root root 0 Nov 14 23:19 1480 drwxr-xr-x 14 root root 0 Nov 14 23:19 kmem
1143skb drwxr-xr-x 4 root root 0 Nov 14 23:19 sock drwxr-xr-x 10 root root 0 1481 drwxr-xr-x 7 root root 0 Nov 14 23:19 module
1144Nov 14 23:19 sunrpc drwxr-xr-x 538 root root 0 Nov 14 23:19 syscalls 1482 drwxr-xr-x 3 root root 0 Nov 14 23:19 napi
1145drwxr-xr-x 4 root root 0 Nov 14 23:19 task drwxr-xr-x 14 root root 0 Nov 1483 drwxr-xr-x 6 root root 0 Nov 14 23:19 net
114614 23:19 timer drwxr-xr-x 3 root root 0 Nov 14 23:19 udp drwxr-xr-x 21 1484 drwxr-xr-x 3 root root 0 Nov 14 23:19 oom
1147root root 0 Nov 14 23:19 vmscan drwxr-xr-x 3 root root 0 Nov 14 23:19 1485 drwxr-xr-x 12 root root 0 Nov 14 23:19 power
1148vsyscall drwxr-xr-x 6 root root 0 Nov 14 23:19 workqueue drwxr-xr-x 26 1486 drwxr-xr-x 3 root root 0 Nov 14 23:19 printk
1149root root 0 Nov 14 23:19 writeback Each one of these subdirectories 1487 drwxr-xr-x 8 root root 0 Nov 14 23:19 random
1488 drwxr-xr-x 4 root root 0 Nov 14 23:19 raw_syscalls
1489 drwxr-xr-x 3 root root 0 Nov 14 23:19 rcu
1490 drwxr-xr-x 6 root root 0 Nov 14 23:19 rpm
1491 drwxr-xr-x 20 root root 0 Nov 14 23:19 sched
1492 drwxr-xr-x 7 root root 0 Nov 14 23:19 scsi
1493 drwxr-xr-x 4 root root 0 Nov 14 23:19 signal
1494 drwxr-xr-x 5 root root 0 Nov 14 23:19 skb
1495 drwxr-xr-x 4 root root 0 Nov 14 23:19 sock
1496 drwxr-xr-x 10 root root 0 Nov 14 23:19 sunrpc
1497 drwxr-xr-x 538 root root 0 Nov 14 23:19 syscalls
1498 drwxr-xr-x 4 root root 0 Nov 14 23:19 task
1499 drwxr-xr-x 14 root root 0 Nov 14 23:19 timer
1500 drwxr-xr-x 3 root root 0 Nov 14 23:19 udp
1501 drwxr-xr-x 21 root root 0 Nov 14 23:19 vmscan
1502 drwxr-xr-x 3 root root 0 Nov 14 23:19 vsyscall
1503 drwxr-xr-x 6 root root 0 Nov 14 23:19 workqueue
1504 drwxr-xr-x 26 root root 0 Nov 14 23:19 writeback
1505
1506Each one of these subdirectories
1150corresponds to a 'subsystem' and contains yet again more subdirectories, 1507corresponds to a 'subsystem' and contains yet again more subdirectories,
1151each one of those finally corresponding to a tracepoint. For example, 1508each one of those finally corresponding to a tracepoint. For example,
1152here are the contents of the 'kmem' subsystem: 1509here are the contents of the 'kmem' subsystem: ::
1153root@sugarbay:/sys/kernel/debug/tracing/events# cd kmem 1510
1154root@sugarbay:/sys/kernel/debug/tracing/events/kmem# ls -al drwxr-xr-x 1511 root@sugarbay:/sys/kernel/debug/tracing/events# cd kmem
115514 root root 0 Nov 14 23:19 . drwxr-xr-x 38 root root 0 Nov 14 23:19 .. 1512 root@sugarbay:/sys/kernel/debug/tracing/events/kmem# ls -al
1156-rw-r--r-- 1 root root 0 Nov 14 23:19 enable -rw-r--r-- 1 root root 0 1513 drwxr-xr-x 14 root root 0 Nov 14 23:19 .
1157Nov 14 23:19 filter drwxr-xr-x 2 root root 0 Nov 14 23:19 kfree 1514 drwxr-xr-x 38 root root 0 Nov 14 23:19 ..
1158drwxr-xr-x 2 root root 0 Nov 14 23:19 kmalloc drwxr-xr-x 2 root root 0 1515 -rw-r--r-- 1 root root 0 Nov 14 23:19 enable
1159Nov 14 23:19 kmalloc_node drwxr-xr-x 2 root root 0 Nov 14 23:19 1516 -rw-r--r-- 1 root root 0 Nov 14 23:19 filter
1160kmem_cache_alloc drwxr-xr-x 2 root root 0 Nov 14 23:19 1517 drwxr-xr-x 2 root root 0 Nov 14 23:19 kfree
1161kmem_cache_alloc_node drwxr-xr-x 2 root root 0 Nov 14 23:19 1518 drwxr-xr-x 2 root root 0 Nov 14 23:19 kmalloc
1162kmem_cache_free drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc 1519 drwxr-xr-x 2 root root 0 Nov 14 23:19 kmalloc_node
1163drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc_extfrag drwxr-xr-x 2 1520 drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_alloc
1164root root 0 Nov 14 23:19 mm_page_alloc_zone_locked drwxr-xr-x 2 root 1521 drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_alloc_node
1165root 0 Nov 14 23:19 mm_page_free drwxr-xr-x 2 root root 0 Nov 14 23:19 1522 drwxr-xr-x 2 root root 0 Nov 14 23:19 kmem_cache_free
1166mm_page_free_batched drwxr-xr-x 2 root root 0 Nov 14 23:19 1523 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc
1167mm_page_pcpu_drain Let's see what's inside the subdirectory for a 1524 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc_extfrag
1168specific tracepoint, in this case the one for kmalloc: 1525 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_alloc_zone_locked
1169root@sugarbay:/sys/kernel/debug/tracing/events/kmem# cd kmalloc 1526 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_free
1170root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# ls -al 1527 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_free_batched
1171drwxr-xr-x 2 root root 0 Nov 14 23:19 . drwxr-xr-x 14 root root 0 Nov 14 1528 drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_pcpu_drain
117223:19 .. -rw-r--r-- 1 root root 0 Nov 14 23:19 enable -rw-r--r-- 1 root 1529
1173root 0 Nov 14 23:19 filter -r--r--r-- 1 root root 0 Nov 14 23:19 format 1530Let's see what's inside the subdirectory for a
1174-r--r--r-- 1 root root 0 Nov 14 23:19 id The 'format' file for the 1531specific tracepoint, in this case the one for kmalloc: ::
1532
1533 root@sugarbay:/sys/kernel/debug/tracing/events/kmem# cd kmalloc
1534 root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# ls -al
1535 drwxr-xr-x 2 root root 0 Nov 14 23:19 .
1536 drwxr-xr-x 14 root root 0 Nov 14 23:19 ..
1537 -rw-r--r-- 1 root root 0 Nov 14 23:19 enable
1538 -rw-r--r-- 1 root root 0 Nov 14 23:19 filter
1539 -r--r--r-- 1 root root 0 Nov 14 23:19 format
1540 -r--r--r-- 1 root root 0 Nov 14 23:19 id
1541
1542The 'format' file for the
1175tracepoint describes the event in memory, which is used by the various 1543tracepoint describes the event in memory, which is used by the various
1176tracing tools that now make use of these tracepoint to parse the event 1544tracing tools that now make use of these tracepoint to parse the event
1177and make sense of it, along with a 'print fmt' field that allows tools 1545and make sense of it, along with a 'print fmt' field that allows tools
1178like ftrace to display the event as text. Here's what the format of the 1546like ftrace to display the event as text. Here's what the format of the
1179kmalloc event looks like: 1547kmalloc event looks like: ::
1180root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format 1548
1181name: kmalloc ID: 313 format: field:unsigned short common_type; 1549 root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format
1182offset:0; size:2; signed:0; field:unsigned char common_flags; offset:2; 1550 name: kmalloc
1183size:1; signed:0; field:unsigned char common_preempt_count; offset:3; 1551 ID: 313
1184size:1; signed:0; field:int common_pid; offset:4; size:4; signed:1; 1552 format:
1185field:int common_padding; offset:8; size:4; signed:1; field:unsigned 1553 field:unsigned short common_type; offset:0; size:2; signed:0;
1186long call_site; offset:16; size:8; signed:0; field:const void \* ptr; 1554 field:unsigned char common_flags; offset:2; size:1; signed:0;
1187offset:24; size:8; signed:0; field:size_t bytes_req; offset:32; size:8; 1555 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
1188signed:0; field:size_t bytes_alloc; offset:40; size:8; signed:0; 1556 field:int common_pid; offset:4; size:4; signed:1;
1189field:gfp_t gfp_flags; offset:48; size:4; signed:0; print fmt: 1557 field:int common_padding; offset:8; size:4; signed:1;
1190"call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", 1558
1191REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, 1559 field:unsigned long call_site; offset:16; size:8; signed:0;
1192(REC->gfp_flags) ? \__print_flags(REC->gfp_flags, "|", {(unsigned 1560 field:const void * ptr; offset:24; size:8; signed:0;
1193long)(((( gfp_t)0x10u) \| (( gfp_t)0x40u) \| (( gfp_t)0x80u) \| (( 1561 field:size_t bytes_req; offset:32; size:8; signed:0;
1194gfp_t)0x20000u) \| (( gfp_t)0x02u) \| (( gfp_t)0x08u)) \| (( 1562 field:size_t bytes_alloc; offset:40; size:8; signed:0;
1195gfp_t)0x4000u) \| (( gfp_t)0x10000u) \| (( gfp_t)0x1000u) \| (( 1563 field:gfp_t gfp_flags; offset:48; size:4; signed:0;
1196gfp_t)0x200u) \| (( gfp_t)0x400000u)), "GFP_TRANSHUGE"}, {(unsigned 1564
1197long)((( gfp_t)0x10u) \| (( gfp_t)0x40u) \| (( gfp_t)0x80u) \| (( 1565 print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc,
1198gfp_t)0x20000u) \| (( gfp_t)0x02u) \| (( gfp_t)0x08u)), 1566 (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)(((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | ((
1199"GFP_HIGHUSER_MOVABLE"}, {(unsigned long)((( gfp_t)0x10u) \| (( 1567 gfp_t)0x20000u) | (( gfp_t)0x02u) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u) | ((
1200gfp_t)0x40u) \| (( gfp_t)0x80u) \| (( gfp_t)0x20000u) \| (( 1568 gfp_t)0x400000u)), "GFP_TRANSHUGE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u) | ((
1201gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)0x10u) \| (( 1569 gfp_t)0x02u) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | ((
1202gfp_t)0x40u) \| (( gfp_t)0x80u) \| (( gfp_t)0x20000u)), "GFP_USER"}, 1570 gfp_t)0x20000u) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | ((
1203{(unsigned long)((( gfp_t)0x10u) \| (( gfp_t)0x40u) \| (( gfp_t)0x80u) 1571 gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x80000u)), GFP_TEMPORARY"},
1204\| (( gfp_t)0x80000u)), GFP_TEMPORARY"}, {(unsigned long)((( 1572 {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u)),
1205gfp_t)0x10u) \| (( gfp_t)0x40u) \| (( gfp_t)0x80u)), "GFP_KERNEL"}, 1573 "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)((
1206{(unsigned long)((( gfp_t)0x10u) \| (( gfp_t)0x40u)), "GFP_NOFS"}, 1574 gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x10u), "GFP_WAIT"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)((
1207{(unsigned long)((( gfp_t)0x20u)), "GFP_ATOMIC"}, {(unsigned long)((( 1575 gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned
1208gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), 1576 long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"},
1209"GFP_HIGH"}, {(unsigned long)(( gfp_t)0x10u), "GFP_WAIT"}, {(unsigned 1577 {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u),
1210long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), 1578 "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_RECLAIMABLE"}, {(unsigned
1211"GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned 1579 long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"},
1212long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), 1580 {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
1213"GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, 1581
1214{(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( 1582The 'enable' file
1215gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u),
1216"GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"},
1217{(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)((
1218gfp_t)0x80000u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x08u),
1219"GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0), "GFP_NOTRACK"}, {(unsigned
1220long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"}, {(unsigned long)((
1221gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT" The 'enable' file
1222in the tracepoint directory is what allows the user (or tools such as 1583in the tracepoint directory is what allows the user (or tools such as
1223trace-cmd) to actually turn the tracepoint on and off. When enabled, the 1584trace-cmd) to actually turn the tracepoint on and off. When enabled, the
1224corresponding tracepoint will start appearing in the ftrace 'trace' file 1585corresponding tracepoint will start appearing in the ftrace 'trace' file
1225described previously. For example, this turns on the kmalloc tracepoint: 1586described previously. For example, this turns on the kmalloc tracepoint: ::
1226root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > 1587
1227enable At the moment, we're not interested in the function tracer or 1588 root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > enable
1589
1590At the moment, we're not interested in the function tracer or
1228some other tracer that might be in effect, so we first turn it off, but 1591some other tracer that might be in effect, so we first turn it off, but
1229if we do that, we still need to turn tracing on in order to see the 1592if we do that, we still need to turn tracing on in order to see the
1230events in the output buffer: root@sugarbay:/sys/kernel/debug/tracing# 1593events in the output buffer: ::
1231echo nop > current_tracer root@sugarbay:/sys/kernel/debug/tracing# echo 1594
12321 > tracing_on Now, if we look at the the 'trace' file, we see nothing 1595 root@sugarbay:/sys/kernel/debug/tracing# echo nop > current_tracer
1233but the kmalloc events we just turned on: 1596 root@sugarbay:/sys/kernel/debug/tracing# echo 1 > tracing_on
1234root@sugarbay:/sys/kernel/debug/tracing# cat trace \| less # tracer: nop 1597
1235# # entries-in-buffer/entries-written: 1897/1897 #P:8 # # \_-----=> 1598Now, if we look at the the 'trace' file, we see nothing
1236irqs-off # / \_----=> need-resched # \| / \_---=> hardirq/softirq # \|\| 1599but the kmalloc events we just turned on: ::
1237/ \_--=> preempt-depth # \||\| / delay # TASK-PID CPU# \|||\| TIMESTAMP 1600
1238FUNCTION # \| \| \| \|||\| \| \| dropbear-1465 [000] ...1 18154.620753: 1601 root@sugarbay:/sys/kernel/debug/tracing# cat trace | less
1239kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 1602 # tracer: nop
1240bytes_alloc=2048 gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 18154.621640: 1603 #
1241kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 1604 # entries-in-buffer/entries-written: 1897/1897 #P:8
1242bytes_alloc=512 gfp_flags=GFP_ATOMIC <idle>-0 [000] ..s3 18154.621656: 1605 #
1243kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 1606 # _-----=> irqs-off
1244bytes_alloc=512 gfp_flags=GFP_ATOMIC matchbox-termin-1361 [001] ...1 1607 # / _----=> need-resched
124518154.755472: kmalloc: call_site=ffffffff81614050 ptr=ffff88006d5f0e00 1608 # | / _---=> hardirq/softirq
1246bytes_req=512 bytes_alloc=512 gfp_flags=GFP_KERNEL|GFP_REPEAT Xorg-1264 1609 # || / _--=> preempt-depth
1247[002] ...1 18154.755581: kmalloc: call_site=ffffffff8141abe8 1610 # ||| / delay
1248ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 1611 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1249gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY Xorg-1264 [002] ...1 1612 # | | | |||| | |
125018154.755583: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 1613 dropbear-1465 [000] ...1 18154.620753: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
1251bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO Xorg-1264 1614 <idle>-0 [000] ..s3 18154.621640: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1252[002] ...1 18154.755589: kmalloc: call_site=ffffffff81419edb 1615 <idle>-0 [000] ..s3 18154.621656: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1253ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 1616 matchbox-termin-1361 [001] ...1 18154.755472: kmalloc: call_site=ffffffff81614050 ptr=ffff88006d5f0e00 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_KERNEL|GFP_REPEAT
1254gfp_flags=GFP_KERNEL|GFP_ZERO matchbox-termin-1361 [001] ...1 1617 Xorg-1264 [002] ...1 18154.755581: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY
125518155.354594: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db35400 1618 Xorg-1264 [002] ...1 18154.755583: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
1256bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT Xorg-1264 1619 Xorg-1264 [002] ...1 18154.755589: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO
1257[002] ...1 18155.354703: kmalloc: call_site=ffffffff8141abe8 1620 matchbox-termin-1361 [001] ...1 18155.354594: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db35400 bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT
1258ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 1621 Xorg-1264 [002] ...1 18155.354703: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY
1259gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY Xorg-1264 [002] ...1 1622 Xorg-1264 [002] ...1 18155.354705: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
126018155.354705: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 1623 Xorg-1264 [002] ...1 18155.354711: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO
1261bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO Xorg-1264 1624 <idle>-0 [000] ..s3 18155.673319: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1262[002] ...1 18155.354711: kmalloc: call_site=ffffffff81419edb 1625 dropbear-1465 [000] ...1 18155.673525: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
1263ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 1626 <idle>-0 [000] ..s3 18155.674821: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1264gfp_flags=GFP_KERNEL|GFP_ZERO <idle>-0 [000] ..s3 18155.673319: kmalloc: 1627 <idle>-0 [000] ..s3 18155.793014: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1265call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 1628 dropbear-1465 [000] ...1 18155.793219: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
1266bytes_alloc=512 gfp_flags=GFP_ATOMIC dropbear-1465 [000] ...1 1629 <idle>-0 [000] ..s3 18155.794147: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
126718155.673525: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 1630 <idle>-0 [000] ..s3 18155.936705: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1268bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 1631 dropbear-1465 [000] ...1 18155.936910: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
126918155.674821: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 1632 <idle>-0 [000] ..s3 18155.937869: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1270bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC <idle>-0 [000] ..s3 1633 matchbox-termin-1361 [001] ...1 18155.953667: kmalloc: call_site=ffffffff81614050 ptr=ffff88006d5f2000 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_KERNEL|GFP_REPEAT
127118155.793014: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 1634 Xorg-1264 [002] ...1 18155.953775: kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY
1272bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC dropbear-1465 [000] 1635 Xorg-1264 [002] ...1 18155.953777: kmalloc: call_site=ffffffff814192a3 ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO
1273...1 18155.793219: kmalloc: call_site=ffffffff816650d4 1636 Xorg-1264 [002] ...1 18155.953783: kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO
1274ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 1637 <idle>-0 [000] ..s3 18156.176053: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1275gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 18155.794147: kmalloc: 1638 dropbear-1465 [000] ...1 18156.176257: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
1276call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 1639 <idle>-0 [000] ..s3 18156.177717: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1277bytes_alloc=512 gfp_flags=GFP_ATOMIC <idle>-0 [000] ..s3 18155.936705: 1640 <idle>-0 [000] ..s3 18156.399229: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
1278kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512 1641 dropbear-1465 [000] ...1 18156.399434: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 bytes_http://rostedt.homelinux.com/kernelshark/req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL
1279bytes_alloc=512 gfp_flags=GFP_ATOMIC dropbear-1465 [000] ...1 1642 <idle>-0 [000] ..s3 18156.400660: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC
128018155.936910: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000 1643 matchbox-termin-1361 [001] ...1 18156.552800: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db34800 bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT
1281bytes_req=2048 bytes_alloc=2048 gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 1644
128218155.937869: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 1645To again disable the kmalloc event, we need to send 0 to the enable file: ::
1283bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC matchbox-termin-1361 1646
1284[001] ...1 18155.953667: kmalloc: call_site=ffffffff81614050 1647 root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 > enable
1285ptr=ffff88006d5f2000 bytes_req=512 bytes_alloc=512 1648
1286gfp_flags=GFP_KERNEL|GFP_REPEAT Xorg-1264 [002] ...1 18155.953775: 1649You can enable any number of events or complete subsystems (by
1287kmalloc: call_site=ffffffff8141abe8 ptr=ffff8800734f4cc0 bytes_req=168
1288bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_NOWARN|GFP_NORETRY Xorg-1264
1289[002] ...1 18155.953777: kmalloc: call_site=ffffffff814192a3
1290ptr=ffff88001f822520 bytes_req=24 bytes_alloc=32
1291gfp_flags=GFP_KERNEL|GFP_ZERO Xorg-1264 [002] ...1 18155.953783:
1292kmalloc: call_site=ffffffff81419edb ptr=ffff8800721a2f00 bytes_req=64
1293bytes_alloc=64 gfp_flags=GFP_KERNEL|GFP_ZERO <idle>-0 [000] ..s3
129418156.176053: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800
1295bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC dropbear-1465 [000]
1296...1 18156.176257: kmalloc: call_site=ffffffff816650d4
1297ptr=ffff8800729c3000 bytes_req=2048 bytes_alloc=2048
1298gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 18156.177717: kmalloc:
1299call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512
1300bytes_alloc=512 gfp_flags=GFP_ATOMIC <idle>-0 [000] ..s3 18156.399229:
1301kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d555800 bytes_req=512
1302bytes_alloc=512 gfp_flags=GFP_ATOMIC dropbear-1465 [000] ...1
130318156.399434: kmalloc: call_site=ffffffff816650d4 ptr=ffff8800729c3000
1304bytes_http://rostedt.homelinux.com/kernelshark/req=2048 bytes_alloc=2048
1305gfp_flags=GFP_KERNEL <idle>-0 [000] ..s3 18156.400660: kmalloc:
1306call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512
1307bytes_alloc=512 gfp_flags=GFP_ATOMIC matchbox-termin-1361 [001] ...1
130818156.552800: kmalloc: call_site=ffffffff81614050 ptr=ffff88006db34800
1309bytes_req=576 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_REPEAT To again
1310disable the kmalloc event, we need to send 0 to the enable file:
1311root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 >
1312enable You can enable any number of events or complete subsystems (by
1313using the 'enable' file in the subsystem directory) and get an 1650using the 'enable' file in the subsystem directory) and get an
1314arbitrarily fine-grained idea of what's going on in the system by 1651arbitrarily fine-grained idea of what's going on in the system by
1315enabling as many of the appropriate tracepoints as applicable. 1652enabling as many of the appropriate tracepoints as applicable.
@@ -1317,18 +1654,16 @@ enabling as many of the appropriate tracepoints as applicable.
1317A number of the tools described in this HOWTO do just that, including 1654A number of the tools described in this HOWTO do just that, including
1318trace-cmd and kernelshark in the next section. 1655trace-cmd and kernelshark in the next section.
1319 1656
1320.. container:: informalexample 1657.. admonition:: Tying it Together
1321 1658
1322 **Tying it Together**:
1323 These tracepoints and their representation are used not only by 1659 These tracepoints and their representation are used not only by
1324 ftrace, but by many of the other tools covered in this document and 1660 ftrace, but by many of the other tools covered in this document and
1325 they form a central point of integration for the various tracers 1661 they form a central point of integration for the various tracers
1326 available in Linux. They form a central part of the instrumentation 1662 available in Linux. They form a central part of the instrumentation
1327 for the following tools: perf, lttng, ftrace, blktrace and SystemTap 1663 for the following tools: perf, lttng, ftrace, blktrace and SystemTap
1328 1664
1329.. container:: informalexample 1665.. admonition:: Tying it Together
1330 1666
1331 **Tying it Together**:
1332 Eventually all the special-purpose tracers currently available in 1667 Eventually all the special-purpose tracers currently available in
1333 /sys/kernel/debug/tracing will be removed and replaced with 1668 /sys/kernel/debug/tracing will be removed and replaced with
1334 equivalent tracers based on the 'trace events' subsystem. 1669 equivalent tracers based on the 'trace events' subsystem.
@@ -1351,11 +1686,17 @@ a per-CPU graphical display. It directly uses 'trace-cmd' as the
1351plumbing that accomplishes all that underneath the covers (and actually 1686plumbing that accomplishes all that underneath the covers (and actually
1352displays the trace-cmd command it uses, as we'll see). 1687displays the trace-cmd command it uses, as we'll see).
1353 1688
1354To start a trace using kernelshark, first start kernelshark: 1689To start a trace using kernelshark, first start kernelshark: ::
1355root@sugarbay:~# kernelshark Then bring up the 'Capture' dialog by 1690
1356choosing from the kernelshark menu: Capture \| Record That will display 1691 root@sugarbay:~# kernelshark
1357the following dialog, which allows you to choose one or more events (or 1692
1358even one or more complete subsystems) to trace: 1693Then bring up the 'Capture' dialog by
1694choosing from the kernelshark menu: ::
1695
1696 Capture | Record
1697
1698That will display the following dialog, which allows you to choose one or more
1699events (or even one or more complete subsystems) to trace:
1359 1700
1360.. image:: figures/kernelshark-choose-events.png 1701.. image:: figures/kernelshark-choose-events.png
1361 :align: center 1702 :align: center
@@ -1398,14 +1739,20 @@ website <http://rostedt.homelinux.com/kernelshark/>`__.
1398 1739
1399.. _ftrace-documentation: 1740.. _ftrace-documentation:
1400 1741
1401Documentation 1742ftrace Documentation
1402------------- 1743--------------------
1403 1744
1404The documentation for ftrace can be found in the kernel Documentation 1745The documentation for ftrace can be found in the kernel Documentation
1405directory: Documentation/trace/ftrace.txt The documentation for the 1746directory: ::
1406trace event subsystem can also be found in the kernel Documentation 1747
1407directory: Documentation/trace/events.txt There is a nice series of 1748 Documentation/trace/ftrace.txt
1408articles on using ftrace and trace-cmd at LWN: 1749
1750The documentation for the trace event subsystem can also be found in the kernel
1751Documentation directory: ::
1752
1753 Documentation/trace/events.txt
1754
1755There is a nice series of articles on using ftrace and trace-cmd at LWN:
1409 1756
1410- `Debugging the kernel using Ftrace - part 1757- `Debugging the kernel using Ftrace - part
1411 1 <http://lwn.net/Articles/365835/>`__ 1758 1 <http://lwn.net/Articles/365835/>`__
@@ -1423,7 +1770,7 @@ There's more detailed documentation kernelshark usage here:
1423`KernelShark <http://rostedt.homelinux.com/kernelshark/>`__ 1770`KernelShark <http://rostedt.homelinux.com/kernelshark/>`__
1424 1771
1425An amusing yet useful README (a tracing mini-HOWTO) can be found in 1772An amusing yet useful README (a tracing mini-HOWTO) can be found in
1426/sys/kernel/debug/tracing/README. 1773``/sys/kernel/debug/tracing/README``.
1427 1774
1428.. _profile-manual-systemtap: 1775.. _profile-manual-systemtap:
1429 1776
@@ -1441,12 +1788,27 @@ tutorial <http://sourceware.org/systemtap/tutorial/>`__ simply prints a
1441line every time any process on the system open()s a file. For each line, 1788line every time any process on the system open()s a file. For each line,
1442it prints the executable name of the program that opened the file, along 1789it prints the executable name of the program that opened the file, along
1443with its PID, and the name of the file it opened (or tried to open), 1790with its PID, and the name of the file it opened (or tried to open),
1444which it extracts from the open syscall's argstr. probe syscall.open { 1791which it extracts from the open syscall's argstr.
1445printf ("%s(%d) open (%s)\n", execname(), pid(), argstr) } probe 1792
1446timer.ms(4000) # after 4 seconds { exit () } Normally, to execute this 1793.. code-block:: none
1794
1795 probe syscall.open
1796 {
1797 printf ("%s(%d) open (%s)\n", execname(), pid(), argstr)
1798 }
1799
1800 probe timer.ms(4000) # after 4 seconds
1801 {
1802 exit ()
1803 }
1804
1805Normally, to execute this
1447probe, you'd simply install systemtap on the system you want to probe, 1806probe, you'd simply install systemtap on the system you want to probe,
1448and directly run the probe on that system e.g. assuming the name of the 1807and directly run the probe on that system e.g. assuming the name of the
1449file containing the above text is trace_open.stp: # stap trace_open.stp 1808file containing the above text is trace_open.stp: ::
1809
1810 # stap trace_open.stp
1811
1450What systemtap does under the covers to run this probe is 1) parse and 1812What systemtap does under the covers to run this probe is 1) parse and
1451convert the probe to an equivalent 'C' form, 2) compile the 'C' form 1813convert the probe to an equivalent 'C' form, 2) compile the 'C' form
1452into a kernel module, 3) insert the module into the kernel, which arms 1814into a kernel module, 3) insert the module into the kernel, which arms
@@ -1475,8 +1837,8 @@ to the user.
1475 1837
1476.. _systemtap-setup: 1838.. _systemtap-setup:
1477 1839
1478Setup 1840systemtap Setup
1479----- 1841---------------
1480 1842
1481Those are a lot of steps and a lot of details, but fortunately Yocto 1843Those are a lot of steps and a lot of details, but fortunately Yocto
1482includes a script called 'crosstap' that will take care of those 1844includes a script called 'crosstap' that will take care of those
@@ -1486,7 +1848,40 @@ target, with arguments if necessary.
1486In order to do this from a remote host, however, you need to have access 1848In order to do this from a remote host, however, you need to have access
1487to the build for the image you booted. The 'crosstap' script provides 1849to the build for the image you booted. The 'crosstap' script provides
1488details on how to do this if you run the script on the host without 1850details on how to do this if you run the script on the host without
1489having done a build: 1851having done a build: ::
1852
1853 $ crosstap root@192.168.1.88 trace_open.stp
1854
1855 Error: No target kernel build found.
1856 Did you forget to create a local build of your image?
1857
1858 'crosstap' requires a local sdk build of the target system
1859 (or a build that includes 'tools-profile') in order to build
1860 kernel modules that can probe the target system.
1861
1862 Practically speaking, that means you need to do the following:
1863 - If you're running a pre-built image, download the release
1864 and/or BSP tarballs used to build the image.
1865 - If you're working from git sources, just clone the metadata
1866 and BSP layers needed to build the image you'll be booting.
1867 - Make sure you're properly set up to build a new image (see
1868 the BSP README and/or the widely available basic documentation
1869 that discusses how to build images).
1870 - Build an -sdk version of the image e.g.:
1871 $ bitbake core-image-sato-sdk
1872 OR
1873 - Build a non-sdk image but include the profiling tools:
1874 [ edit local.conf and add 'tools-profile' to the end of
1875 the EXTRA_IMAGE_FEATURES variable ]
1876 $ bitbake core-image-sato
1877
1878 Once you've build the image on the host system, you're ready to
1879 boot it (or the equivalent pre-built image) and use 'crosstap'
1880 to probe it (you need to source the environment as usual first):
1881
1882 $ source oe-init-build-env
1883 $ cd ~/my/systemtap/scripts
1884 $ crosstap root@192.168.1.xxx myscript.stp
1490 1885
1491.. note:: 1886.. note::
1492 1887
@@ -1496,27 +1891,9 @@ having done a build:
1496 . Also, the ability to ssh into the target system is not enabled by 1891 . Also, the ability to ssh into the target system is not enabled by
1497 default in \*-minimal images. 1892 default in \*-minimal images.
1498 1893
1499$ crosstap root@192.168.1.88 trace_open.stp Error: No target kernel 1894So essentially what you need to
1500build found. Did you forget to create a local build of your image?
1501'crosstap' requires a local sdk build of the target system (or a build
1502that includes 'tools-profile') in order to build kernel modules that can
1503probe the target system. Practically speaking, that means you need to do
1504the following: - If you're running a pre-built image, download the
1505release and/or BSP tarballs used to build the image. - If you're working
1506from git sources, just clone the metadata and BSP layers needed to build
1507the image you'll be booting. - Make sure you're properly set up to build
1508a new image (see the BSP README and/or the widely available basic
1509documentation that discusses how to build images). - Build an -sdk
1510version of the image e.g.: $ bitbake core-image-sato-sdk OR - Build a
1511non-sdk image but include the profiling tools: [ edit local.conf and add
1512'tools-profile' to the end of the EXTRA_IMAGE_FEATURES variable ] $
1513bitbake core-image-sato Once you've build the image on the host system,
1514you're ready to boot it (or the equivalent pre-built image) and use
1515'crosstap' to probe it (you need to source the environment as usual
1516first): $ source oe-init-build-env $ cd ~/my/systemtap/scripts $
1517crosstap root@192.168.1.xxx myscript.stp So essentially what you need to
1518do is build an SDK image or image with 'tools-profile' as detailed in 1895do is build an SDK image or image with 'tools-profile' as detailed in
1519the "`General Setup <#profile-manual-general-setup>`__" section of this 1896the ":ref:`profile-manual/profile-manual-intro:General Setup`" section of this
1520manual, and boot the resulting target image. 1897manual, and boot the resulting target image.
1521 1898
1522.. note:: 1899.. note::
@@ -1531,32 +1908,57 @@ Running a Script on a Target
1531---------------------------- 1908----------------------------
1532 1909
1533Once you've done that, you should be able to run a systemtap script on 1910Once you've done that, you should be able to run a systemtap script on
1534the target: $ cd /path/to/yocto $ source oe-init-build-env ### Shell 1911the target: ::
1535environment set up for builds. ### You can now run 'bitbake <target>' 1912
1536Common targets are: core-image-minimal core-image-sato meta-toolchain 1913 $ cd /path/to/yocto
1537meta-ide-support You can also run generated qemu images with a command 1914 $ source oe-init-build-env
1538like 'runqemu qemux86-64' Once you've done that, you can cd to whatever 1915
1539directory contains your scripts and use 'crosstap' to run the script: $ 1916 ### Shell environment set up for builds. ###
1540cd /path/to/my/systemap/script $ crosstap root@192.168.7.2 1917
1541trace_open.stp If you get an error connecting to the target e.g.: $ 1918 You can now run 'bitbake <target>'
1542crosstap root@192.168.7.2 trace_open.stp error establishing ssh 1919
1543connection on remote 'root@192.168.7.2' Try ssh'ing to the target and 1920 Common targets are:
1544see what happens: $ ssh root@192.168.7.2 A lot of the time, connection 1921 core-image-minimal
1922 core-image-sato
1923 meta-toolchain
1924 meta-ide-support
1925
1926 You can also run generated qemu images with a command like 'runqemu qemux86-64'
1927
1928Once you've done that, you can cd to whatever
1929directory contains your scripts and use 'crosstap' to run the script: ::
1930
1931 $ cd /path/to/my/systemap/script
1932 $ crosstap root@192.168.7.2 trace_open.stp
1933
1934If you get an error connecting to the target e.g.: ::
1935
1936 $ crosstap root@192.168.7.2 trace_open.stp
1937 error establishing ssh connection on remote 'root@192.168.7.2'
1938
1939Try ssh'ing to the target and see what happens: ::
1940
1941 $ ssh root@192.168.7.2
1942
1943A lot of the time, connection
1545problems are due specifying a wrong IP address or having a 'host key 1944problems are due specifying a wrong IP address or having a 'host key
1546verification error'. 1945verification error'.
1547 1946
1548If everything worked as planned, you should see something like this 1947If everything worked as planned, you should see something like this
1549(enter the password when prompted, or press enter if it's set up to use 1948(enter the password when prompted, or press enter if it's set up to use
1550no password): $ crosstap root@192.168.7.2 trace_open.stp 1949no password):
1551root@192.168.7.2's password: matchbox-termin(1036) open 1950
1552("/tmp/vte3FS2LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) 1951.. code-block:: none
1553matchbox-termin(1036) open ("/tmp/vteJMC7LW", 1952
1554O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) 1953 $ crosstap root@192.168.7.2 trace_open.stp
1954 root@192.168.7.2's password:
1955 matchbox-termin(1036) open ("/tmp/vte3FS2LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600)
1956 matchbox-termin(1036) open ("/tmp/vteJMC7LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600)
1555 1957
1556.. _systemtap-documentation: 1958.. _systemtap-documentation:
1557 1959
1558Documentation 1960systemtap Documentation
1559------------- 1961-----------------------
1560 1962
1561The SystemTap language reference can be found here: `SystemTap Language 1963The SystemTap language reference can be found here: `SystemTap Language
1562Reference <http://sourceware.org/systemtap/langref/>`__ 1964Reference <http://sourceware.org/systemtap/langref/>`__
@@ -1576,11 +1978,11 @@ start, stop, and view the profile from one place.
1576 1978
1577.. _sysprof-setup: 1979.. _sysprof-setup:
1578 1980
1579Setup 1981Sysprof Setup
1580----- 1982-------------
1581 1983
1582For this section, we'll assume you've already performed the basic setup 1984For this section, we'll assume you've already performed the basic setup
1583outlined in the General Setup section. 1985outlined in the ":ref:`profile-manual/profile-manual-intro:General Setup`" section.
1584 1986
1585Sysprof is a GUI-based application that runs on the target system. For 1987Sysprof is a GUI-based application that runs on the target system. For
1586the rest of this document we assume you've ssh'ed to the host and will 1988the rest of this document we assume you've ssh'ed to the host and will
@@ -1590,8 +1992,8 @@ if you want).
1590 1992
1591.. _sysprof-basic-usage: 1993.. _sysprof-basic-usage:
1592 1994
1593Basic Usage 1995Basic Sysprof Usage
1594----------- 1996-------------------
1595 1997
1596To start profiling the system, you simply press the 'Start' button. To 1998To start profiling the system, you simply press the 'Start' button. To
1597stop profiling and to start viewing the profile data in one easy step, 1999stop profiling and to start viewing the profile data in one easy step,
@@ -1608,9 +2010,9 @@ those expands that function in the right pane, showing all its callees.
1608Note that this caller-oriented display is essentially the inverse of 2010Note that this caller-oriented display is essentially the inverse of
1609perf's default callee-oriented callchain display. 2011perf's default callee-oriented callchain display.
1610 2012
1611In the screenshot above, we're focusing on \__copy_to_user_ll() and 2013In the screenshot above, we're focusing on ``__copy_to_user_ll()`` and
1612looking up the callchain we can see that one of the callers of 2014looking up the callchain we can see that one of the callers of
1613\__copy_to_user_ll is sys_read() and the complete callpath between them. 2015``__copy_to_user_ll`` is sys_read() and the complete callpath between them.
1614Notice that this is essentially a portion of the same information we saw 2016Notice that this is essentially a portion of the same information we saw
1615in the perf display shown in the perf section of this page. 2017in the perf display shown in the perf section of this page.
1616 2018
@@ -1623,7 +2025,7 @@ copy-from-user callchain.
1623Finally, looking at the third Sysprof pane in the lower left, we can see 2025Finally, looking at the third Sysprof pane in the lower left, we can see
1624a list of all the callers of a particular function selected in the top 2026a list of all the callers of a particular function selected in the top
1625left pane. In this case, the lower pane is showing all the callers of 2027left pane. In this case, the lower pane is showing all the callers of
1626\__mark_inode_dirty: 2028``__mark_inode_dirty``:
1627 2029
1628.. image:: figures/sysprof-callers.png 2030.. image:: figures/sysprof-callers.png
1629 :align: center 2031 :align: center
@@ -1631,9 +2033,8 @@ left pane. In this case, the lower pane is showing all the callers of
1631Double-clicking on one of those functions will in turn change the focus 2033Double-clicking on one of those functions will in turn change the focus
1632to the selected function, and so on. 2034to the selected function, and so on.
1633 2035
1634.. container:: informalexample 2036.. admonition:: Tying it Together
1635 2037
1636 **Tying it Together**:
1637 If you like sysprof's 'caller-oriented' display, you may be able to 2038 If you like sysprof's 'caller-oriented' display, you may be able to
1638 approximate it in other tools as well. For example, 'perf report' has 2039 approximate it in other tools as well. For example, 'perf report' has
1639 the -g (--call-graph) option that you can experiment with; one of the 2040 the -g (--call-graph) option that you can experiment with; one of the
@@ -1641,8 +2042,8 @@ to the selected function, and so on.
1641 2042
1642.. _sysprof-documentation: 2043.. _sysprof-documentation:
1643 2044
1644Documentation 2045Sysprof Documentation
1645------------- 2046---------------------
1646 2047
1647There doesn't seem to be any documentation for Sysprof, but maybe that's 2048There doesn't seem to be any documentation for Sysprof, but maybe that's
1648because it's pretty self-explanatory. The Sysprof website, however, is 2049because it's pretty self-explanatory. The Sysprof website, however, is
@@ -1654,108 +2055,115 @@ LTTng (Linux Trace Toolkit, next generation)
1654 2055
1655.. _lttng-setup: 2056.. _lttng-setup:
1656 2057
1657Setup 2058LTTng Setup
1658----- 2059-----------
1659 2060
1660For this section, we'll assume you've already performed the basic setup 2061For this section, we'll assume you've already performed the basic setup
1661outlined in the General Setup section. LTTng is run on the target system 2062outlined in the ":ref:`profile-manual/profile-manual-intro:General Setup`" section.
1662by ssh'ing to it. 2063LTTng is run on the target system by ssh'ing to it.
1663 2064
1664Collecting and Viewing Traces 2065Collecting and Viewing Traces
1665----------------------------- 2066-----------------------------
1666 2067
1667Once you've applied the above commits and built and booted your image 2068Once you've applied the above commits and built and booted your image
1668(you need to build the core-image-sato-sdk image or use one of the other 2069(you need to build the core-image-sato-sdk image or use one of the other
1669methods described in the General Setup section), you're ready to start 2070methods described in the ":ref:`profile-manual/profile-manual-intro:General Setup`" section), you're ready to start
1670tracing. 2071tracing.
1671 2072
1672Collecting and viewing a trace on the target (inside a shell) 2073Collecting and viewing a trace on the target (inside a shell)
1673~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 2074~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
1674 2075
1675First, from the host, ssh to the target: $ ssh -l root 192.168.1.47 The 2076First, from the host, ssh to the target: ::
1676authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. 2077
1677RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e. 2078 $ ssh -l root 192.168.1.47
1678Are you sure you want to continue connecting (yes/no)? yes Warning: 2079 The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established.
1679Permanently added '192.168.1.47' (RSA) to the list of known hosts. 2080 RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e.
1680root@192.168.1.47's password: Once on the target, use these steps to 2081 Are you sure you want to continue connecting (yes/no)? yes
1681create a trace: root@crownbay:~# lttng create Spawning a session daemon 2082 Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts.
1682Session auto-20121015-232120 created. Traces will be written in 2083 root@192.168.1.47's password:
1683/home/root/lttng-traces/auto-20121015-232120 Enable the events you want 2084
1684to trace (in this case all kernel events): root@crownbay:~# lttng 2085Once on the target, use these steps to create a trace: ::
1685enable-event --kernel --all All kernel events are enabled in channel 2086
1686channel0 Start the trace: root@crownbay:~# lttng start Tracing started 2087 root@crownbay:~# lttng create
1687for session auto-20121015-232120 And then stop the trace after awhile or 2088 Spawning a session daemon
1688after running a particular workload that you want to trace: 2089 Session auto-20121015-232120 created.
1689root@crownbay:~# lttng stop Tracing stopped for session 2090 Traces will be written in /home/root/lttng-traces/auto-20121015-232120
1690auto-20121015-232120 You can now view the trace in text form on the 2091
1691target: root@crownbay:~# lttng view [23:21:56.989270399] (+?.?????????) 2092Enable the events you want to trace (in this case all kernel events): ::
1692sys_geteuid: { 1 }, { } [23:21:56.989278081] (+0.000007682) 2093
1693exit_syscall: { 1 }, { ret = 0 } [23:21:56.989286043] (+0.000007962) 2094 root@crownbay:~# lttng enable-event --kernel --all
1694sys_pipe: { 1 }, { fildes = 0xB77B9E8C } [23:21:56.989321802] 2095 All kernel events are enabled in channel channel0
1695(+0.000035759) exit_syscall: { 1 }, { ret = 0 } [23:21:56.989329345] 2096
1696(+0.000007543) sys_mmap_pgoff: { 1 }, { addr = 0x0, len = 10485760, prot 2097Start the trace: ::
1697= 3, flags = 131362, fd = 4294967295, pgoff = 0 } [23:21:56.989351694] 2098
1698(+0.000022349) exit_syscall: { 1 }, { ret = -1247805440 } 2099 root@crownbay:~# lttng start
1699[23:21:56.989432989] (+0.000081295) sys_clone: { 1 }, { clone_flags = 2100 Tracing started for session auto-20121015-232120
17000x411, newsp = 0xB5EFFFE4, parent_tid = 0xFFFFFFFF, child_tid = 0x0 } 2101
1701[23:21:56.989477129] (+0.000044140) sched_stat_runtime: { 1 }, { comm = 2102And then stop the trace after awhile or after running a particular workload that
1702"lttng-consumerd", tid = 1193, runtime = 681660, vruntime = 43367983388 2103you want to trace: ::
1703} [23:21:56.989486697] (+0.000009568) sched_migrate_task: { 1 }, { comm 2104
1704= "lttng-consumerd", tid = 1193, prio = 20, orig_cpu = 1, dest_cpu = 1 } 2105 root@crownbay:~# lttng stop
1705[23:21:56.989508418] (+0.000021721) hrtimer_init: { 1 }, { hrtimer = 2106 Tracing stopped for session auto-20121015-232120
17063970832076, clockid = 1, mode = 1 } [23:21:56.989770462] (+0.000262044) 2107
1707hrtimer_cancel: { 1 }, { hrtimer = 3993865440 } [23:21:56.989771580] 2108You can now view the trace in text form on the target: ::
1708(+0.000001118) hrtimer_cancel: { 0 }, { hrtimer = 3993812192 } 2109
1709[23:21:56.989776957] (+0.000005377) hrtimer_expire_entry: { 1 }, { 2110 root@crownbay:~# lttng view
1710hrtimer = 3993865440, now = 79815980007057, function = 3238465232 } 2111 [23:21:56.989270399] (+?.?????????) sys_geteuid: { 1 }, { }
1711[23:21:56.989778145] (+0.000001188) hrtimer_expire_entry: { 0 }, { 2112 [23:21:56.989278081] (+0.000007682) exit_syscall: { 1 }, { ret = 0 }
1712hrtimer = 3993812192, now = 79815980008174, function = 3238465232 } 2113 [23:21:56.989286043] (+0.000007962) sys_pipe: { 1 }, { fildes = 0xB77B9E8C }
1713[23:21:56.989791695] (+0.000013550) softirq_raise: { 1 }, { vec = 1 } 2114 [23:21:56.989321802] (+0.000035759) exit_syscall: { 1 }, { ret = 0 }
1714[23:21:56.989795396] (+0.000003701) softirq_raise: { 0 }, { vec = 1 } 2115 [23:21:56.989329345] (+0.000007543) sys_mmap_pgoff: { 1 }, { addr = 0x0, len = 10485760, prot = 3, flags = 131362, fd = 4294967295, pgoff = 0 }
1715[23:21:56.989800635] (+0.000005239) softirq_raise: { 0 }, { vec = 9 } 2116 [23:21:56.989351694] (+0.000022349) exit_syscall: { 1 }, { ret = -1247805440 }
1716[23:21:56.989807130] (+0.000006495) sched_stat_runtime: { 1 }, { comm = 2117 [23:21:56.989432989] (+0.000081295) sys_clone: { 1 }, { clone_flags = 0x411, newsp = 0xB5EFFFE4, parent_tid = 0xFFFFFFFF, child_tid = 0x0 }
1717"lttng-consumerd", tid = 1193, runtime = 330710, vruntime = 43368314098 2118 [23:21:56.989477129] (+0.000044140) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 681660, vruntime = 43367983388 }
1718} [23:21:56.989809993] (+0.000002863) sched_stat_runtime: { 0 }, { comm 2119 [23:21:56.989486697] (+0.000009568) sched_migrate_task: { 1 }, { comm = "lttng-consumerd", tid = 1193, prio = 20, orig_cpu = 1, dest_cpu = 1 }
1719= "lttng-sessiond", tid = 1181, runtime = 1015313, vruntime = 2120 [23:21:56.989508418] (+0.000021721) hrtimer_init: { 1 }, { hrtimer = 3970832076, clockid = 1, mode = 1 }
172036976733240 } [23:21:56.989818514] (+0.000008521) hrtimer_expire_exit: { 2121 [23:21:56.989770462] (+0.000262044) hrtimer_cancel: { 1 }, { hrtimer = 3993865440 }
17210 }, { hrtimer = 3993812192 } [23:21:56.989819631] (+0.000001117) 2122 [23:21:56.989771580] (+0.000001118) hrtimer_cancel: { 0 }, { hrtimer = 3993812192 }
1722hrtimer_expire_exit: { 1 }, { hrtimer = 3993865440 } 2123 [23:21:56.989776957] (+0.000005377) hrtimer_expire_entry: { 1 }, { hrtimer = 3993865440, now = 79815980007057, function = 3238465232 }
1723[23:21:56.989821866] (+0.000002235) hrtimer_start: { 0 }, { hrtimer = 2124 [23:21:56.989778145] (+0.000001188) hrtimer_expire_entry: { 0 }, { hrtimer = 3993812192, now = 79815980008174, function = 3238465232 }
17243993812192, function = 3238465232, expires = 79815981000000, softexpires 2125 [23:21:56.989791695] (+0.000013550) softirq_raise: { 1 }, { vec = 1 }
1725= 79815981000000 } [23:21:56.989822984] (+0.000001118) hrtimer_start: { 2126 [23:21:56.989795396] (+0.000003701) softirq_raise: { 0 }, { vec = 1 }
17261 }, { hrtimer = 3993865440, function = 3238465232, expires = 2127 [23:21:56.989800635] (+0.000005239) softirq_raise: { 0 }, { vec = 9 }
172779815981000000, softexpires = 79815981000000 } [23:21:56.989832762] 2128 [23:21:56.989807130] (+0.000006495) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 330710, vruntime = 43368314098 }
1728(+0.000009778) softirq_entry: { 1 }, { vec = 1 } [23:21:56.989833879] 2129 [23:21:56.989809993] (+0.000002863) sched_stat_runtime: { 0 }, { comm = "lttng-sessiond", tid = 1181, runtime = 1015313, vruntime = 36976733240 }
1729(+0.000001117) softirq_entry: { 0 }, { vec = 1 } [23:21:56.989838069] 2130 [23:21:56.989818514] (+0.000008521) hrtimer_expire_exit: { 0 }, { hrtimer = 3993812192 }
1730(+0.000004190) timer_cancel: { 1 }, { timer = 3993871956 } 2131 [23:21:56.989819631] (+0.000001117) hrtimer_expire_exit: { 1 }, { hrtimer = 3993865440 }
1731[23:21:56.989839187] (+0.000001118) timer_cancel: { 0 }, { timer = 2132 [23:21:56.989821866] (+0.000002235) hrtimer_start: { 0 }, { hrtimer = 3993812192, function = 3238465232, expires = 79815981000000, softexpires = 79815981000000 }
17323993818708 } [23:21:56.989841492] (+0.000002305) timer_expire_entry: { 1 2133 [23:21:56.989822984] (+0.000001118) hrtimer_start: { 1 }, { hrtimer = 3993865440, function = 3238465232, expires = 79815981000000, softexpires = 79815981000000 }
1733}, { timer = 3993871956, now = 79515980, function = 3238277552 } 2134 [23:21:56.989832762] (+0.000009778) softirq_entry: { 1 }, { vec = 1 }
1734[23:21:56.989842819] (+0.000001327) timer_expire_entry: { 0 }, { timer = 2135 [23:21:56.989833879] (+0.000001117) softirq_entry: { 0 }, { vec = 1 }
17353993818708, now = 79515980, function = 3238277552 } [23:21:56.989854831] 2136 [23:21:56.989838069] (+0.000004190) timer_cancel: { 1 }, { timer = 3993871956 }
1736(+0.000012012) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", 2137 [23:21:56.989839187] (+0.000001118) timer_cancel: { 0 }, { timer = 3993818708 }
1737tid = 1193, runtime = 49237, vruntime = 43368363335 } 2138 [23:21:56.989841492] (+0.000002305) timer_expire_entry: { 1 }, { timer = 3993871956, now = 79515980, function = 3238277552 }
1738[23:21:56.989855949] (+0.000001118) sched_stat_runtime: { 0 }, { comm = 2139 [23:21:56.989842819] (+0.000001327) timer_expire_entry: { 0 }, { timer = 3993818708, now = 79515980, function = 3238277552 }
1739"lttng-sessiond", tid = 1181, runtime = 45121, vruntime = 36976778361 } 2140 [23:21:56.989854831] (+0.000012012) sched_stat_runtime: { 1 }, { comm = "lttng-consumerd", tid = 1193, runtime = 49237, vruntime = 43368363335 }
1740[23:21:56.989861257] (+0.000005308) sched_stat_sleep: { 1 }, { comm = 2141 [23:21:56.989855949] (+0.000001118) sched_stat_runtime: { 0 }, { comm = "lttng-sessiond", tid = 1181, runtime = 45121, vruntime = 36976778361 }
1741"kworker/1:1", tid = 21, delay = 9451318 } [23:21:56.989862374] 2142 [23:21:56.989861257] (+0.000005308) sched_stat_sleep: { 1 }, { comm = "kworker/1:1", tid = 21, delay = 9451318 }
1742(+0.000001117) sched_stat_sleep: { 0 }, { comm = "kworker/0:0", tid = 4, 2143 [23:21:56.989862374] (+0.000001117) sched_stat_sleep: { 0 }, { comm = "kworker/0:0", tid = 4, delay = 9958820 }
1743delay = 9958820 } [23:21:56.989868241] (+0.000005867) sched_wakeup: { 0 2144 [23:21:56.989868241] (+0.000005867) sched_wakeup: { 0 }, { comm = "kworker/0:0", tid = 4, prio = 120, success = 1, target_cpu = 0 }
1744}, { comm = "kworker/0:0", tid = 4, prio = 120, success = 1, target_cpu 2145 [23:21:56.989869358] (+0.000001117) sched_wakeup: { 1 }, { comm = "kworker/1:1", tid = 21, prio = 120, success = 1, target_cpu = 1 }
1745= 0 } [23:21:56.989869358] (+0.000001117) sched_wakeup: { 1 }, { comm = 2146 [23:21:56.989877460] (+0.000008102) timer_expire_exit: { 1 }, { timer = 3993871956 }
1746"kworker/1:1", tid = 21, prio = 120, success = 1, target_cpu = 1 } 2147 [23:21:56.989878577] (+0.000001117) timer_expire_exit: { 0 }, { timer = 3993818708 }
1747[23:21:56.989877460] (+0.000008102) timer_expire_exit: { 1 }, { timer = 2148 .
17483993871956 } [23:21:56.989878577] (+0.000001117) timer_expire_exit: { 0 2149 .
1749}, { timer = 3993818708 } . . . You can now safely destroy the trace 2150 .
2151
2152You can now safely destroy the trace
1750session (note that this doesn't delete the trace - it's still there in 2153session (note that this doesn't delete the trace - it's still there in
1751~/lttng-traces): root@crownbay:~# lttng destroy Session 2154~/lttng-traces): ::
1752auto-20121015-232120 destroyed at /home/root Note that the trace is 2155
1753saved in a directory of the same name as returned by 'lttng create', 2156 root@crownbay:~# lttng destroy
1754under the ~/lttng-traces directory (note that you can change this by 2157 Session auto-20121015-232120 destroyed at /home/root
1755supplying your own name to 'lttng create'): root@crownbay:~# ls -al 2158
1756~/lttng-traces drwxrwx--- 3 root root 1024 Oct 15 23:21 . drwxr-xr-x 5 2159Note that the trace is saved in a directory of the same name as returned by
1757root root 1024 Oct 15 23:57 .. drwxrwx--- 3 root root 1024 Oct 15 23:21 2160'lttng create', under the ~/lttng-traces directory (note that you can change this by
1758auto-20121015-232120 2161supplying your own name to 'lttng create'): ::
2162
2163 root@crownbay:~# ls -al ~/lttng-traces
2164 drwxrwx--- 3 root root 1024 Oct 15 23:21 .
2165 drwxr-xr-x 5 root root 1024 Oct 15 23:57 ..
2166 drwxrwx--- 3 root root 1024 Oct 15 23:21 auto-20121015-232120
1759 2167
1760Collecting and viewing a userspace trace on the target (inside a shell) 2168Collecting and viewing a userspace trace on the target (inside a shell)
1761~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 2169~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@@ -1766,64 +2174,75 @@ generated by the lttng-ust build.
1766 2174
1767The 'hello' test program isn't installed on the rootfs by the lttng-ust 2175The 'hello' test program isn't installed on the rootfs by the lttng-ust
1768build, so we need to copy it over manually. First cd into the build 2176build, so we need to copy it over manually. First cd into the build
1769directory that contains the hello executable: $ cd 2177directory that contains the hello executable: ::
1770build/tmp/work/core2_32-poky-linux/lttng-ust/2.0.5-r0/git/tests/hello/.libs 2178
1771Copy that over to the target machine: $ scp hello root@192.168.1.20: You 2179 $ cd build/tmp/work/core2_32-poky-linux/lttng-ust/2.0.5-r0/git/tests/hello/.libs
1772now have the instrumented lttng 'hello world' test program on the 2180
2181Copy that over to the target machine: ::
2182
2183 $ scp hello root@192.168.1.20:
2184
2185You now have the instrumented lttng 'hello world' test program on the
1773target, ready to test. 2186target, ready to test.
1774 2187
1775First, from the host, ssh to the target: $ ssh -l root 192.168.1.47 The 2188First, from the host, ssh to the target: ::
1776authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. 2189
1777RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e. 2190 $ ssh -l root 192.168.1.47
1778Are you sure you want to continue connecting (yes/no)? yes Warning: 2191 The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established.
1779Permanently added '192.168.1.47' (RSA) to the list of known hosts. 2192 RSA key fingerprint is 23:bd:c8:b1:a8:71:52:00:ee:00:4f:64:9e:10:b9:7e.
1780root@192.168.1.47's password: Once on the target, use these steps to 2193 Are you sure you want to continue connecting (yes/no)? yes
1781create a trace: root@crownbay:~# lttng create Session 2194 Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts.
1782auto-20190303-021943 created. Traces will be written in 2195 root@192.168.1.47's password:
1783/home/root/lttng-traces/auto-20190303-021943 Enable the events you want 2196
1784to trace (in this case all userspace events): root@crownbay:~# lttng 2197Once on the target, use these steps to create a trace: ::
1785enable-event --userspace --all All UST events are enabled in channel 2198
1786channel0 Start the trace: root@crownbay:~# lttng start Tracing started 2199 root@crownbay:~# lttng create
1787for session auto-20190303-021943 Run the instrumented hello world 2200 Session auto-20190303-021943 created.
1788program: root@crownbay:~# ./hello Hello, World! Tracing... done. And 2201 Traces will be written in /home/root/lttng-traces/auto-20190303-021943
1789then stop the trace after awhile or after running a particular workload 2202
1790that you want to trace: root@crownbay:~# lttng stop Tracing stopped for 2203Enable the events you want to trace (in this case all userspace events): ::
1791session auto-20190303-021943 You can now view the trace in text form on 2204
1792the target: root@crownbay:~# lttng view [02:31:14.906146544] 2205 root@crownbay:~# lttng enable-event --userspace --all
1793(+?.?????????) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { 2206 All UST events are enabled in channel channel0
1794intfield = 0, intfield2 = 0x0, longfield = 0, netintfield = 0, 2207
1795netintfieldhex = 0x0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], 2208Start the trace: ::
1796arrfield2 = "test", \_seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] 2209
1797= 101, [2] = 115, [3] = 116 ], \_seqfield2_length = 4, seqfield2 = 2210 root@crownbay:~# lttng start
1798"test", stringfield = "test", floatfield = 2222, doublefield = 2, 2211 Tracing started for session auto-20190303-021943
1799boolfield = 1 } [02:31:14.906170360] (+0.000023816) hello:1424 2212
1800ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 1, intfield2 = 0x1, 2213Run the instrumented hello world program: ::
1801longfield = 1, netintfield = 1, netintfieldhex = 0x1, arrfield1 = [ [0] 2214
1802= 1, [1] = 2, [2] = 3 ], arrfield2 = "test", \_seqfield1_length = 4, 2215 root@crownbay:~# ./hello
1803seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], 2216 Hello, World!
1804\_seqfield2_length = 4, seqfield2 = "test", stringfield = "test", 2217 Tracing... done.
1805floatfield = 2222, doublefield = 2, boolfield = 1 } [02:31:14.906183140] 2218
1806(+0.000012780) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { 2219And then stop the trace after awhile or after running a particular workload
1807intfield = 2, intfield2 = 0x2, longfield = 2, netintfield = 2, 2220that you want to trace: ::
1808netintfieldhex = 0x2, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], 2221
1809arrfield2 = "test", \_seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] 2222 root@crownbay:~# lttng stop
1810= 101, [2] = 115, [3] = 116 ], \_seqfield2_length = 4, seqfield2 = 2223 Tracing stopped for session auto-20190303-021943
1811"test", stringfield = "test", floatfield = 2222, doublefield = 2, 2224
1812boolfield = 1 } [02:31:14.906194385] (+0.000011245) hello:1424 2225You can now view the trace in text form on the target: ::
1813ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3, intfield2 = 0x3, 2226
1814longfield = 3, netintfield = 3, netintfieldhex = 0x3, arrfield1 = [ [0] 2227 root@crownbay:~# lttng view
1815= 1, [1] = 2, [2] = 3 ], arrfield2 = "test", \_seqfield1_length = 4, 2228 [02:31:14.906146544] (+?.?????????) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 0, intfield2 = 0x0, longfield = 0, netintfield = 0, netintfieldhex = 0x0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
1816seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], 2229 [02:31:14.906170360] (+0.000023816) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 1, intfield2 = 0x1, longfield = 1, netintfield = 1, netintfieldhex = 0x1, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
1817\_seqfield2_length = 4, seqfield2 = "test", stringfield = "test", 2230 [02:31:14.906183140] (+0.000012780) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 2, intfield2 = 0x2, longfield = 2, netintfield = 2, netintfieldhex = 0x2, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
1818floatfield = 2222, doublefield = 2, boolfield = 1 } . . . You can now 2231 [02:31:14.906194385] (+0.000011245) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3, intfield2 = 0x3, longfield = 3, netintfield = 3, netintfieldhex = 0x3, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
1819safely destroy the trace session (note that this doesn't delete the 2232 .
1820trace - it's still there in ~/lttng-traces): root@crownbay:~# lttng 2233 .
1821destroy Session auto-20190303-021943 destroyed at /home/root 2234 .
2235
2236You can now safely destroy the trace session (note that this doesn't delete the
2237trace - it's still there in ~/lttng-traces): ::
2238
2239 root@crownbay:~# lttng destroy
2240 Session auto-20190303-021943 destroyed at /home/root
1822 2241
1823.. _lltng-documentation: 2242.. _lltng-documentation:
1824 2243
1825Documentation 2244LTTng Documentation
1826------------- 2245-------------------
1827 2246
1828You can find the primary LTTng Documentation on the `LTTng 2247You can find the primary LTTng Documentation on the `LTTng
1829Documentation <https://lttng.org/docs/>`__ site. The documentation on 2248Documentation <https://lttng.org/docs/>`__ site. The documentation on
@@ -1847,101 +2266,146 @@ human-readable form and does some basic analysis:
1847 2266
1848.. _blktrace-setup: 2267.. _blktrace-setup:
1849 2268
1850Setup 2269blktrace Setup
1851----- 2270--------------
1852 2271
1853For this section, we'll assume you've already performed the basic setup 2272For this section, we'll assume you've already performed the basic setup
1854outlined in the "`General Setup <#profile-manual-general-setup>`__" 2273outlined in the ":ref:`profile-manual/profile-manual-intro:General Setup`"
1855section. 2274section.
1856 2275
1857blktrace is an application that runs on the target system. You can run 2276blktrace is an application that runs on the target system. You can run
1858the entire blktrace and blkparse pipeline on the target, or you can run 2277the entire blktrace and blkparse pipeline on the target, or you can run
1859blktrace in 'listen' mode on the target and have blktrace and blkparse 2278blktrace in 'listen' mode on the target and have blktrace and blkparse
1860collect and analyze the data on the host (see the "`Using blktrace 2279collect and analyze the data on the host (see the
1861Remotely <#using-blktrace-remotely>`__" section below). For the rest of 2280":ref:`profile-manual/profile-manual-usage:Using blktrace Remotely`" section
1862this section we assume you've ssh'ed to the host and will be running 2281below). For the rest of this section we assume you've ssh'ed to the host and
1863blkrace on the target. 2282will be running blkrace on the target.
1864 2283
1865.. _blktrace-basic-usage: 2284.. _blktrace-basic-usage:
1866 2285
1867Basic Usage 2286Basic blktrace Usage
1868----------- 2287--------------------
1869 2288
1870To record a trace, simply run the 'blktrace' command, giving it the name 2289To record a trace, simply run the 'blktrace' command, giving it the name
1871of the block device you want to trace activity on: root@crownbay:~# 2290of the block device you want to trace activity on: ::
1872blktrace /dev/sdc In another shell, execute a workload you want to 2291
1873trace. root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget 2292 root@crownbay:~# blktrace /dev/sdc
1874http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; 2293
1875sync Connecting to downloads.yoctoproject.org (140.211.169.59:80) 2294In another shell, execute a workload you want to trace. ::
1876linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 2295
18770:00:00 ETA Press Ctrl-C in the blktrace shell to stop the trace. It 2296 root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync
2297 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
2298 linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA
2299
2300Press Ctrl-C in the blktrace shell to stop the trace. It
1878will display how many events were logged, along with the per-cpu file 2301will display how many events were logged, along with the per-cpu file
1879sizes (blktrace records traces in per-cpu kernel buffers and simply 2302sizes (blktrace records traces in per-cpu kernel buffers and simply
1880dumps them to userspace for blkparse to merge and sort later). ^C=== sdc 2303dumps them to userspace for blkparse to merge and sort later). ::
1881=== CPU 0: 7082 events, 332 KiB data CPU 1: 1578 events, 74 KiB data 2304
1882Total: 8660 events (dropped 0), 406 KiB data If you examine the files 2305 ^C=== sdc ===
1883saved to disk, you see multiple files, one per CPU and with the device 2306 CPU 0: 7082 events, 332 KiB data
1884name as the first part of the filename: root@crownbay:~# ls -al 2307 CPU 1: 1578 events, 74 KiB data
1885drwxr-xr-x 6 root root 1024 Oct 27 22:39 . drwxr-sr-x 4 root root 1024 2308 Total: 8660 events (dropped 0), 406 KiB data
1886Oct 26 18:24 .. -rw-r--r-- 1 root root 339938 Oct 27 22:40 2309
1887sdc.blktrace.0 -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1 2310If you examine the files saved to disk, you see multiple files, one per CPU and
2311with the device name as the first part of the filename: ::
2312
2313 root@crownbay:~# ls -al
2314 drwxr-xr-x 6 root root 1024 Oct 27 22:39 .
2315 drwxr-sr-x 4 root root 1024 Oct 26 18:24 ..
2316 -rw-r--r-- 1 root root 339938 Oct 27 22:40 sdc.blktrace.0
2317 -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1
2318
1888To view the trace events, simply invoke 'blkparse' in the directory 2319To view the trace events, simply invoke 'blkparse' in the directory
1889containing the trace files, giving it the device name that forms the 2320containing the trace files, giving it the device name that forms the
1890first part of the filenames: root@crownbay:~# blkparse sdc 8,32 1 1 2321first part of the filenames: ::
18910.000000000 1225 Q WS 3417048 + 8 [jbd2/sdc-8] 8,32 1 2 0.000025213 1225 2322
1892G WS 3417048 + 8 [jbd2/sdc-8] 8,32 1 3 0.000033384 1225 P N [jbd2/sdc-8] 2323 root@crownbay:~# blkparse sdc
18938,32 1 4 0.000043301 1225 I WS 3417048 + 8 [jbd2/sdc-8] 8,32 1 0 2324
18940.000057270 0 m N cfq1225 insert_request 8,32 1 0 0.000064813 0 m N 2325 8,32 1 1 0.000000000 1225 Q WS 3417048 + 8 [jbd2/sdc-8]
1895cfq1225 add_to_rr 8,32 1 5 0.000076336 1225 U N [jbd2/sdc-8] 1 8,32 1 0 2326 8,32 1 2 0.000025213 1225 G WS 3417048 + 8 [jbd2/sdc-8]
18960.000088559 0 m N cfq workload slice:150 8,32 1 0 0.000097359 0 m N 2327 8,32 1 3 0.000033384 1225 P N [jbd2/sdc-8]
1897cfq1225 set_active wl_prio:0 wl_type:1 8,32 1 0 0.000104063 0 m N 2328 8,32 1 4 0.000043301 1225 I WS 3417048 + 8 [jbd2/sdc-8]
1898cfq1225 Not idling. st->count:1 8,32 1 0 0.000112584 0 m N cfq1225 fifo= 2329 8,32 1 0 0.000057270 0 m N cfq1225 insert_request
1899(null) 8,32 1 0 0.000118730 0 m N cfq1225 dispatch_insert 8,32 1 0 2330 8,32 1 0 0.000064813 0 m N cfq1225 add_to_rr
19000.000127390 0 m N cfq1225 dispatched a request 8,32 1 0 0.000133536 0 m 2331 8,32 1 5 0.000076336 1225 U N [jbd2/sdc-8] 1
1901N cfq1225 activate rq, drv=1 8,32 1 6 0.000136889 1225 D WS 3417048 + 8 2332 8,32 1 0 0.000088559 0 m N cfq workload slice:150
1902[jbd2/sdc-8] 8,32 1 7 0.000360381 1225 Q WS 3417056 + 8 [jbd2/sdc-8] 2333 8,32 1 0 0.000097359 0 m N cfq1225 set_active wl_prio:0 wl_type:1
19038,32 1 8 0.000377422 1225 G WS 3417056 + 8 [jbd2/sdc-8] 8,32 1 9 2334 8,32 1 0 0.000104063 0 m N cfq1225 Not idling. st->count:1
19040.000388876 1225 P N [jbd2/sdc-8] 8,32 1 10 0.000397886 1225 Q WS 2335 8,32 1 0 0.000112584 0 m N cfq1225 fifo= (null)
19053417064 + 8 [jbd2/sdc-8] 8,32 1 11 0.000404800 1225 M WS 3417064 + 8 2336 8,32 1 0 0.000118730 0 m N cfq1225 dispatch_insert
1906[jbd2/sdc-8] 8,32 1 12 0.000412343 1225 Q WS 3417072 + 8 [jbd2/sdc-8] 2337 8,32 1 0 0.000127390 0 m N cfq1225 dispatched a request
19078,32 1 13 0.000416533 1225 M WS 3417072 + 8 [jbd2/sdc-8] 8,32 1 14 2338 8,32 1 0 0.000133536 0 m N cfq1225 activate rq, drv=1
19080.000422121 1225 Q WS 3417080 + 8 [jbd2/sdc-8] 8,32 1 15 0.000425194 2339 8,32 1 6 0.000136889 1225 D WS 3417048 + 8 [jbd2/sdc-8]
19091225 M WS 3417080 + 8 [jbd2/sdc-8] 8,32 1 16 0.000431968 1225 Q WS 2340 8,32 1 7 0.000360381 1225 Q WS 3417056 + 8 [jbd2/sdc-8]
19103417088 + 8 [jbd2/sdc-8] 8,32 1 17 0.000435251 1225 M WS 3417088 + 8 2341 8,32 1 8 0.000377422 1225 G WS 3417056 + 8 [jbd2/sdc-8]
1911[jbd2/sdc-8] 8,32 1 18 0.000440279 1225 Q WS 3417096 + 8 [jbd2/sdc-8] 2342 8,32 1 9 0.000388876 1225 P N [jbd2/sdc-8]
19128,32 1 19 0.000443911 1225 M WS 3417096 + 8 [jbd2/sdc-8] 8,32 1 20 2343 8,32 1 10 0.000397886 1225 Q WS 3417064 + 8 [jbd2/sdc-8]
19130.000450336 1225 Q WS 3417104 + 8 [jbd2/sdc-8] 8,32 1 21 0.000454038 2344 8,32 1 11 0.000404800 1225 M WS 3417064 + 8 [jbd2/sdc-8]
19141225 M WS 3417104 + 8 [jbd2/sdc-8] 8,32 1 22 0.000462070 1225 Q WS 2345 8,32 1 12 0.000412343 1225 Q WS 3417072 + 8 [jbd2/sdc-8]
19153417112 + 8 [jbd2/sdc-8] 8,32 1 23 0.000465422 1225 M WS 3417112 + 8 2346 8,32 1 13 0.000416533 1225 M WS 3417072 + 8 [jbd2/sdc-8]
1916[jbd2/sdc-8] 8,32 1 24 0.000474222 1225 I WS 3417056 + 64 [jbd2/sdc-8] 2347 8,32 1 14 0.000422121 1225 Q WS 3417080 + 8 [jbd2/sdc-8]
19178,32 1 0 0.000483022 0 m N cfq1225 insert_request 8,32 1 25 0.000489727 2348 8,32 1 15 0.000425194 1225 M WS 3417080 + 8 [jbd2/sdc-8]
19181225 U N [jbd2/sdc-8] 1 8,32 1 0 0.000498457 0 m N cfq1225 Not idling. 2349 8,32 1 16 0.000431968 1225 Q WS 3417088 + 8 [jbd2/sdc-8]
1919st->count:1 8,32 1 0 0.000503765 0 m N cfq1225 dispatch_insert 8,32 1 0 2350 8,32 1 17 0.000435251 1225 M WS 3417088 + 8 [jbd2/sdc-8]
19200.000512914 0 m N cfq1225 dispatched a request 8,32 1 0 0.000518851 0 m 2351 8,32 1 18 0.000440279 1225 Q WS 3417096 + 8 [jbd2/sdc-8]
1921N cfq1225 activate rq, drv=2 . . . 8,32 0 0 58.515006138 0 m N cfq3551 2352 8,32 1 19 0.000443911 1225 M WS 3417096 + 8 [jbd2/sdc-8]
1922complete rqnoidle 1 8,32 0 2024 58.516603269 3 C WS 3156992 + 16 [0] 2353 8,32 1 20 0.000450336 1225 Q WS 3417104 + 8 [jbd2/sdc-8]
19238,32 0 0 58.516626736 0 m N cfq3551 complete rqnoidle 1 8,32 0 0 2354 8,32 1 21 0.000454038 1225 M WS 3417104 + 8 [jbd2/sdc-8]
192458.516634558 0 m N cfq3551 arm_idle: 8 group_idle: 0 8,32 0 0 2355 8,32 1 22 0.000462070 1225 Q WS 3417112 + 8 [jbd2/sdc-8]
192558.516636933 0 m N cfq schedule dispatch 8,32 1 0 58.516971613 0 m N 2356 8,32 1 23 0.000465422 1225 M WS 3417112 + 8 [jbd2/sdc-8]
1926cfq3551 slice expired t=0 8,32 1 0 58.516982089 0 m N cfq3551 sl_used=13 2357 8,32 1 24 0.000474222 1225 I WS 3417056 + 64 [jbd2/sdc-8]
1927disp=6 charge=13 iops=0 sect=80 8,32 1 0 58.516985511 0 m N cfq3551 2358 8,32 1 0 0.000483022 0 m N cfq1225 insert_request
1928del_from_rr 8,32 1 0 58.516990819 0 m N cfq3551 put_queue CPU0 (sdc): 2359 8,32 1 25 0.000489727 1225 U N [jbd2/sdc-8] 1
1929Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB Read Dispatches: 0, 2360 8,32 1 0 0.000498457 0 m N cfq1225 Not idling. st->count:1
19300KiB Write Dispatches: 485, 40,484KiB Reads Requeued: 0 Writes Requeued: 2361 8,32 1 0 0.000503765 0 m N cfq1225 dispatch_insert
19310 Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB Read Merges: 2362 8,32 1 0 0.000512914 0 m N cfq1225 dispatched a request
19320, 0KiB Write Merges: 13, 160KiB Read depth: 0 Write depth: 2 IO 2363 8,32 1 0 0.000518851 0 m N cfq1225 activate rq, drv=2
1933unplugs: 23 Timer unplugs: 0 CPU1 (sdc): Reads Queued: 0, 0KiB Writes 2364 .
1934Queued: 249, 15,800KiB Read Dispatches: 0, 0KiB Write Dispatches: 42, 2365 .
19351,600KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 0, 0KiB 2366 .
1936Writes Completed: 16, 1,084KiB Read Merges: 0, 0KiB Write Merges: 40, 2367 8,32 0 0 58.515006138 0 m N cfq3551 complete rqnoidle 1
1937276KiB Read depth: 0 Write depth: 2 IO unplugs: 30 Timer unplugs: 1 2368 8,32 0 2024 58.516603269 3 C WS 3156992 + 16 [0]
1938Total (sdc): Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB Read 2369 8,32 0 0 58.516626736 0 m N cfq3551 complete rqnoidle 1
1939Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB Reads Requeued: 0 2370 8,32 0 0 58.516634558 0 m N cfq3551 arm_idle: 8 group_idle: 0
1940Writes Requeued: 0 Reads Completed: 0, 0KiB Writes Completed: 527, 2371 8,32 0 0 58.516636933 0 m N cfq schedule dispatch
194142,084KiB Read Merges: 0, 0KiB Write Merges: 53, 436KiB IO unplugs: 53 2372 8,32 1 0 58.516971613 0 m N cfq3551 slice expired t=0
1942Timer unplugs: 1 Throughput (R/W): 0KiB/s / 719KiB/s Events (sdc): 6,592 2373 8,32 1 0 58.516982089 0 m N cfq3551 sl_used=13 disp=6 charge=13 iops=0 sect=80
1943entries Skips: 0 forward (0 - 0.0%) Input file sdc.blktrace.0 added 2374 8,32 1 0 58.516985511 0 m N cfq3551 del_from_rr
1944Input file sdc.blktrace.1 added The report shows each event that was 2375 8,32 1 0 58.516990819 0 m N cfq3551 put_queue
2376
2377 CPU0 (sdc):
2378 Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB
2379 Read Dispatches: 0, 0KiB Write Dispatches: 485, 40,484KiB
2380 Reads Requeued: 0 Writes Requeued: 0
2381 Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB
2382 Read Merges: 0, 0KiB Write Merges: 13, 160KiB
2383 Read depth: 0 Write depth: 2
2384 IO unplugs: 23 Timer unplugs: 0
2385 CPU1 (sdc):
2386 Reads Queued: 0, 0KiB Writes Queued: 249, 15,800KiB
2387 Read Dispatches: 0, 0KiB Write Dispatches: 42, 1,600KiB
2388 Reads Requeued: 0 Writes Requeued: 0
2389 Reads Completed: 0, 0KiB Writes Completed: 16, 1,084KiB
2390 Read Merges: 0, 0KiB Write Merges: 40, 276KiB
2391 Read depth: 0 Write depth: 2
2392 IO unplugs: 30 Timer unplugs: 1
2393
2394 Total (sdc):
2395 Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB
2396 Read Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB
2397 Reads Requeued: 0 Writes Requeued: 0
2398 Reads Completed: 0, 0KiB Writes Completed: 527, 42,084KiB
2399 Read Merges: 0, 0KiB Write Merges: 53, 436KiB
2400 IO unplugs: 53 Timer unplugs: 1
2401
2402 Throughput (R/W): 0KiB/s / 719KiB/s
2403 Events (sdc): 6,592 entries
2404 Skips: 0 forward (0 - 0.0%)
2405 Input file sdc.blktrace.0 added
2406 Input file sdc.blktrace.1 added
2407
2408The report shows each event that was
1945found in the blktrace data, along with a summary of the overall block 2409found in the blktrace data, along with a summary of the overall block
1946I/O traffic during the run. You can look at the 2410I/O traffic during the run. You can look at the
1947`blkparse <http://linux.die.net/man/1/blkparse>`__ manpage to learn the 2411`blkparse <http://linux.die.net/man/1/blkparse>`__ manpage to learn the
@@ -1954,8 +2418,11 @@ Live Mode
1954 2418
1955blktrace and blkparse are designed from the ground up to be able to 2419blktrace and blkparse are designed from the ground up to be able to
1956operate together in a 'pipe mode' where the stdout of blktrace can be 2420operate together in a 'pipe mode' where the stdout of blktrace can be
1957fed directly into the stdin of blkparse: root@crownbay:~# blktrace 2421fed directly into the stdin of blkparse: ::
1958/dev/sdc -o - \| blkparse -i - This enables long-lived tracing sessions 2422
2423 root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i -
2424
2425This enables long-lived tracing sessions
1959to run without writing anything to disk, and allows the user to look for 2426to run without writing anything to disk, and allows the user to look for
1960certain conditions in the trace data in 'real-time' by viewing the trace 2427certain conditions in the trace data in 'real-time' by viewing the trace
1961output as it scrolls by on the screen or by passing it along to yet 2428output as it scrolls by on the screen or by passing it along to yet
@@ -1964,7 +2431,9 @@ identify and capture conditions of interest.
1964 2431
1965There's actually another blktrace command that implements the above 2432There's actually another blktrace command that implements the above
1966pipeline as a single command, so the user doesn't have to bother typing 2433pipeline as a single command, so the user doesn't have to bother typing
1967in the above command sequence: root@crownbay:~# btrace /dev/sdc 2434in the above command sequence: ::
2435
2436 root@crownbay:~# btrace /dev/sdc
1968 2437
1969Using blktrace Remotely 2438Using blktrace Remotely
1970~~~~~~~~~~~~~~~~~~~~~~~ 2439~~~~~~~~~~~~~~~~~~~~~~~
@@ -1977,100 +2446,167 @@ the traced device at all by providing native support for sending all
1977trace data over the network. 2446trace data over the network.
1978 2447
1979To have blktrace operate in this mode, start blktrace on the target 2448To have blktrace operate in this mode, start blktrace on the target
1980system being traced with the -l option, along with the device to trace: 2449system being traced with the -l option, along with the device to trace: ::
1981root@crownbay:~# blktrace -l /dev/sdc server: waiting for connections... 2450
2451 root@crownbay:~# blktrace -l /dev/sdc
2452 server: waiting for connections...
2453
1982On the host system, use the -h option to connect to the target system, 2454On the host system, use the -h option to connect to the target system,
1983also passing it the device to trace: $ blktrace -d /dev/sdc -h 2455also passing it the device to trace: ::
1984192.168.1.43 blktrace: connecting to 192.168.1.43 blktrace: connected! 2456
1985On the target system, you should see this: server: connection from 2457 $ blktrace -d /dev/sdc -h 192.168.1.43
1986192.168.1.43 In another shell, execute a workload you want to trace. 2458 blktrace: connecting to 192.168.1.43
1987root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget 2459 blktrace: connected!
1988http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; 2460
1989sync Connecting to downloads.yoctoproject.org (140.211.169.59:80) 2461On the target system, you should see this: ::
1990linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 2462
19910:00:00 ETA When it's done, do a Ctrl-C on the host system to stop the 2463 server: connection from 192.168.1.43
1992trace: ^C=== sdc === CPU 0: 7691 events, 361 KiB data CPU 1: 4109 2464
1993events, 193 KiB data Total: 11800 events (dropped 0), 554 KiB data On 2465In another shell, execute a workload you want to trace. ::
1994the target system, you should also see a trace summary for the trace 2466
1995just ended: server: end of run for 192.168.1.43:sdc === sdc === CPU 0: 2467 root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync
19967691 events, 361 KiB data CPU 1: 4109 events, 193 KiB data Total: 11800 2468 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
1997events (dropped 0), 554 KiB data The blktrace instance on the host will 2469 linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA
1998save the target output inside a hostname-timestamp directory: $ ls -al 2470
1999drwxr-xr-x 10 root root 1024 Oct 28 02:40 . drwxr-sr-x 4 root root 1024 2471When it's done, do a Ctrl-C on the host system to stop the
2000Oct 26 18:24 .. drwxr-xr-x 2 root root 1024 Oct 28 02:40 2472trace: ::
2001192.168.1.43-2012-10-28-02:40:56 cd into that directory to see the 2473
2002output files: $ ls -l -rw-r--r-- 1 root root 369193 Oct 28 02:44 2474 ^C=== sdc ===
2003sdc.blktrace.0 -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1 2475 CPU 0: 7691 events, 361 KiB data
2004And run blkparse on the host system using the device name: $ blkparse 2476 CPU 1: 4109 events, 193 KiB data
2005sdc 8,32 1 1 0.000000000 1263 Q RM 6016 + 8 [ls] 8,32 1 0 0.000036038 0 2477 Total: 11800 events (dropped 0), 554 KiB data
2006m N cfq1263 alloced 8,32 1 2 0.000039390 1263 G RM 6016 + 8 [ls] 8,32 1 2478
20073 0.000049168 1263 I RM 6016 + 8 [ls] 8,32 1 0 0.000056152 0 m N cfq1263 2479On the target system, you should also see a trace summary for the trace
2008insert_request 8,32 1 0 0.000061600 0 m N cfq1263 add_to_rr 8,32 1 0 2480just ended: ::
20090.000075498 0 m N cfq workload slice:300 . . . 8,32 0 0 177.266385696 0 2481
2010m N cfq1267 arm_idle: 8 group_idle: 0 8,32 0 0 177.266388140 0 m N cfq 2482 server: end of run for 192.168.1.43:sdc
2011schedule dispatch 8,32 1 0 177.266679239 0 m N cfq1267 slice expired t=0 2483 === sdc ===
20128,32 1 0 177.266689297 0 m N cfq1267 sl_used=9 disp=6 charge=9 iops=0 2484 CPU 0: 7691 events, 361 KiB data
2013sect=56 8,32 1 0 177.266692649 0 m N cfq1267 del_from_rr 8,32 1 0 2485 CPU 1: 4109 events, 193 KiB data
2014177.266696560 0 m N cfq1267 put_queue CPU0 (sdc): Reads Queued: 0, 0KiB 2486 Total: 11800 events (dropped 0), 554 KiB data
2015Writes Queued: 270, 21,708KiB Read Dispatches: 59, 2,628KiB Write 2487
2016Dispatches: 495, 39,964KiB Reads Requeued: 0 Writes Requeued: 0 Reads 2488The blktrace instance on the host will
2017Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB Read Merges: 0, 2489save the target output inside a hostname-timestamp directory: ::
20180KiB Write Merges: 9, 344KiB Read depth: 2 Write depth: 2 IO unplugs: 20 2490
2019Timer unplugs: 1 CPU1 (sdc): Reads Queued: 688, 2,752KiB Writes Queued: 2491 $ ls -al
2020381, 20,652KiB Read Dispatches: 31, 124KiB Write Dispatches: 59, 2492 drwxr-xr-x 10 root root 1024 Oct 28 02:40 .
20212,396KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 0, 0KiB 2493 drwxr-sr-x 4 root root 1024 Oct 26 18:24 ..
2022Writes Completed: 11, 764KiB Read Merges: 598, 2,392KiB Write Merges: 2494 drwxr-xr-x 2 root root 1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56
202388, 448KiB Read depth: 2 Write depth: 2 IO unplugs: 52 Timer unplugs: 0 2495
2024Total (sdc): Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB 2496cd into that directory to see the output files: ::
2025Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB Reads 2497
2026Requeued: 0 Writes Requeued: 0 Reads Completed: 90, 2,752KiB Writes 2498 $ ls -l
2027Completed: 554, 42,360KiB Read Merges: 598, 2,392KiB Write Merges: 97, 2499 -rw-r--r-- 1 root root 369193 Oct 28 02:44 sdc.blktrace.0
2028792KiB IO unplugs: 72 Timer unplugs: 1 Throughput (R/W): 15KiB/s / 2500 -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1
2029238KiB/s Events (sdc): 9,301 entries Skips: 0 forward (0 - 0.0%) You 2501
2030should see the trace events and summary just as you would have if you'd 2502And run blkparse on the host system using the device name: ::
2031run the same command on the target. 2503
2504 $ blkparse sdc
2505
2506 8,32 1 1 0.000000000 1263 Q RM 6016 + 8 [ls]
2507 8,32 1 0 0.000036038 0 m N cfq1263 alloced
2508 8,32 1 2 0.000039390 1263 G RM 6016 + 8 [ls]
2509 8,32 1 3 0.000049168 1263 I RM 6016 + 8 [ls]
2510 8,32 1 0 0.000056152 0 m N cfq1263 insert_request
2511 8,32 1 0 0.000061600 0 m N cfq1263 add_to_rr
2512 8,32 1 0 0.000075498 0 m N cfq workload slice:300
2513 .
2514 .
2515 .
2516 8,32 0 0 177.266385696 0 m N cfq1267 arm_idle: 8 group_idle: 0
2517 8,32 0 0 177.266388140 0 m N cfq schedule dispatch
2518 8,32 1 0 177.266679239 0 m N cfq1267 slice expired t=0
2519 8,32 1 0 177.266689297 0 m N cfq1267 sl_used=9 disp=6 charge=9 iops=0 sect=56
2520 8,32 1 0 177.266692649 0 m N cfq1267 del_from_rr
2521 8,32 1 0 177.266696560 0 m N cfq1267 put_queue
2522
2523 CPU0 (sdc):
2524 Reads Queued: 0, 0KiB Writes Queued: 270, 21,708KiB
2525 Read Dispatches: 59, 2,628KiB Write Dispatches: 495, 39,964KiB
2526 Reads Requeued: 0 Writes Requeued: 0
2527 Reads Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB
2528 Read Merges: 0, 0KiB Write Merges: 9, 344KiB
2529 Read depth: 2 Write depth: 2
2530 IO unplugs: 20 Timer unplugs: 1
2531 CPU1 (sdc):
2532 Reads Queued: 688, 2,752KiB Writes Queued: 381, 20,652KiB
2533 Read Dispatches: 31, 124KiB Write Dispatches: 59, 2,396KiB
2534 Reads Requeued: 0 Writes Requeued: 0
2535 Reads Completed: 0, 0KiB Writes Completed: 11, 764KiB
2536 Read Merges: 598, 2,392KiB Write Merges: 88, 448KiB
2537 Read depth: 2 Write depth: 2
2538 IO unplugs: 52 Timer unplugs: 0
2539
2540 Total (sdc):
2541 Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB
2542 Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB
2543 Reads Requeued: 0 Writes Requeued: 0
2544 Reads Completed: 90, 2,752KiB Writes Completed: 554, 42,360KiB
2545 Read Merges: 598, 2,392KiB Write Merges: 97, 792KiB
2546 IO unplugs: 72 Timer unplugs: 1
2547
2548 Throughput (R/W): 15KiB/s / 238KiB/s
2549 Events (sdc): 9,301 entries
2550 Skips: 0 forward (0 - 0.0%)
2551
2552You should see the trace events and summary just as you would have if you'd run
2553the same command on the target.
2032 2554
2033Tracing Block I/O via 'ftrace' 2555Tracing Block I/O via 'ftrace'
2034~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 2556~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2035 2557
2036It's also possible to trace block I/O using only `trace events 2558It's also possible to trace block I/O using only
2037subsystem <#the-trace-events-subsystem>`__, which can be useful for 2559:ref:`profile-manual/profile-manual-usage:The 'trace events' Subsystem`, which
2038casual tracing if you don't want to bother dealing with the userspace 2560can be useful for casual tracing if you don't want to bother dealing with the
2039tools. 2561userspace tools.
2040 2562
2041To enable tracing for a given device, use /sys/block/xxx/trace/enable, 2563To enable tracing for a given device, use /sys/block/xxx/trace/enable,
2042where xxx is the device name. This for example enables tracing for 2564where xxx is the device name. This for example enables tracing for
2043/dev/sdc: root@crownbay:/sys/kernel/debug/tracing# echo 1 > 2565/dev/sdc: ::
2044/sys/block/sdc/trace/enable Once you've selected the device(s) you want 2566
2045to trace, selecting the 'blk' tracer will turn the blk tracer on: 2567 root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable
2046root@crownbay:/sys/kernel/debug/tracing# cat available_tracers blk 2568
2047function_graph function nop root@crownbay:/sys/kernel/debug/tracing# 2569Once you've selected the device(s) you want
2048echo blk > current_tracer Execute the workload you're interested in: 2570to trace, selecting the 'blk' tracer will turn the blk tracer on: ::
2049root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt And 2571
2050look at the output (note here that we're using 'trace_pipe' instead of 2572 root@crownbay:/sys/kernel/debug/tracing# cat available_tracers
2573 blk function_graph function nop
2574
2575 root@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer
2576
2577Execute the workload you're interested in: ::
2578
2579 root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt
2580
2581And look at the output (note here that we're using 'trace_pipe' instead of
2051trace to capture this trace - this allows us to wait around on the pipe 2582trace to capture this trace - this allows us to wait around on the pipe
2052for data to appear): root@crownbay:/sys/kernel/debug/tracing# cat 2583for data to appear): ::
2053trace_pipe cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat] 2584
2054cat-3587 [001] d..1 3023.276410: 8,32 m N cfq3587 alloced cat-3587 [001] 2585 root@crownbay:/sys/kernel/debug/tracing# cat trace_pipe
2055d..1 3023.276415: 8,32 G R 1699848 + 8 [cat] cat-3587 [001] d..1 2586 cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat]
20563023.276424: 8,32 P N [cat] cat-3587 [001] d..2 3023.276432: 8,32 I R 2587 cat-3587 [001] d..1 3023.276410: 8,32 m N cfq3587 alloced
20571699848 + 8 [cat] cat-3587 [001] d..1 3023.276439: 8,32 m N cfq3587 2588 cat-3587 [001] d..1 3023.276415: 8,32 G R 1699848 + 8 [cat]
2058insert_request cat-3587 [001] d..1 3023.276445: 8,32 m N cfq3587 2589 cat-3587 [001] d..1 3023.276424: 8,32 P N [cat]
2059add_to_rr cat-3587 [001] d..2 3023.276454: 8,32 U N [cat] 1 cat-3587 2590 cat-3587 [001] d..2 3023.276432: 8,32 I R 1699848 + 8 [cat]
2060[001] d..1 3023.276464: 8,32 m N cfq workload slice:150 cat-3587 [001] 2591 cat-3587 [001] d..1 3023.276439: 8,32 m N cfq3587 insert_request
2061d..1 3023.276471: 8,32 m N cfq3587 set_active wl_prio:0 wl_type:2 2592 cat-3587 [001] d..1 3023.276445: 8,32 m N cfq3587 add_to_rr
2062cat-3587 [001] d..1 3023.276478: 8,32 m N cfq3587 fifo= (null) cat-3587 2593 cat-3587 [001] d..2 3023.276454: 8,32 U N [cat] 1
2063[001] d..1 3023.276483: 8,32 m N cfq3587 dispatch_insert cat-3587 [001] 2594 cat-3587 [001] d..1 3023.276464: 8,32 m N cfq workload slice:150
2064d..1 3023.276490: 8,32 m N cfq3587 dispatched a request cat-3587 [001] 2595 cat-3587 [001] d..1 3023.276471: 8,32 m N cfq3587 set_active wl_prio:0 wl_type:2
2065d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1 cat-3587 [001] 2596 cat-3587 [001] d..1 3023.276478: 8,32 m N cfq3587 fifo= (null)
2066d..2 3023.276500: 8,32 D R 1699848 + 8 [cat] And this turns off tracing 2597 cat-3587 [001] d..1 3023.276483: 8,32 m N cfq3587 dispatch_insert
2067for the specified device: root@crownbay:/sys/kernel/debug/tracing# echo 2598 cat-3587 [001] d..1 3023.276490: 8,32 m N cfq3587 dispatched a request
20680 > /sys/block/sdc/trace/enable 2599 cat-3587 [001] d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1
2600 cat-3587 [001] d..2 3023.276500: 8,32 D R 1699848 + 8 [cat]
2601
2602And this turns off tracing for the specified device: ::
2603
2604 root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable
2069 2605
2070.. _blktrace-documentation: 2606.. _blktrace-documentation:
2071 2607
2072Documentation 2608blktrace Documentation
2073------------- 2609----------------------
2074 2610
2075Online versions of the man pages for the commands discussed in this 2611Online versions of the man pages for the commands discussed in this
2076section can be found here: 2612section can be found here:
@@ -2083,4 +2619,6 @@ section can be found here:
2083 2619
2084The above manpages, along with manpages for the other blktrace utilities 2620The above manpages, along with manpages for the other blktrace utilities
2085(btt, blkiomon, etc) can be found in the /doc directory of the blktrace 2621(btt, blkiomon, etc) can be found in the /doc directory of the blktrace
2086tools git repo: $ git clone git://git.kernel.dk/blktrace.git 2622tools git repo: ::
2623
2624 $ git clone git://git.kernel.dk/blktrace.git