diff options
Diffstat (limited to 'documentation/profile-manual/usage.rst')
-rw-r--r-- | documentation/profile-manual/usage.rst | 1058 |
1 files changed, 541 insertions, 517 deletions
diff --git a/documentation/profile-manual/usage.rst b/documentation/profile-manual/usage.rst index b401cf9040..17be149580 100644 --- a/documentation/profile-manual/usage.rst +++ b/documentation/profile-manual/usage.rst | |||
@@ -13,11 +13,11 @@ tools. | |||
13 | perf | 13 | perf |
14 | ==== | 14 | ==== |
15 | 15 | ||
16 | The 'perf' tool is the profiling and tracing tool that comes bundled | 16 | The perf tool is the profiling and tracing tool that comes bundled |
17 | with the Linux kernel. | 17 | with the Linux kernel. |
18 | 18 | ||
19 | Don't let the fact that it's part of the kernel fool you into thinking | 19 | Don't let the fact that it's part of the kernel fool you into thinking |
20 | that it's only for tracing and profiling the kernel - you can indeed use | 20 | that it's only for tracing and profiling the kernel --- you can indeed use |
21 | it to trace and profile just the kernel, but you can also use it to | 21 | it to trace and profile just the kernel, but you can also use it to |
22 | profile specific applications separately (with or without kernel | 22 | profile specific applications separately (with or without kernel |
23 | context), and you can also use it to trace and profile the kernel and | 23 | context), and you can also use it to trace and profile the kernel and |
@@ -26,43 +26,43 @@ of what's going on. | |||
26 | 26 | ||
27 | In many ways, perf aims to be a superset of all the tracing and | 27 | In many ways, perf aims to be a superset of all the tracing and |
28 | profiling tools available in Linux today, including all the other tools | 28 | profiling tools available in Linux today, including all the other tools |
29 | covered in this HOWTO. The past couple of years have seen perf subsume a | 29 | covered in this How-to. The past couple of years have seen perf subsume a |
30 | lot of the functionality of those other tools and, at the same time, | 30 | lot of the functionality of those other tools and, at the same time, |
31 | those other tools have removed large portions of their previous | 31 | those other tools have removed large portions of their previous |
32 | functionality and replaced it with calls to the equivalent functionality | 32 | functionality and replaced it with calls to the equivalent functionality |
33 | now implemented by the perf subsystem. Extrapolation suggests that at | 33 | now implemented by the perf subsystem. Extrapolation suggests that at |
34 | some point those other tools will simply become completely redundant and | 34 | some point those other tools will become completely redundant and |
35 | go away; until then, we'll cover those other tools in these pages and in | 35 | go away; until then, we'll cover those other tools in these pages and in |
36 | many cases show how the same things can be accomplished in perf and the | 36 | many cases show how the same things can be accomplished in perf and the |
37 | other tools when it seems useful to do so. | 37 | other tools when it seems useful to do so. |
38 | 38 | ||
39 | The coverage below details some of the most common ways you'll likely | 39 | The coverage below details some of the most common ways you'll likely |
40 | want to apply the tool; full documentation can be found either within | 40 | want to apply the tool; full documentation can be found either within |
41 | the tool itself or in the man pages at | 41 | the tool itself or in the manual pages at |
42 | `perf(1) <https://linux.die.net/man/1/perf>`__. | 42 | `perf(1) <https://linux.die.net/man/1/perf>`__. |
43 | 43 | ||
44 | Perf Setup | 44 | perf Setup |
45 | ---------- | 45 | ---------- |
46 | 46 | ||
47 | For this section, we'll assume you've already performed the basic setup | 47 | For this section, we'll assume you've already performed the basic setup |
48 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. | 48 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. |
49 | 49 | ||
50 | In particular, you'll get the most mileage out of perf if you profile an | 50 | In particular, you'll get the most mileage out of perf if you profile an |
51 | image built with the following in your ``local.conf`` file: :: | 51 | image built with the following in your ``local.conf`` file:: |
52 | 52 | ||
53 | INHIBIT_PACKAGE_STRIP = "1" | 53 | INHIBIT_PACKAGE_STRIP = "1" |
54 | 54 | ||
55 | perf runs on the target system for the most part. You can archive | 55 | perf runs on the target system for the most part. You can archive |
56 | profile data and copy it to the host for analysis, but for the rest of | 56 | profile data and copy it to the host for analysis, but for the rest of |
57 | this document we assume you've ssh'ed to the host and will be running | 57 | this document we assume you're connected to the host through SSH and will be |
58 | the perf commands on the target. | 58 | running the perf commands on the target. |
59 | 59 | ||
60 | Basic Perf Usage | 60 | Basic perf Usage |
61 | ---------------- | 61 | ---------------- |
62 | 62 | ||
63 | The perf tool is pretty much self-documenting. To remind yourself of the | 63 | The perf tool is pretty much self-documenting. To remind yourself of the |
64 | available commands, simply type 'perf', which will show you basic usage | 64 | available commands, just type ``perf``, which will show you basic usage |
65 | along with the available perf subcommands: :: | 65 | along with the available perf subcommands:: |
66 | 66 | ||
67 | root@crownbay:~# perf | 67 | root@crownbay:~# perf |
68 | 68 | ||
@@ -97,26 +97,26 @@ along with the available perf subcommands: :: | |||
97 | Using perf to do Basic Profiling | 97 | Using perf to do Basic Profiling |
98 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ | 98 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ |
99 | 99 | ||
100 | As a simple test case, we'll profile the 'wget' of a fairly large file, | 100 | As a simple test case, we'll profile the ``wget`` of a fairly large file, |
101 | which is a minimally interesting case because it has both file and | 101 | which is a minimally interesting case because it has both file and |
102 | network I/O aspects, and at least in the case of standard Yocto images, | 102 | network I/O aspects, and at least in the case of standard Yocto images, |
103 | it's implemented as part of busybox, so the methods we use to analyze it | 103 | it's implemented as part of BusyBox, so the methods we use to analyze it |
104 | can be used in a very similar way to the whole host of supported busybox | 104 | can be used in a similar way to the whole host of supported BusyBox |
105 | applets in Yocto. :: | 105 | applets in Yocto:: |
106 | 106 | ||
107 | root@crownbay:~# rm linux-2.6.19.2.tar.bz2; \ | 107 | root@crownbay:~# rm linux-2.6.19.2.tar.bz2; \ |
108 | wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 108 | wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
109 | 109 | ||
110 | The quickest and easiest way to get some basic overall data about what's | 110 | The quickest and easiest way to get some basic overall data about what's |
111 | going on for a particular workload is to profile it using 'perf stat'. | 111 | going on for a particular workload is to profile it using ``perf stat``. |
112 | 'perf stat' basically profiles using a few default counters and displays | 112 | This command basically profiles using a few default counters and displays |
113 | the summed counts at the end of the run: :: | 113 | the summed counts at the end of the run:: |
114 | 114 | ||
115 | root@crownbay:~# perf stat wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 115 | root@crownbay:~# perf stat wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
116 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 116 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
117 | linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA | 117 | linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA |
118 | 118 | ||
119 | Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': | 119 | Performance counter stats for 'wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2': |
120 | 120 | ||
121 | 4597.223902 task-clock # 0.077 CPUs utilized | 121 | 4597.223902 task-clock # 0.077 CPUs utilized |
122 | 23568 context-switches # 0.005 M/sec | 122 | 23568 context-switches # 0.005 M/sec |
@@ -131,21 +131,21 @@ the summed counts at the end of the run: :: | |||
131 | 131 | ||
132 | 59.836627620 seconds time elapsed | 132 | 59.836627620 seconds time elapsed |
133 | 133 | ||
134 | Many times such a simple-minded test doesn't yield much of | 134 | Such a simple-minded test doesn't always yield much of interest, but sometimes |
135 | interest, but sometimes it does (see Real-world Yocto bug (slow | 135 | it does (see the :yocto_bugs:`Slow write speed on live images with denzil |
136 | loop-mounted write speed)). | 136 | </show_bug.cgi?id=3049>` bug report). |
137 | 137 | ||
138 | Also, note that 'perf stat' isn't restricted to a fixed set of counters | 138 | Also, note that ``perf stat`` isn't restricted to a fixed set of counters |
139 | - basically any event listed in the output of 'perf list' can be tallied | 139 | --- basically any event listed in the output of ``perf list`` can be tallied |
140 | by 'perf stat'. For example, suppose we wanted to see a summary of all | 140 | by ``perf stat``. For example, suppose we wanted to see a summary of all |
141 | the events related to kernel memory allocation/freeing along with cache | 141 | the events related to kernel memory allocation/freeing along with cache |
142 | hits and misses: :: | 142 | hits and misses:: |
143 | 143 | ||
144 | 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 | 144 | root@crownbay:~# perf stat -e kmem:* -e cache-references -e cache-misses wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
145 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 145 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
146 | linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA | 146 | linux-2.6.19.2.tar.b 100% |***************************************************| 41727k 0:00:00 ETA |
147 | 147 | ||
148 | Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': | 148 | Performance counter stats for 'wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2': |
149 | 149 | ||
150 | 5566 kmem:kmalloc | 150 | 5566 kmem:kmalloc |
151 | 125517 kmem:kmem_cache_alloc | 151 | 125517 kmem:kmem_cache_alloc |
@@ -164,24 +164,24 @@ hits and misses: :: | |||
164 | 164 | ||
165 | 44.831023415 seconds time elapsed | 165 | 44.831023415 seconds time elapsed |
166 | 166 | ||
167 | So 'perf stat' gives us a nice easy | 167 | As you can see, ``perf stat`` gives us a nice easy |
168 | way to get a quick overview of what might be happening for a set of | 168 | way to get a quick overview of what might be happening for a set of |
169 | events, but normally we'd need a little more detail in order to | 169 | events, but normally we'd need a little more detail in order to |
170 | understand what's going on in a way that we can act on in a useful way. | 170 | understand what's going on in a way that we can act on in a useful way. |
171 | 171 | ||
172 | To dive down into a next level of detail, we can use 'perf record'/'perf | 172 | To dive down into a next level of detail, we can use ``perf record`` / |
173 | report' which will collect profiling data and present it to use using an | 173 | ``perf report`` which will collect profiling data and present it to use using an |
174 | interactive text-based UI (or simply as text if we specify --stdio to | 174 | interactive text-based UI (or just as text if we specify ``--stdio`` to |
175 | 'perf report'). | 175 | ``perf report``). |
176 | 176 | ||
177 | As our first attempt at profiling this workload, we'll simply run 'perf | 177 | As our first attempt at profiling this workload, we'll just run ``perf |
178 | record', handing it the workload we want to profile (everything after | 178 | record``, handing it the workload we want to profile (everything after |
179 | 'perf record' and any perf options we hand it - here none - will be | 179 | ``perf record`` and any perf options we hand it --- here none, will be |
180 | executed in a new shell). perf collects samples until the process exits | 180 | executed in a new shell). perf collects samples until the process exits |
181 | and records them in a file named 'perf.data' in the current working | 181 | and records them in a file named ``perf.data`` in the current working |
182 | directory. :: | 182 | directory:: |
183 | 183 | ||
184 | root@crownbay:~# perf record wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 184 | root@crownbay:~# perf record wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
185 | 185 | ||
186 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 186 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
187 | linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA | 187 | linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA |
@@ -189,37 +189,38 @@ directory. :: | |||
189 | [ perf record: Captured and wrote 0.176 MB perf.data (~7700 samples) ] | 189 | [ perf record: Captured and wrote 0.176 MB perf.data (~7700 samples) ] |
190 | 190 | ||
191 | To see the results in a | 191 | To see the results in a |
192 | 'text-based UI' (tui), simply run 'perf report', which will read the | 192 | "text-based UI" (tui), just run ``perf report``, which will read the |
193 | perf.data file in the current working directory and display the results | 193 | perf.data file in the current working directory and display the results |
194 | in an interactive UI: :: | 194 | in an interactive UI:: |
195 | 195 | ||
196 | root@crownbay:~# perf report | 196 | root@crownbay:~# perf report |
197 | 197 | ||
198 | .. image:: figures/perf-wget-flat-stripped.png | 198 | .. image:: figures/perf-wget-flat-stripped.png |
199 | :align: center | 199 | :align: center |
200 | :width: 70% | ||
200 | 201 | ||
201 | The above screenshot displays a 'flat' profile, one entry for each | 202 | The above screenshot displays a "flat" profile, one entry for each |
202 | 'bucket' corresponding to the functions that were profiled during the | 203 | "bucket" corresponding to the functions that were profiled during the |
203 | profiling run, ordered from the most popular to the least (perf has | 204 | profiling run, ordered from the most popular to the least (perf has |
204 | options to sort in various orders and keys as well as display entries | 205 | options to sort in various orders and keys as well as display entries |
205 | only above a certain threshold and so on - see the perf documentation | 206 | only above a certain threshold and so on --- see the perf documentation |
206 | for details). Note that this includes both userspace functions (entries | 207 | for details). Note that this includes both user space functions (entries |
207 | containing a [.]) and kernel functions accounted to the process (entries | 208 | containing a ``[.]``) and kernel functions accounted to the process (entries |
208 | containing a [k]). (perf has command-line modifiers that can be used to | 209 | containing a ``[k]``). perf has command-line modifiers that can be used to |
209 | restrict the profiling to kernel or userspace, among others). | 210 | restrict the profiling to kernel or user space, among others. |
210 | 211 | ||
211 | Notice also that the above report shows an entry for 'busybox', which is | 212 | Notice also that the above report shows an entry for ``busybox``, which is |
212 | the executable that implements 'wget' in Yocto, but that instead of a | 213 | the executable that implements ``wget`` in Yocto, but that instead of a |
213 | useful function name in that entry, it displays a not-so-friendly hex | 214 | useful function name in that entry, it displays a not-so-friendly hex |
214 | value instead. The steps below will show how to fix that problem. | 215 | value instead. The steps below will show how to fix that problem. |
215 | 216 | ||
216 | Before we do that, however, let's try running a different profile, one | 217 | Before we do that, however, let's try running a different profile, one |
217 | which shows something a little more interesting. The only difference | 218 | which shows something a little more interesting. The only difference |
218 | between the new profile and the previous one is that we'll add the -g | 219 | between the new profile and the previous one is that we'll add the ``-g`` |
219 | option, which will record not just the address of a sampled function, | 220 | option, which will record not just the address of a sampled function, |
220 | but the entire callchain to the sampled function as well: :: | 221 | but the entire call chain to the sampled function as well:: |
221 | 222 | ||
222 | root@crownbay:~# perf record -g wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 223 | root@crownbay:~# perf record -g wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
223 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 224 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
224 | linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA | 225 | linux-2.6.19.2.tar.b 100% |************************************************| 41727k 0:00:00 ETA |
225 | [ perf record: Woken up 3 times to write data ] | 226 | [ perf record: Woken up 3 times to write data ] |
@@ -230,45 +231,47 @@ but the entire callchain to the sampled function as well: :: | |||
230 | 231 | ||
231 | .. image:: figures/perf-wget-g-copy-to-user-expanded-stripped.png | 232 | .. image:: figures/perf-wget-g-copy-to-user-expanded-stripped.png |
232 | :align: center | 233 | :align: center |
234 | :width: 70% | ||
233 | 235 | ||
234 | Using the callgraph view, we can actually see not only which functions | 236 | Using the call graph view, we can actually see not only which functions |
235 | took the most time, but we can also see a summary of how those functions | 237 | took the most time, but we can also see a summary of how those functions |
236 | were called and learn something about how the program interacts with the | 238 | were called and learn something about how the program interacts with the |
237 | kernel in the process. | 239 | kernel in the process. |
238 | 240 | ||
239 | Notice that each entry in the above screenshot now contains a '+' on the | 241 | Notice that each entry in the above screenshot now contains a ``+`` on the |
240 | left-hand side. This means that we can expand the entry and drill down | 242 | left side. This means that we can expand the entry and drill down |
241 | into the callchains that feed into that entry. Pressing 'enter' on any | 243 | into the call chains that feed into that entry. Pressing ``Enter`` on any |
242 | one of them will expand the callchain (you can also press 'E' to expand | 244 | one of them will expand the call chain (you can also press ``E`` to expand |
243 | them all at the same time or 'C' to collapse them all). | 245 | them all at the same time or ``C`` to collapse them all). |
244 | 246 | ||
245 | In the screenshot above, we've toggled the ``__copy_to_user_ll()`` entry | 247 | In the screenshot above, we've toggled the ``__copy_to_user_ll()`` entry |
246 | and several subnodes all the way down. This lets us see which callchains | 248 | and several subnodes all the way down. This lets us see which call chains |
247 | contributed to the profiled ``__copy_to_user_ll()`` function which | 249 | contributed to the profiled ``__copy_to_user_ll()`` function which |
248 | contributed 1.77% to the total profile. | 250 | contributed 1.77% to the total profile. |
249 | 251 | ||
250 | As a bit of background explanation for these callchains, think about | 252 | As a bit of background explanation for these call chains, think about |
251 | what happens at a high level when you run wget to get a file out on the | 253 | what happens at a high level when you run ``wget`` to get a file out on the |
252 | network. Basically what happens is that the data comes into the kernel | 254 | network. Basically what happens is that the data comes into the kernel |
253 | via the network connection (socket) and is passed to the userspace | 255 | via the network connection (socket) and is passed to the user space |
254 | program 'wget' (which is actually a part of busybox, but that's not | 256 | program ``wget`` (which is actually a part of BusyBox, but that's not |
255 | important for now), which takes the buffers the kernel passes to it and | 257 | important for now), which takes the buffers the kernel passes to it and |
256 | writes it to a disk file to save it. | 258 | writes it to a disk file to save it. |
257 | 259 | ||
258 | The part of this process that we're looking at in the above call stacks | 260 | The part of this process that we're looking at in the above call stacks |
259 | is the part where the kernel passes the data it's read from the socket | 261 | is the part where the kernel passes the data it has read from the socket |
260 | down to wget i.e. a copy-to-user. | 262 | down to wget i.e. a ``copy-to-user``. |
261 | 263 | ||
262 | Notice also that here there's also a case where the hex value is | 264 | Notice also that here there's also a case where the hex value is |
263 | displayed in the callstack, here in the expanded ``sys_clock_gettime()`` | 265 | displayed in the call stack, here in the expanded ``sys_clock_gettime()`` |
264 | function. Later we'll see it resolve to a userspace function call in | 266 | function. Later we'll see it resolve to a user space function call in |
265 | busybox. | 267 | BusyBox. |
266 | 268 | ||
267 | .. image:: figures/perf-wget-g-copy-from-user-expanded-stripped.png | 269 | .. image:: figures/perf-wget-g-copy-from-user-expanded-stripped.png |
268 | :align: center | 270 | :align: center |
271 | :width: 70% | ||
269 | 272 | ||
270 | The above screenshot shows the other half of the journey for the data - | 273 | The above screenshot shows the other half of the journey for the data --- |
271 | from the wget program's userspace buffers to disk. To get the buffers to | 274 | from the ``wget`` program's user space buffers to disk. To get the buffers to |
272 | disk, the wget program issues a ``write(2)``, which does a ``copy-from-user`` to | 275 | disk, the wget program issues a ``write(2)``, which does a ``copy-from-user`` to |
273 | the kernel, which then takes care via some circuitous path (probably | 276 | the kernel, which then takes care via some circuitous path (probably |
274 | also present somewhere in the profile data), to get it safely to disk. | 277 | also present somewhere in the profile data), to get it safely to disk. |
@@ -277,112 +280,118 @@ Now that we've seen the basic layout of the profile data and the basics | |||
277 | of how to extract useful information out of it, let's get back to the | 280 | of how to extract useful information out of it, let's get back to the |
278 | task at hand and see if we can get some basic idea about where the time | 281 | task at hand and see if we can get some basic idea about where the time |
279 | is spent in the program we're profiling, wget. Remember that wget is | 282 | is spent in the program we're profiling, wget. Remember that wget is |
280 | actually implemented as an applet in busybox, so while the process name | 283 | actually implemented as an applet in BusyBox, so while the process name |
281 | is 'wget', the executable we're actually interested in is busybox. So | 284 | is ``wget``, the executable we're actually interested in is ``busybox``. |
282 | let's expand the first entry containing busybox: | 285 | Therefore, let's expand the first entry containing BusyBox: |
283 | 286 | ||
284 | .. image:: figures/perf-wget-busybox-expanded-stripped.png | 287 | .. image:: figures/perf-wget-busybox-expanded-stripped.png |
285 | :align: center | 288 | :align: center |
289 | :width: 70% | ||
286 | 290 | ||
287 | Again, before we expanded we saw that the function was labeled with a | 291 | Again, before we expanded we saw that the function was labeled with a |
288 | hex value instead of a symbol as with most of the kernel entries. | 292 | hex value instead of a symbol as with most of the kernel entries. |
289 | Expanding the busybox entry doesn't make it any better. | 293 | Expanding the BusyBox entry doesn't make it any better. |
290 | 294 | ||
291 | The problem is that perf can't find the symbol information for the | 295 | The problem is that perf can't find the symbol information for the |
292 | busybox binary, which is actually stripped out by the Yocto build | 296 | ``busybox`` binary, which is actually stripped out by the Yocto build |
293 | system. | 297 | system. |
294 | 298 | ||
295 | One way around that is to put the following in your ``local.conf`` file | 299 | One way around that is to put the following in your ``local.conf`` file |
296 | when you build the image: :: | 300 | when you build the image:: |
297 | 301 | ||
298 | INHIBIT_PACKAGE_STRIP = "1" | 302 | INHIBIT_PACKAGE_STRIP = "1" |
299 | 303 | ||
300 | However, we already have an image with the binaries stripped, so | 304 | However, we already have an image with the binaries stripped, so |
301 | what can we do to get perf to resolve the symbols? Basically we need to | 305 | what can we do to get perf to resolve the symbols? Basically we need to |
302 | install the debuginfo for the busybox package. | 306 | install the debugging information for the BusyBox package. |
303 | 307 | ||
304 | To generate the debug info for the packages in the image, we can add | 308 | To generate the debug info for the packages in the image, we can add |
305 | ``dbg-pkgs`` to :term:`EXTRA_IMAGE_FEATURES` in ``local.conf``. For example: :: | 309 | ``dbg-pkgs`` to :term:`EXTRA_IMAGE_FEATURES` in ``local.conf``. For example:: |
306 | 310 | ||
307 | EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile dbg-pkgs" | 311 | EXTRA_IMAGE_FEATURES = "debug-tweaks tools-profile dbg-pkgs" |
308 | 312 | ||
309 | Additionally, in order to generate the type of debuginfo that perf | 313 | Additionally, in order to generate the type of debugging information that perf |
310 | understands, we also need to set | 314 | understands, we also need to set :term:`PACKAGE_DEBUG_SPLIT_STYLE` |
311 | :term:`PACKAGE_DEBUG_SPLIT_STYLE` | 315 | in the ``local.conf`` file:: |
312 | in the ``local.conf`` file: :: | ||
313 | 316 | ||
314 | PACKAGE_DEBUG_SPLIT_STYLE = 'debug-file-directory' | 317 | PACKAGE_DEBUG_SPLIT_STYLE = 'debug-file-directory' |
315 | 318 | ||
316 | Once we've done that, we can install the | 319 | Once we've done that, we can install the debugging information for BusyBox. The |
317 | debuginfo for busybox. The debug packages once built can be found in | 320 | debug packages once built can be found in ``build/tmp/deploy/rpm/*`` |
318 | ``build/tmp/deploy/rpm/*`` on the host system. Find the busybox-dbg-...rpm | 321 | on the host system. Find the ``busybox-dbg-...rpm`` file and copy it |
319 | file and copy it to the target. For example: :: | 322 | to the target. For example:: |
320 | 323 | ||
321 | [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: | 324 | [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: |
322 | busybox-dbg-1.20.2-r2.core2_32.rpm 100% 1826KB 1.8MB/s 00:01 | 325 | busybox-dbg-1.20.2-r2.core2_32.rpm 100% 1826KB 1.8MB/s 00:01 |
323 | 326 | ||
324 | Now install the debug rpm on the target: :: | 327 | Now install the debug RPM on the target:: |
325 | 328 | ||
326 | root@crownbay:~# rpm -i busybox-dbg-1.20.2-r2.core2_32.rpm | 329 | root@crownbay:~# rpm -i busybox-dbg-1.20.2-r2.core2_32.rpm |
327 | 330 | ||
328 | Now that the debuginfo is installed, we see that the busybox entries now display | 331 | Now that the debugging information is installed, we see that the BusyBox entries now display |
329 | their functions symbolically: | 332 | their functions symbolically: |
330 | 333 | ||
331 | .. image:: figures/perf-wget-busybox-debuginfo.png | 334 | .. image:: figures/perf-wget-busybox-debuginfo.png |
332 | :align: center | 335 | :align: center |
336 | :width: 70% | ||
333 | 337 | ||
334 | If we expand one of the entries and press 'enter' on a leaf node, we're | 338 | If we expand one of the entries and press ``Enter`` on a leaf node, we're |
335 | presented with a menu of actions we can take to get more information | 339 | presented with a menu of actions we can take to get more information |
336 | related to that entry: | 340 | related to that entry: |
337 | 341 | ||
338 | .. image:: figures/perf-wget-busybox-dso-zoom-menu.png | 342 | .. image:: figures/perf-wget-busybox-dso-zoom-menu.png |
339 | :align: center | 343 | :align: center |
344 | :width: 70% | ||
340 | 345 | ||
341 | One of these actions allows us to show a view that displays a | 346 | One of these actions allows us to show a view that displays a |
342 | busybox-centric view of the profiled functions (in this case we've also | 347 | busybox-centric view of the profiled functions (in this case we've also |
343 | expanded all the nodes using the 'E' key): | 348 | expanded all the nodes using the ``E`` key): |
344 | 349 | ||
345 | .. image:: figures/perf-wget-busybox-dso-zoom.png | 350 | .. image:: figures/perf-wget-busybox-dso-zoom.png |
346 | :align: center | 351 | :align: center |
352 | :width: 70% | ||
347 | 353 | ||
348 | Finally, we can see that now that the busybox debuginfo is installed, | 354 | Finally, we can see that now that the BusyBox debugging information is installed, |
349 | the previously unresolved symbol in the ``sys_clock_gettime()`` entry | 355 | the previously unresolved symbol in the ``sys_clock_gettime()`` entry |
350 | mentioned previously is now resolved, and shows that the | 356 | mentioned previously is now resolved, and shows that the |
351 | sys_clock_gettime system call that was the source of 6.75% of the | 357 | ``sys_clock_gettime`` system call that was the source of 6.75% of the |
352 | copy-to-user overhead was initiated by the ``handle_input()`` busybox | 358 | ``copy-to-user`` overhead was initiated by the ``handle_input()`` BusyBox |
353 | function: | 359 | function: |
354 | 360 | ||
355 | .. image:: figures/perf-wget-g-copy-to-user-expanded-debuginfo.png | 361 | .. image:: figures/perf-wget-g-copy-to-user-expanded-debuginfo.png |
356 | :align: center | 362 | :align: center |
363 | :width: 70% | ||
357 | 364 | ||
358 | At the lowest level of detail, we can dive down to the assembly level | 365 | At the lowest level of detail, we can dive down to the assembly level |
359 | and see which instructions caused the most overhead in a function. | 366 | and see which instructions caused the most overhead in a function. |
360 | Pressing 'enter' on the 'udhcpc_main' function, we're again presented | 367 | Pressing ``Enter`` on the ``udhcpc_main`` function, we're again presented |
361 | with a menu: | 368 | with a menu: |
362 | 369 | ||
363 | .. image:: figures/perf-wget-busybox-annotate-menu.png | 370 | .. image:: figures/perf-wget-busybox-annotate-menu.png |
364 | :align: center | 371 | :align: center |
372 | :width: 70% | ||
365 | 373 | ||
366 | Selecting 'Annotate udhcpc_main', we get a detailed listing of | 374 | Selecting ``Annotate udhcpc_main``, we get a detailed listing of |
367 | percentages by instruction for the udhcpc_main function. From the | 375 | percentages by instruction for the ``udhcpc_main`` function. From the |
368 | display, we can see that over 50% of the time spent in this function is | 376 | display, we can see that over 50% of the time spent in this function is |
369 | taken up by a couple tests and the move of a constant (1) to a register: | 377 | taken up by a couple tests and the move of a constant (1) to a register: |
370 | 378 | ||
371 | .. image:: figures/perf-wget-busybox-annotate-udhcpc.png | 379 | .. image:: figures/perf-wget-busybox-annotate-udhcpc.png |
372 | :align: center | 380 | :align: center |
381 | :width: 70% | ||
373 | 382 | ||
374 | As a segue into tracing, let's try another profile using a different | 383 | As a segue into tracing, let's try another profile using a different |
375 | counter, something other than the default 'cycles'. | 384 | counter, something other than the default ``cycles``. |
376 | 385 | ||
377 | The tracing and profiling infrastructure in Linux has become unified in | 386 | The tracing and profiling infrastructure in Linux has become unified in |
378 | a way that allows us to use the same tool with a completely different | 387 | a way that allows us to use the same tool with a completely different |
379 | set of counters, not just the standard hardware counters that | 388 | set of counters, not just the standard hardware counters that |
380 | traditional tools have had to restrict themselves to (of course the | 389 | traditional tools have had to restrict themselves to (the |
381 | traditional tools can also make use of the expanded possibilities now | 390 | traditional tools can now actually make use of the expanded possibilities now |
382 | available to them, and in some cases have, as mentioned previously). | 391 | available to them, and in some cases have, as mentioned previously). |
383 | 392 | ||
384 | We can get a list of the available events that can be used to profile a | 393 | We can get a list of the available events that can be used to profile a |
385 | workload via 'perf list': :: | 394 | workload via ``perf list``:: |
386 | 395 | ||
387 | root@crownbay:~# perf list | 396 | root@crownbay:~# perf list |
388 | 397 | ||
@@ -518,17 +527,17 @@ workload via 'perf list': :: | |||
518 | .. admonition:: Tying it Together | 527 | .. admonition:: Tying it Together |
519 | 528 | ||
520 | These are exactly the same set of events defined by the trace event | 529 | These are exactly the same set of events defined by the trace event |
521 | subsystem and exposed by ftrace/tracecmd/kernelshark as files in | 530 | subsystem and exposed by ftrace / trace-cmd / KernelShark as files in |
522 | /sys/kernel/debug/tracing/events, by SystemTap as | 531 | ``/sys/kernel/debug/tracing/events``, by SystemTap as |
523 | kernel.trace("tracepoint_name") and (partially) accessed by LTTng. | 532 | kernel.trace("tracepoint_name") and (partially) accessed by LTTng. |
524 | 533 | ||
525 | Only a subset of these would be of interest to us when looking at this | 534 | Only a subset of these would be of interest to us when looking at this |
526 | workload, so let's choose the most likely subsystems (identified by the | 535 | workload, so let's choose the most likely subsystems (identified by the |
527 | string before the colon in the Tracepoint events) and do a 'perf stat' | 536 | string before the colon in the ``Tracepoint`` events) and do a ``perf stat`` |
528 | run using only those wildcarded subsystems: :: | 537 | run using only those subsystem wildcards:: |
529 | 538 | ||
530 | 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 | 539 | root@crownbay:~# perf stat -e skb:* -e net:* -e napi:* -e sched:* -e workqueue:* -e irq:* -e syscalls:* wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
531 | Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2': | 540 | Performance counter stats for 'wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2': |
532 | 541 | ||
533 | 23323 skb:kfree_skb | 542 | 23323 skb:kfree_skb |
534 | 0 skb:consume_skb | 543 | 0 skb:consume_skb |
@@ -587,17 +596,18 @@ run using only those wildcarded subsystems: :: | |||
587 | 596 | ||
588 | 597 | ||
589 | Let's pick one of these tracepoints | 598 | Let's pick one of these tracepoints |
590 | and tell perf to do a profile using it as the sampling event: :: | 599 | and tell perf to do a profile using it as the sampling event:: |
591 | 600 | ||
592 | root@crownbay:~# perf record -g -e sched:sched_wakeup wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 601 | root@crownbay:~# perf record -g -e sched:sched_wakeup wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
593 | 602 | ||
594 | .. image:: figures/sched-wakeup-profile.png | 603 | .. image:: figures/sched-wakeup-profile.png |
595 | :align: center | 604 | :align: center |
605 | :width: 70% | ||
596 | 606 | ||
597 | The screenshot above shows the results of running a profile using | 607 | The screenshot above shows the results of running a profile using |
598 | sched:sched_switch tracepoint, which shows the relative costs of various | 608 | sched:sched_switch tracepoint, which shows the relative costs of various |
599 | paths to sched_wakeup (note that sched_wakeup is the name of the | 609 | paths to ``sched_wakeup`` (note that ``sched_wakeup`` is the name of the |
600 | tracepoint - it's actually defined just inside ttwu_do_wakeup(), which | 610 | tracepoint --- it's actually defined just inside ``ttwu_do_wakeup()``, which |
601 | accounts for the function name actually displayed in the profile: | 611 | accounts for the function name actually displayed in the profile: |
602 | 612 | ||
603 | .. code-block:: c | 613 | .. code-block:: c |
@@ -615,15 +625,15 @@ accounts for the function name actually displayed in the profile: | |||
615 | } | 625 | } |
616 | 626 | ||
617 | A couple of the more interesting | 627 | A couple of the more interesting |
618 | callchains are expanded and displayed above, basically some network | 628 | call chains are expanded and displayed above, basically some network |
619 | receive paths that presumably end up waking up wget (busybox) when | 629 | receive paths that presumably end up waking up wget (BusyBox) when |
620 | network data is ready. | 630 | network data is ready. |
621 | 631 | ||
622 | Note that because tracepoints are normally used for tracing, the default | 632 | Note that because tracepoints are normally used for tracing, the default |
623 | sampling period for tracepoints is 1 i.e. for tracepoints perf will | 633 | sampling period for tracepoints is ``1`` i.e. for tracepoints perf will |
624 | sample on every event occurrence (this can be changed using the -c | 634 | sample on every event occurrence (this can be changed using the ``-c`` |
625 | option). This is in contrast to hardware counters such as for example | 635 | option). This is in contrast to hardware counters such as for example |
626 | the default 'cycles' hardware counter used for normal profiling, where | 636 | the default ``cycles`` hardware counter used for normal profiling, where |
627 | sampling periods are much higher (in the thousands) because profiling | 637 | sampling periods are much higher (in the thousands) because profiling |
628 | should have as low an overhead as possible and sampling on every cycle | 638 | should have as low an overhead as possible and sampling on every cycle |
629 | would be prohibitively expensive. | 639 | would be prohibitively expensive. |
@@ -634,24 +644,24 @@ Using perf to do Basic Tracing | |||
634 | Profiling is a great tool for solving many problems or for getting a | 644 | Profiling is a great tool for solving many problems or for getting a |
635 | high-level view of what's going on with a workload or across the system. | 645 | high-level view of what's going on with a workload or across the system. |
636 | It is however by definition an approximation, as suggested by the most | 646 | It is however by definition an approximation, as suggested by the most |
637 | prominent word associated with it, 'sampling'. On the one hand, it | 647 | prominent word associated with it, ``sampling``. On the one hand, it |
638 | allows a representative picture of what's going on in the system to be | 648 | allows a representative picture of what's going on in the system to be |
639 | cheaply taken, but on the other hand, that cheapness limits its utility | 649 | cheaply taken, but alternatively, that cheapness limits its utility |
640 | when that data suggests a need to 'dive down' more deeply to discover | 650 | when that data suggests a need to "dive down" more deeply to discover |
641 | what's really going on. In such cases, the only way to see what's really | 651 | what's really going on. In such cases, the only way to see what's really |
642 | going on is to be able to look at (or summarize more intelligently) the | 652 | going on is to be able to look at (or summarize more intelligently) the |
643 | individual steps that go into the higher-level behavior exposed by the | 653 | individual steps that go into the higher-level behavior exposed by the |
644 | coarse-grained profiling data. | 654 | coarse-grained profiling data. |
645 | 655 | ||
646 | As a concrete example, we can trace all the events we think might be | 656 | As a concrete example, we can trace all the events we think might be |
647 | applicable to our workload: :: | 657 | applicable to our workload:: |
648 | 658 | ||
649 | root@crownbay:~# perf record -g -e skb:* -e net:* -e napi:* -e sched:sched_switch -e sched:sched_wakeup -e irq:* | 659 | root@crownbay:~# perf record -g -e skb:* -e net:* -e napi:* -e sched:sched_switch -e sched:sched_wakeup -e irq:* |
650 | -e syscalls:sys_enter_read -e syscalls:sys_exit_read -e syscalls:sys_enter_write -e syscalls:sys_exit_write | 660 | -e syscalls:sys_enter_read -e syscalls:sys_exit_read -e syscalls:sys_enter_write -e syscalls:sys_exit_write |
651 | wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 661 | wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
652 | 662 | ||
653 | We can look at the raw trace output using 'perf script' with no | 663 | We can look at the raw trace output using ``perf script`` with no |
654 | arguments: :: | 664 | arguments:: |
655 | 665 | ||
656 | root@crownbay:~# perf script | 666 | root@crownbay:~# perf script |
657 | 667 | ||
@@ -681,7 +691,7 @@ arguments: :: | |||
681 | This gives us a detailed timestamped sequence of events that occurred within the | 691 | This gives us a detailed timestamped sequence of events that occurred within the |
682 | workload with respect to those events. | 692 | workload with respect to those events. |
683 | 693 | ||
684 | In many ways, profiling can be viewed as a subset of tracing - | 694 | In many ways, profiling can be viewed as a subset of tracing --- |
685 | theoretically, if you have a set of trace events that's sufficient to | 695 | theoretically, if you have a set of trace events that's sufficient to |
686 | capture all the important aspects of a workload, you can derive any of | 696 | capture all the important aspects of a workload, you can derive any of |
687 | the results or views that a profiling run can. | 697 | the results or views that a profiling run can. |
@@ -701,23 +711,23 @@ an infinite variety of ways. | |||
701 | Another way to look at it is that there are only so many ways that the | 711 | Another way to look at it is that there are only so many ways that the |
702 | 'primitive' counters can be used on their own to generate interesting | 712 | 'primitive' counters can be used on their own to generate interesting |
703 | output; to get anything more complicated than simple counts requires | 713 | output; to get anything more complicated than simple counts requires |
704 | some amount of additional logic, which is typically very specific to the | 714 | some amount of additional logic, which is typically specific to the |
705 | problem at hand. For example, if we wanted to make use of a 'counter' | 715 | problem at hand. For example, if we wanted to make use of a 'counter' |
706 | that maps to the value of the time difference between when a process was | 716 | that maps to the value of the time difference between when a process was |
707 | scheduled to run on a processor and the time it actually ran, we | 717 | scheduled to run on a processor and the time it actually ran, we |
708 | wouldn't expect such a counter to exist on its own, but we could derive | 718 | wouldn't expect such a counter to exist on its own, but we could derive |
709 | one called say 'wakeup_latency' and use it to extract a useful view of | 719 | one called say ``wakeup_latency`` and use it to extract a useful view of |
710 | that metric from trace data. Likewise, we really can't figure out from | 720 | that metric from trace data. Likewise, we really can't figure out from |
711 | standard profiling tools how much data every process on the system reads | 721 | standard profiling tools how much data every process on the system reads |
712 | and writes, along with how many of those reads and writes fail | 722 | and writes, along with how many of those reads and writes fail |
713 | completely. If we have sufficient trace data, however, we could with the | 723 | completely. If we have sufficient trace data, however, we could with the |
714 | right tools easily extract and present that information, but we'd need | 724 | right tools easily extract and present that information, but we'd need |
715 | something other than pre-canned profiling tools to do that. | 725 | something other than ready-made profiling tools to do that. |
716 | 726 | ||
717 | Luckily, there is a general-purpose way to handle such needs, called | 727 | Luckily, there is a general-purpose way to handle such needs, called |
718 | 'programming languages'. Making programming languages easily available | 728 | "programming languages". Making programming languages easily available |
719 | to apply to such problems given the specific format of data is called a | 729 | to apply to such problems given the specific format of data is called a |
720 | 'programming language binding' for that data and language. Perf supports | 730 | 'programming language binding' for that data and language. perf supports |
721 | two programming language bindings, one for Python and one for Perl. | 731 | two programming language bindings, one for Python and one for Perl. |
722 | 732 | ||
723 | .. admonition:: Tying it Together | 733 | .. admonition:: Tying it Together |
@@ -727,21 +737,21 @@ two programming language bindings, one for Python and one for Perl. | |||
727 | DProbes dpcc compiler, an ANSI C compiler which targeted a low-level | 737 | DProbes dpcc compiler, an ANSI C compiler which targeted a low-level |
728 | assembly language running on an in-kernel interpreter on the target | 738 | assembly language running on an in-kernel interpreter on the target |
729 | system. This is exactly analogous to what Sun's DTrace did, except | 739 | system. This is exactly analogous to what Sun's DTrace did, except |
730 | that DTrace invented its own language for the purpose. Systemtap, | 740 | that DTrace invented its own language for the purpose. SystemTap, |
731 | heavily inspired by DTrace, also created its own one-off language, | 741 | heavily inspired by DTrace, also created its own one-off language, |
732 | but rather than running the product on an in-kernel interpreter, | 742 | but rather than running the product on an in-kernel interpreter, |
733 | created an elaborate compiler-based machinery to translate its | 743 | created an elaborate compiler-based machinery to translate its |
734 | language into kernel modules written in C. | 744 | language into kernel modules written in C. |
735 | 745 | ||
736 | Now that we have the trace data in perf.data, we can use 'perf script | 746 | Now that we have the trace data in ``perf.data``, we can use ``perf script |
737 | -g' to generate a skeleton script with handlers for the read/write | 747 | -g`` to generate a skeleton script with handlers for the read / write |
738 | entry/exit events we recorded: :: | 748 | entry / exit events we recorded:: |
739 | 749 | ||
740 | root@crownbay:~# perf script -g python | 750 | root@crownbay:~# perf script -g python |
741 | generated Python script: perf-script.py | 751 | generated Python script: perf-script.py |
742 | 752 | ||
743 | The skeleton script simply creates a python function for each event type in the | 753 | The skeleton script just creates a Python function for each event type in the |
744 | perf.data file. The body of each function simply prints the event name along | 754 | ``perf.data`` file. The body of each function just prints the event name along |
745 | with its parameters. For example: | 755 | with its parameters. For example: |
746 | 756 | ||
747 | .. code-block:: python | 757 | .. code-block:: python |
@@ -755,7 +765,7 @@ with its parameters. For example: | |||
755 | print "skbaddr=%u, len=%u, name=%s\n" % (skbaddr, len, name), | 765 | print "skbaddr=%u, len=%u, name=%s\n" % (skbaddr, len, name), |
756 | 766 | ||
757 | We can run that script directly to print all of the events contained in the | 767 | We can run that script directly to print all of the events contained in the |
758 | perf.data file: :: | 768 | ``perf.data`` file:: |
759 | 769 | ||
760 | root@crownbay:~# perf script -s perf-script.py | 770 | root@crownbay:~# perf script -s perf-script.py |
761 | 771 | ||
@@ -784,8 +794,8 @@ perf.data file: :: | |||
784 | syscalls__sys_exit_read 1 11624.859944032 1262 wget nr=3, ret=1024 | 794 | syscalls__sys_exit_read 1 11624.859944032 1262 wget nr=3, ret=1024 |
785 | 795 | ||
786 | That in itself isn't very useful; after all, we can accomplish pretty much the | 796 | That in itself isn't very useful; after all, we can accomplish pretty much the |
787 | same thing by simply running 'perf script' without arguments in the same | 797 | same thing by just running ``perf script`` without arguments in the same |
788 | directory as the perf.data file. | 798 | directory as the ``perf.data`` file. |
789 | 799 | ||
790 | We can however replace the print statements in the generated function | 800 | We can however replace the print statements in the generated function |
791 | bodies with whatever we want, and thereby make it infinitely more | 801 | bodies with whatever we want, and thereby make it infinitely more |
@@ -806,8 +816,8 @@ event. For example: | |||
806 | 816 | ||
807 | Each event handler function in the generated code | 817 | Each event handler function in the generated code |
808 | is modified to do this. For convenience, we define a common function | 818 | is modified to do this. For convenience, we define a common function |
809 | called inc_counts() that each handler calls; inc_counts() simply tallies | 819 | called ``inc_counts()`` that each handler calls; ``inc_counts()`` just tallies |
810 | a count for each event using the 'counts' hash, which is a specialized | 820 | a count for each event using the ``counts`` hash, which is a specialized |
811 | hash function that does Perl-like autovivification, a capability that's | 821 | hash function that does Perl-like autovivification, a capability that's |
812 | extremely useful for kinds of multi-level aggregation commonly used in | 822 | extremely useful for kinds of multi-level aggregation commonly used in |
813 | processing traces (see perf's documentation on the Python language | 823 | processing traces (see perf's documentation on the Python language |
@@ -825,7 +835,7 @@ binding for details): | |||
825 | 835 | ||
826 | Finally, at the end of the trace processing run, we want to print the | 836 | Finally, at the end of the trace processing run, we want to print the |
827 | result of all the per-event tallies. For that, we use the special | 837 | result of all the per-event tallies. For that, we use the special |
828 | 'trace_end()' function: | 838 | ``trace_end()`` function: |
829 | 839 | ||
830 | .. code-block:: python | 840 | .. code-block:: python |
831 | 841 | ||
@@ -833,7 +843,7 @@ result of all the per-event tallies. For that, we use the special | |||
833 | for event_name, count in counts.iteritems(): | 843 | for event_name, count in counts.iteritems(): |
834 | print "%-40s %10s\n" % (event_name, count) | 844 | print "%-40s %10s\n" % (event_name, count) |
835 | 845 | ||
836 | The end result is a summary of all the events recorded in the trace: :: | 846 | The end result is a summary of all the events recorded in the trace:: |
837 | 847 | ||
838 | skb__skb_copy_datagram_iovec 13148 | 848 | skb__skb_copy_datagram_iovec 13148 |
839 | irq__softirq_entry 4796 | 849 | irq__softirq_entry 4796 |
@@ -854,56 +864,57 @@ The end result is a summary of all the events recorded in the trace: :: | |||
854 | syscalls__sys_exit_write 8990 | 864 | syscalls__sys_exit_write 8990 |
855 | 865 | ||
856 | Note that this is | 866 | Note that this is |
857 | pretty much exactly the same information we get from 'perf stat', which | 867 | pretty much exactly the same information we get from ``perf stat``, which |
858 | goes a little way to support the idea mentioned previously that given | 868 | goes a little way to support the idea mentioned previously that given |
859 | the right kind of trace data, higher-level profiling-type summaries can | 869 | the right kind of trace data, higher-level profiling-type summaries can |
860 | be derived from it. | 870 | be derived from it. |
861 | 871 | ||
862 | Documentation on using the `'perf script' python | 872 | Documentation on using the `'perf script' Python |
863 | binding <https://linux.die.net/man/1/perf-script-python>`__. | 873 | binding <https://linux.die.net/man/1/perf-script-python>`__. |
864 | 874 | ||
865 | System-Wide Tracing and Profiling | 875 | System-Wide Tracing and Profiling |
866 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ | 876 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ |
867 | 877 | ||
868 | The examples so far have focused on tracing a particular program or | 878 | The examples so far have focused on tracing a particular program or |
869 | workload - in other words, every profiling run has specified the program | 879 | workload --- that is, every profiling run has specified the program |
870 | to profile in the command-line e.g. 'perf record wget ...'. | 880 | to profile in the command-line e.g. ``perf record wget ...``. |
871 | 881 | ||
872 | It's also possible, and more interesting in many cases, to run a | 882 | It's also possible, and more interesting in many cases, to run a |
873 | system-wide profile or trace while running the workload in a separate | 883 | system-wide profile or trace while running the workload in a separate |
874 | shell. | 884 | shell. |
875 | 885 | ||
876 | To do system-wide profiling or tracing, you typically use the -a flag to | 886 | To do system-wide profiling or tracing, you typically use the ``-a`` flag to |
877 | 'perf record'. | 887 | ``perf record``. |
878 | 888 | ||
879 | To demonstrate this, open up one window and start the profile using the | 889 | To demonstrate this, open up one window and start the profile using the |
880 | -a flag (press Ctrl-C to stop tracing): :: | 890 | ``-a`` flag (press ``Ctrl-C`` to stop tracing):: |
881 | 891 | ||
882 | root@crownbay:~# perf record -g -a | 892 | root@crownbay:~# perf record -g -a |
883 | ^C[ perf record: Woken up 6 times to write data ] | 893 | ^C[ perf record: Woken up 6 times to write data ] |
884 | [ perf record: Captured and wrote 1.400 MB perf.data (~61172 samples) ] | 894 | [ perf record: Captured and wrote 1.400 MB perf.data (~61172 samples) ] |
885 | 895 | ||
886 | In another window, run the wget test: :: | 896 | In another window, run the ``wget`` test:: |
887 | 897 | ||
888 | root@crownbay:~# wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2 | 898 | root@crownbay:~# wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2 |
889 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 899 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
890 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA | 900 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA |
891 | 901 | ||
892 | Here we see entries not only for our wget load, but for | 902 | Here we see entries not only for our ``wget`` load, but for |
893 | other processes running on the system as well: | 903 | other processes running on the system as well: |
894 | 904 | ||
895 | .. image:: figures/perf-systemwide.png | 905 | .. image:: figures/perf-systemwide.png |
896 | :align: center | 906 | :align: center |
907 | :width: 70% | ||
897 | 908 | ||
898 | In the snapshot above, we can see callchains that originate in libc, and | 909 | In the snapshot above, we can see call chains that originate in ``libc``, and |
899 | a callchain from Xorg that demonstrates that we're using a proprietary X | 910 | a call chain from ``Xorg`` that demonstrates that we're using a proprietary X |
900 | driver in userspace (notice the presence of 'PVR' and some other | 911 | driver in user space (notice the presence of ``PVR`` and some other |
901 | unresolvable symbols in the expanded Xorg callchain). | 912 | unresolvable symbols in the expanded ``Xorg`` call chain). |
902 | 913 | ||
903 | Note also that we have both kernel and userspace entries in the above | 914 | Note also that we have both kernel and user space entries in the above |
904 | snapshot. We can also tell perf to focus on userspace but providing a | 915 | snapshot. We can also tell perf to focus on user space but providing a |
905 | modifier, in this case 'u', to the 'cycles' hardware counter when we | 916 | modifier, in this case ``u``, to the ``cycles`` hardware counter when we |
906 | record a profile: :: | 917 | record a profile:: |
907 | 918 | ||
908 | root@crownbay:~# perf record -g -a -e cycles:u | 919 | root@crownbay:~# perf record -g -a -e cycles:u |
909 | ^C[ perf record: Woken up 2 times to write data ] | 920 | ^C[ perf record: Woken up 2 times to write data ] |
@@ -911,25 +922,27 @@ record a profile: :: | |||
911 | 922 | ||
912 | .. image:: figures/perf-report-cycles-u.png | 923 | .. image:: figures/perf-report-cycles-u.png |
913 | :align: center | 924 | :align: center |
925 | :width: 70% | ||
914 | 926 | ||
915 | Notice in the screenshot above, we see only userspace entries ([.]) | 927 | Notice in the screenshot above, we see only user space entries (``[.]``) |
916 | 928 | ||
917 | Finally, we can press 'enter' on a leaf node and select the 'Zoom into | 929 | Finally, we can press ``Enter`` on a leaf node and select the ``Zoom into |
918 | DSO' menu item to show only entries associated with a specific DSO. In | 930 | DSO`` menu item to show only entries associated with a specific DSO. In |
919 | the screenshot below, we've zoomed into the 'libc' DSO which shows all | 931 | the screenshot below, we've zoomed into the ``libc`` DSO which shows all |
920 | the entries associated with the libc-xxx.so DSO. | 932 | the entries associated with the ``libc-xxx.so`` DSO. |
921 | 933 | ||
922 | .. image:: figures/perf-systemwide-libc.png | 934 | .. image:: figures/perf-systemwide-libc.png |
923 | :align: center | 935 | :align: center |
936 | :width: 70% | ||
924 | 937 | ||
925 | We can also use the system-wide -a switch to do system-wide tracing. | 938 | We can also use the system-wide ``-a`` switch to do system-wide tracing. |
926 | Here we'll trace a couple of scheduler events: :: | 939 | Here we'll trace a couple of scheduler events:: |
927 | 940 | ||
928 | root@crownbay:~# perf record -a -e sched:sched_switch -e sched:sched_wakeup | 941 | root@crownbay:~# perf record -a -e sched:sched_switch -e sched:sched_wakeup |
929 | ^C[ perf record: Woken up 38 times to write data ] | 942 | ^C[ perf record: Woken up 38 times to write data ] |
930 | [ perf record: Captured and wrote 9.780 MB perf.data (~427299 samples) ] | 943 | [ perf record: Captured and wrote 9.780 MB perf.data (~427299 samples) ] |
931 | 944 | ||
932 | We can look at the raw output using 'perf script' with no arguments: :: | 945 | We can look at the raw output using ``perf script`` with no arguments:: |
933 | 946 | ||
934 | root@crownbay:~# perf script | 947 | root@crownbay:~# perf script |
935 | 948 | ||
@@ -947,12 +960,12 @@ We can look at the raw output using 'perf script' with no arguments: :: | |||
947 | Filtering | 960 | Filtering |
948 | ^^^^^^^^^ | 961 | ^^^^^^^^^ |
949 | 962 | ||
950 | Notice that there are a lot of events that don't really have anything to | 963 | Notice that there are many events that don't really have anything to |
951 | do with what we're interested in, namely events that schedule 'perf' | 964 | do with what we're interested in, namely events that schedule ``perf`` |
952 | itself in and out or that wake perf up. We can get rid of those by using | 965 | itself in and out or that wake perf up. We can get rid of those by using |
953 | the '--filter' option - for each event we specify using -e, we can add a | 966 | the ``--filter`` option --- for each event we specify using ``-e``, we can add a |
954 | --filter after that to filter out trace events that contain fields with | 967 | ``--filter`` after that to filter out trace events that contain fields with |
955 | specific values: :: | 968 | specific values:: |
956 | 969 | ||
957 | root@crownbay:~# perf record -a -e sched:sched_switch --filter 'next_comm != perf && prev_comm != perf' -e sched:sched_wakeup --filter 'comm != perf' | 970 | root@crownbay:~# perf record -a -e sched:sched_switch --filter 'next_comm != perf && prev_comm != perf' -e sched:sched_wakeup --filter 'comm != perf' |
958 | ^C[ perf record: Woken up 38 times to write data ] | 971 | ^C[ perf record: Woken up 38 times to write data ] |
@@ -977,16 +990,16 @@ specific values: :: | |||
977 | 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 | 990 | 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 |
978 | 991 | ||
979 | In this case, we've filtered out all events that have | 992 | In this case, we've filtered out all events that have |
980 | 'perf' in their 'comm' or 'comm_prev' or 'comm_next' fields. Notice that | 993 | ``perf`` in their ``comm``, ``comm_prev`` or ``comm_next`` fields. Notice that |
981 | there are still events recorded for perf, but notice that those events | 994 | there are still events recorded for perf, but notice that those events |
982 | don't have values of 'perf' for the filtered fields. To completely | 995 | don't have values of ``perf`` for the filtered fields. To completely |
983 | filter out anything from perf will require a bit more work, but for the | 996 | filter out anything from perf will require a bit more work, but for the |
984 | purpose of demonstrating how to use filters, it's close enough. | 997 | purpose of demonstrating how to use filters, it's close enough. |
985 | 998 | ||
986 | .. admonition:: Tying it Together | 999 | .. admonition:: Tying it Together |
987 | 1000 | ||
988 | These are exactly the same set of event filters defined by the trace | 1001 | These are exactly the same set of event filters defined by the trace |
989 | event subsystem. See the ftrace/tracecmd/kernelshark section for more | 1002 | event subsystem. See the ftrace / trace-cmd / KernelShark section for more |
990 | discussion about these event filters. | 1003 | discussion about these event filters. |
991 | 1004 | ||
992 | .. admonition:: Tying it Together | 1005 | .. admonition:: Tying it Together |
@@ -996,14 +1009,14 @@ purpose of demonstrating how to use filters, it's close enough. | |||
996 | indispensable part of the perf design as it relates to tracing. | 1009 | indispensable part of the perf design as it relates to tracing. |
997 | kernel-based event filters provide a mechanism to precisely throttle | 1010 | kernel-based event filters provide a mechanism to precisely throttle |
998 | the event stream that appears in user space, where it makes sense to | 1011 | the event stream that appears in user space, where it makes sense to |
999 | provide bindings to real programming languages for postprocessing the | 1012 | provide bindings to real programming languages for post-processing the |
1000 | event stream. This architecture allows for the intelligent and | 1013 | event stream. This architecture allows for the intelligent and |
1001 | flexible partitioning of processing between the kernel and user | 1014 | flexible partitioning of processing between the kernel and user |
1002 | space. Contrast this with other tools such as SystemTap, which does | 1015 | space. Contrast this with other tools such as SystemTap, which does |
1003 | all of its processing in the kernel and as such requires a special | 1016 | all of its processing in the kernel and as such requires a special |
1004 | project-defined language in order to accommodate that design, or | 1017 | project-defined language in order to accommodate that design, or |
1005 | LTTng, where everything is sent to userspace and as such requires a | 1018 | LTTng, where everything is sent to user space and as such requires a |
1006 | super-efficient kernel-to-userspace transport mechanism in order to | 1019 | super-efficient kernel-to-user space transport mechanism in order to |
1007 | function properly. While perf certainly can benefit from for instance | 1020 | function properly. While perf certainly can benefit from for instance |
1008 | advances in the design of the transport, it doesn't fundamentally | 1021 | advances in the design of the transport, it doesn't fundamentally |
1009 | depend on them. Basically, if you find that your perf tracing | 1022 | depend on them. Basically, if you find that your perf tracing |
@@ -1014,10 +1027,10 @@ Using Dynamic Tracepoints | |||
1014 | ~~~~~~~~~~~~~~~~~~~~~~~~~ | 1027 | ~~~~~~~~~~~~~~~~~~~~~~~~~ |
1015 | 1028 | ||
1016 | perf isn't restricted to the fixed set of static tracepoints listed by | 1029 | perf isn't restricted to the fixed set of static tracepoints listed by |
1017 | 'perf list'. Users can also add their own 'dynamic' tracepoints anywhere | 1030 | ``perf list``. Users can also add their own "dynamic" tracepoints anywhere |
1018 | in the kernel. For instance, suppose we want to define our own | 1031 | in the kernel. For example, suppose we want to define our own |
1019 | tracepoint on do_fork(). We can do that using the 'perf probe' perf | 1032 | tracepoint on ``do_fork()``. We can do that using the ``perf probe`` perf |
1020 | subcommand: :: | 1033 | subcommand:: |
1021 | 1034 | ||
1022 | root@crownbay:~# perf probe do_fork | 1035 | root@crownbay:~# perf probe do_fork |
1023 | Added new event: | 1036 | Added new event: |
@@ -1028,10 +1041,10 @@ subcommand: :: | |||
1028 | perf record -e probe:do_fork -aR sleep 1 | 1041 | perf record -e probe:do_fork -aR sleep 1 |
1029 | 1042 | ||
1030 | Adding a new tracepoint via | 1043 | Adding a new tracepoint via |
1031 | 'perf probe' results in an event with all the expected files and format | 1044 | ``perf probe`` results in an event with all the expected files and format |
1032 | in /sys/kernel/debug/tracing/events, just the same as for static | 1045 | in ``/sys/kernel/debug/tracing/events``, just the same as for static |
1033 | tracepoints (as discussed in more detail in the trace events subsystem | 1046 | tracepoints (as discussed in more detail in the trace events subsystem |
1034 | section: :: | 1047 | section:: |
1035 | 1048 | ||
1036 | root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# ls -al | 1049 | root@crownbay:/sys/kernel/debug/tracing/events/probe/do_fork# ls -al |
1037 | drwxr-xr-x 2 root root 0 Oct 28 11:42 . | 1050 | drwxr-xr-x 2 root root 0 Oct 28 11:42 . |
@@ -1045,32 +1058,32 @@ section: :: | |||
1045 | name: do_fork | 1058 | name: do_fork |
1046 | ID: 944 | 1059 | ID: 944 |
1047 | format: | 1060 | format: |
1048 | field:unsigned short common_type; offset:0; size:2; signed:0; | 1061 | field:unsigned short common_type; offset:0; size:2; signed:0; |
1049 | field:unsigned char common_flags; offset:2; size:1; signed:0; | 1062 | field:unsigned char common_flags; offset:2; size:1; signed:0; |
1050 | field:unsigned char common_preempt_count; offset:3; size:1; signed:0; | 1063 | field:unsigned char common_preempt_count; offset:3; size:1; signed:0; |
1051 | field:int common_pid; offset:4; size:4; signed:1; | 1064 | field:int common_pid; offset:4; size:4; signed:1; |
1052 | field:int common_padding; offset:8; size:4; signed:1; | 1065 | field:int common_padding; offset:8; size:4; signed:1; |
1053 | 1066 | ||
1054 | field:unsigned long __probe_ip; offset:12; size:4; signed:0; | 1067 | field:unsigned long __probe_ip; offset:12; size:4; signed:0; |
1055 | 1068 | ||
1056 | print fmt: "(%lx)", REC->__probe_ip | 1069 | print fmt: "(%lx)", REC->__probe_ip |
1057 | 1070 | ||
1058 | We can list all dynamic tracepoints currently in | 1071 | We can list all dynamic tracepoints currently in |
1059 | existence: :: | 1072 | existence:: |
1060 | 1073 | ||
1061 | root@crownbay:~# perf probe -l | 1074 | root@crownbay:~# perf probe -l |
1062 | probe:do_fork (on do_fork) | 1075 | probe:do_fork (on do_fork) |
1063 | probe:schedule (on schedule) | 1076 | probe:schedule (on schedule) |
1064 | 1077 | ||
1065 | Let's record system-wide ('sleep 30' is a | 1078 | Let's record system-wide (``sleep 30`` is a |
1066 | trick for recording system-wide but basically do nothing and then wake | 1079 | trick for recording system-wide but basically do nothing and then wake |
1067 | up after 30 seconds): :: | 1080 | up after 30 seconds):: |
1068 | 1081 | ||
1069 | root@crownbay:~# perf record -g -a -e probe:do_fork sleep 30 | 1082 | root@crownbay:~# perf record -g -a -e probe:do_fork sleep 30 |
1070 | [ perf record: Woken up 1 times to write data ] | 1083 | [ perf record: Woken up 1 times to write data ] |
1071 | [ perf record: Captured and wrote 0.087 MB perf.data (~3812 samples) ] | 1084 | [ perf record: Captured and wrote 0.087 MB perf.data (~3812 samples) ] |
1072 | 1085 | ||
1073 | Using 'perf script' we can see each do_fork event that fired: :: | 1086 | Using ``perf script`` we can see each ``do_fork`` event that fired:: |
1074 | 1087 | ||
1075 | root@crownbay:~# perf script | 1088 | root@crownbay:~# perf script |
1076 | 1089 | ||
@@ -1111,71 +1124,73 @@ Using 'perf script' we can see each do_fork event that fired: :: | |||
1111 | matchbox-deskto 1311 [001] 34237.114106: do_fork: (c1028460) | 1124 | matchbox-deskto 1311 [001] 34237.114106: do_fork: (c1028460) |
1112 | gaku 1312 [000] 34237.202388: do_fork: (c1028460) | 1125 | gaku 1312 [000] 34237.202388: do_fork: (c1028460) |
1113 | 1126 | ||
1114 | And using 'perf report' on the same file, we can see the | 1127 | And using ``perf report`` on the same file, we can see the |
1115 | callgraphs from starting a few programs during those 30 seconds: | 1128 | call graphs from starting a few programs during those 30 seconds: |
1116 | 1129 | ||
1117 | .. image:: figures/perf-probe-do_fork-profile.png | 1130 | .. image:: figures/perf-probe-do_fork-profile.png |
1118 | :align: center | 1131 | :align: center |
1132 | :width: 70% | ||
1119 | 1133 | ||
1120 | .. admonition:: Tying it Together | 1134 | .. admonition:: Tying it Together |
1121 | 1135 | ||
1122 | The trace events subsystem accommodate static and dynamic tracepoints | 1136 | The trace events subsystem accommodate static and dynamic tracepoints |
1123 | in exactly the same way - there's no difference as far as the | 1137 | in exactly the same way --- there's no difference as far as the |
1124 | infrastructure is concerned. See the ftrace section for more details | 1138 | infrastructure is concerned. See the ftrace section for more details |
1125 | on the trace event subsystem. | 1139 | on the trace event subsystem. |
1126 | 1140 | ||
1127 | .. admonition:: Tying it Together | 1141 | .. admonition:: Tying it Together |
1128 | 1142 | ||
1129 | Dynamic tracepoints are implemented under the covers by kprobes and | 1143 | Dynamic tracepoints are implemented under the covers by Kprobes and |
1130 | uprobes. kprobes and uprobes are also used by and in fact are the | 1144 | Uprobes. Kprobes and Uprobes are also used by and in fact are the |
1131 | main focus of SystemTap. | 1145 | main focus of SystemTap. |
1132 | 1146 | ||
1133 | Perf Documentation | 1147 | perf Documentation |
1134 | ------------------ | 1148 | ------------------ |
1135 | 1149 | ||
1136 | Online versions of the man pages for the commands discussed in this | 1150 | Online versions of the manual pages for the commands discussed in this |
1137 | section can be found here: | 1151 | section can be found here: |
1138 | 1152 | ||
1139 | - The `'perf stat' manpage <https://linux.die.net/man/1/perf-stat>`__. | 1153 | - The `'perf stat' manual page <https://linux.die.net/man/1/perf-stat>`__. |
1140 | 1154 | ||
1141 | - The `'perf record' | 1155 | - The `'perf record' |
1142 | manpage <https://linux.die.net/man/1/perf-record>`__. | 1156 | manual page <https://linux.die.net/man/1/perf-record>`__. |
1143 | 1157 | ||
1144 | - The `'perf report' | 1158 | - The `'perf report' |
1145 | manpage <https://linux.die.net/man/1/perf-report>`__. | 1159 | manual page <https://linux.die.net/man/1/perf-report>`__. |
1146 | 1160 | ||
1147 | - The `'perf probe' manpage <https://linux.die.net/man/1/perf-probe>`__. | 1161 | - The `'perf probe' manual page <https://linux.die.net/man/1/perf-probe>`__. |
1148 | 1162 | ||
1149 | - The `'perf script' | 1163 | - The `'perf script' |
1150 | manpage <https://linux.die.net/man/1/perf-script>`__. | 1164 | manual page <https://linux.die.net/man/1/perf-script>`__. |
1151 | 1165 | ||
1152 | - Documentation on using the `'perf script' python | 1166 | - Documentation on using the `'perf script' Python |
1153 | binding <https://linux.die.net/man/1/perf-script-python>`__. | 1167 | binding <https://linux.die.net/man/1/perf-script-python>`__. |
1154 | 1168 | ||
1155 | - The top-level `perf(1) manpage <https://linux.die.net/man/1/perf>`__. | 1169 | - The top-level `perf(1) manual page <https://linux.die.net/man/1/perf>`__. |
1156 | 1170 | ||
1157 | Normally, you should be able to invoke the man pages via perf itself | 1171 | Normally, you should be able to open the manual pages via perf itself |
1158 | e.g. 'perf help' or 'perf help record'. | 1172 | e.g. ``perf help`` or ``perf help record``. |
1159 | 1173 | ||
1160 | However, by default Yocto doesn't install man pages, but perf invokes | 1174 | To have the perf manual pages installed on your target, modify your |
1161 | the man pages for most help functionality. This is a bug and is being | 1175 | configuration as follows:: |
1162 | addressed by a Yocto bug: :yocto_bugs:`Bug 3388 - perf: enable man pages for | ||
1163 | basic 'help' functionality </show_bug.cgi?id=3388>`. | ||
1164 | 1176 | ||
1165 | The man pages in text form, along with some other files, such as a set | 1177 | IMAGE_INSTALL:append = " perf perf-doc" |
1166 | of examples, can be found in the 'perf' directory of the kernel tree: :: | 1178 | DISTRO_FEATURES:append = " api-documentation" |
1179 | |||
1180 | The manual pages in text form, along with some other files, such as a set | ||
1181 | of examples, can also be found in the ``perf`` directory of the kernel tree:: | ||
1167 | 1182 | ||
1168 | tools/perf/Documentation | 1183 | tools/perf/Documentation |
1169 | 1184 | ||
1170 | There's also a nice perf tutorial on the perf | 1185 | There's also a nice perf tutorial on the perf |
1171 | wiki that goes into more detail than we do here in certain areas: `Perf | 1186 | wiki that goes into more detail than we do here in certain areas: `perf |
1172 | Tutorial <https://perf.wiki.kernel.org/index.php/Tutorial>`__ | 1187 | Tutorial <https://perf.wiki.kernel.org/index.php/Tutorial>`__ |
1173 | 1188 | ||
1174 | ftrace | 1189 | ftrace |
1175 | ====== | 1190 | ====== |
1176 | 1191 | ||
1177 | 'ftrace' literally refers to the 'ftrace function tracer' but in reality | 1192 | "ftrace" literally refers to the "ftrace function tracer" but in reality |
1178 | this encompasses a number of related tracers along with the | 1193 | this encompasses several related tracers along with the |
1179 | infrastructure that they all make use of. | 1194 | infrastructure that they all make use of. |
1180 | 1195 | ||
1181 | ftrace Setup | 1196 | ftrace Setup |
@@ -1184,20 +1199,20 @@ ftrace Setup | |||
1184 | For this section, we'll assume you've already performed the basic setup | 1199 | For this section, we'll assume you've already performed the basic setup |
1185 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. | 1200 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. |
1186 | 1201 | ||
1187 | ftrace, trace-cmd, and kernelshark run on the target system, and are | 1202 | ftrace, trace-cmd, and KernelShark run on the target system, and are |
1188 | ready to go out-of-the-box - no additional setup is necessary. For the | 1203 | ready to go out-of-the-box --- no additional setup is necessary. For the |
1189 | rest of this section we assume you've ssh'ed to the host and will be | 1204 | rest of this section we assume you're connected to the host through SSH and |
1190 | running ftrace on the target. kernelshark is a GUI application and if | 1205 | will be running ftrace on the target. KernelShark is a GUI application and if |
1191 | you use the '-X' option to ssh you can have the kernelshark GUI run on | 1206 | you use the ``-X`` option to ``ssh`` you can have the KernelShark GUI run on |
1192 | the target but display remotely on the host if you want. | 1207 | the target but display remotely on the host if you want. |
1193 | 1208 | ||
1194 | Basic ftrace usage | 1209 | Basic ftrace usage |
1195 | ------------------ | 1210 | ------------------ |
1196 | 1211 | ||
1197 | 'ftrace' essentially refers to everything included in the /tracing | 1212 | "ftrace" essentially refers to everything included in the ``/tracing`` |
1198 | directory of the mounted debugfs filesystem (Yocto follows the standard | 1213 | directory of the mounted debugfs filesystem (Yocto follows the standard |
1199 | convention and mounts it at /sys/kernel/debug). Here's a listing of all | 1214 | convention and mounts it at ``/sys/kernel/debug``). All the files found in |
1200 | the files found in /sys/kernel/debug/tracing on a Yocto system: :: | 1215 | ``/sys/kernel/debug/tracing`` on a Yocto system are:: |
1201 | 1216 | ||
1202 | root@sugarbay:/sys/kernel/debug/tracing# ls | 1217 | root@sugarbay:/sys/kernel/debug/tracing# ls |
1203 | README kprobe_events trace | 1218 | README kprobe_events trace |
@@ -1213,7 +1228,7 @@ the files found in /sys/kernel/debug/tracing on a Yocto system: :: | |||
1213 | free_buffer set_graph_function | 1228 | free_buffer set_graph_function |
1214 | 1229 | ||
1215 | The files listed above are used for various purposes | 1230 | The files listed above are used for various purposes |
1216 | - 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 |
1217 | tracing options, and yet others actually contain the tracing output when | 1232 | tracing options, and yet others actually contain the tracing output when |
1218 | a tracer is in effect. Some of the functions can be guessed from their | 1233 | a tracer is in effect. Some of the functions can be guessed from their |
1219 | names, others need explanation; in any case, we'll cover some of the | 1234 | names, others need explanation; in any case, we'll cover some of the |
@@ -1222,32 +1237,32 @@ the ftrace documentation. | |||
1222 | 1237 | ||
1223 | We'll start by looking at some of the available built-in tracers. | 1238 | We'll start by looking at some of the available built-in tracers. |
1224 | 1239 | ||
1225 | cat'ing the 'available_tracers' file lists the set of available tracers: :: | 1240 | The ``available_tracers`` file lists the set of available tracers:: |
1226 | 1241 | ||
1227 | root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers | 1242 | root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers |
1228 | blk function_graph function nop | 1243 | blk function_graph function nop |
1229 | 1244 | ||
1230 | The 'current_tracer' file contains the tracer currently in effect: :: | 1245 | The ``current_tracer`` file contains the tracer currently in effect:: |
1231 | 1246 | ||
1232 | root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer | 1247 | root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer |
1233 | nop | 1248 | nop |
1234 | 1249 | ||
1235 | The above listing of current_tracer shows that the | 1250 | The above listing of ``current_tracer`` shows that the |
1236 | '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 |
1237 | there's actually no tracer currently in effect. | 1252 | there's actually no tracer currently in effect. |
1238 | 1253 | ||
1239 | echo'ing one of the available_tracers into current_tracer makes the | 1254 | Writing one of the available tracers into ``current_tracer`` makes the |
1240 | specified tracer the current tracer: :: | 1255 | specified tracer the current tracer:: |
1241 | 1256 | ||
1242 | root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer | 1257 | root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer |
1243 | root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer | 1258 | root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer |
1244 | function | 1259 | function |
1245 | 1260 | ||
1246 | The above sets the current tracer to be the 'function tracer'. This tracer | 1261 | The above sets the current tracer to be the ``function`` tracer. This tracer |
1247 | traces every function call in the kernel and makes it available as the | 1262 | traces every function call in the kernel and makes it available as the |
1248 | contents of the 'trace' file. Reading the 'trace' file lists the | 1263 | contents of the ``trace`` file. Reading the ``trace`` file lists the |
1249 | currently buffered function calls that have been traced by the function | 1264 | currently buffered function calls that have been traced by the function |
1250 | tracer: :: | 1265 | tracer:: |
1251 | 1266 | ||
1252 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less | 1267 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less |
1253 | 1268 | ||
@@ -1292,7 +1307,7 @@ tracer: :: | |||
1292 | . | 1307 | . |
1293 | 1308 | ||
1294 | Each line in the trace above shows what was happening in the kernel on a given | 1309 | Each line in the trace above shows what was happening in the kernel on a given |
1295 | cpu, to the level of detail of function calls. Each entry shows the function | 1310 | CPU, to the level of detail of function calls. Each entry shows the function |
1296 | called, followed by its caller (after the arrow). | 1311 | called, followed by its caller (after the arrow). |
1297 | 1312 | ||
1298 | The function tracer gives you an extremely detailed idea of what the | 1313 | The function tracer gives you an extremely detailed idea of what the |
@@ -1302,11 +1317,11 @@ great way to learn about how the kernel code works in a dynamic sense. | |||
1302 | .. admonition:: Tying it Together | 1317 | .. admonition:: Tying it Together |
1303 | 1318 | ||
1304 | 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 |
1305 | ftrace:function tracepoint. | 1320 | ``ftrace:function`` tracepoint. |
1306 | 1321 | ||
1307 | It is a little more difficult to follow the call chains than it needs to | 1322 | It is a little more difficult to follow the call chains than it needs to |
1308 | be - luckily there's a variant of the function tracer that displays the | 1323 | be --- luckily there's a variant of the function tracer that displays the |
1309 | callchains explicitly, called the 'function_graph' tracer: :: | 1324 | call chains explicitly, called the ``function_graph`` tracer:: |
1310 | 1325 | ||
1311 | root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer | 1326 | root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer |
1312 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less | 1327 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less |
@@ -1421,11 +1436,11 @@ callchains explicitly, called the 'function_graph' tracer: :: | |||
1421 | 3) + 13.784 us | } | 1436 | 3) + 13.784 us | } |
1422 | 3) | sys_ioctl() { | 1437 | 3) | sys_ioctl() { |
1423 | 1438 | ||
1424 | As you can see, the function_graph display is much easier | 1439 | As you can see, the ``function_graph`` display is much easier |
1425 | to follow. Also note that in addition to the function calls and | 1440 | to follow. Also note that in addition to the function calls and |
1426 | associated braces, other events such as scheduler events are displayed | 1441 | associated braces, other events such as scheduler events are displayed |
1427 | in context. In fact, you can freely include any tracepoint available in | 1442 | in context. In fact, you can freely include any tracepoint available in |
1428 | the trace events subsystem described in the next section by simply | 1443 | the trace events subsystem described in the next section by just |
1429 | enabling those events, and they'll appear in context in the function | 1444 | enabling those events, and they'll appear in context in the function |
1430 | graph display. Quite a powerful tool for understanding kernel dynamics. | 1445 | graph display. Quite a powerful tool for understanding kernel dynamics. |
1431 | 1446 | ||
@@ -1439,10 +1454,10 @@ The 'trace events' Subsystem | |||
1439 | ---------------------------- | 1454 | ---------------------------- |
1440 | 1455 | ||
1441 | One especially important directory contained within the | 1456 | One especially important directory contained within the |
1442 | /sys/kernel/debug/tracing directory is the 'events' subdirectory, which | 1457 | ``/sys/kernel/debug/tracing`` directory is the ``events`` subdirectory, which |
1443 | contains representations of every tracepoint in the system. Listing out | 1458 | contains representations of every tracepoint in the system. Listing out |
1444 | the contents of the 'events' subdirectory, we see mainly another set of | 1459 | the contents of the ``events`` subdirectory, we see mainly another set of |
1445 | subdirectories: :: | 1460 | subdirectories:: |
1446 | 1461 | ||
1447 | root@sugarbay:/sys/kernel/debug/tracing# cd events | 1462 | root@sugarbay:/sys/kernel/debug/tracing# cd events |
1448 | root@sugarbay:/sys/kernel/debug/tracing/events# ls -al | 1463 | root@sugarbay:/sys/kernel/debug/tracing/events# ls -al |
@@ -1489,9 +1504,9 @@ subdirectories: :: | |||
1489 | drwxr-xr-x 26 root root 0 Nov 14 23:19 writeback | 1504 | drwxr-xr-x 26 root root 0 Nov 14 23:19 writeback |
1490 | 1505 | ||
1491 | Each one of these subdirectories | 1506 | Each one of these subdirectories |
1492 | corresponds to a 'subsystem' and contains yet again more subdirectories, | 1507 | corresponds to a "subsystem" and contains yet again more subdirectories, |
1493 | each one of those finally corresponding to a tracepoint. For example, | 1508 | each one of those finally corresponding to a tracepoint. For example, |
1494 | here are the contents of the 'kmem' subsystem: :: | 1509 | here are the contents of the ``kmem`` subsystem:: |
1495 | 1510 | ||
1496 | root@sugarbay:/sys/kernel/debug/tracing/events# cd kmem | 1511 | root@sugarbay:/sys/kernel/debug/tracing/events# cd kmem |
1497 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem# ls -al | 1512 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem# ls -al |
@@ -1513,7 +1528,7 @@ here are the contents of the 'kmem' subsystem: :: | |||
1513 | drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_pcpu_drain | 1528 | drwxr-xr-x 2 root root 0 Nov 14 23:19 mm_page_pcpu_drain |
1514 | 1529 | ||
1515 | Let's see what's inside the subdirectory for a | 1530 | Let's see what's inside the subdirectory for a |
1516 | specific tracepoint, in this case the one for kmalloc: :: | 1531 | specific tracepoint, in this case the one for ``kmalloc``:: |
1517 | 1532 | ||
1518 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem# cd kmalloc | 1533 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem# cd kmalloc |
1519 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# ls -al | 1534 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# ls -al |
@@ -1524,28 +1539,28 @@ specific tracepoint, in this case the one for kmalloc: :: | |||
1524 | -r--r--r-- 1 root root 0 Nov 14 23:19 format | 1539 | -r--r--r-- 1 root root 0 Nov 14 23:19 format |
1525 | -r--r--r-- 1 root root 0 Nov 14 23:19 id | 1540 | -r--r--r-- 1 root root 0 Nov 14 23:19 id |
1526 | 1541 | ||
1527 | The 'format' file for the | 1542 | The ``format`` file for the |
1528 | tracepoint describes the event in memory, which is used by the various | 1543 | tracepoint describes the event in memory, which is used by the various |
1529 | tracing tools that now make use of these tracepoint to parse the event | 1544 | tracing tools that now make use of these tracepoint to parse the event |
1530 | and make sense of it, along with a 'print fmt' field that allows tools | 1545 | and make sense of it, along with a ``print fmt`` field that allows tools |
1531 | like ftrace to display the event as text. Here's what the format of the | 1546 | like ftrace to display the event as text. The format of the |
1532 | kmalloc event looks like: :: | 1547 | ``kmalloc`` event looks like:: |
1533 | 1548 | ||
1534 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format | 1549 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format |
1535 | name: kmalloc | 1550 | name: kmalloc |
1536 | ID: 313 | 1551 | ID: 313 |
1537 | format: | 1552 | format: |
1538 | field:unsigned short common_type; offset:0; size:2; signed:0; | 1553 | field:unsigned short common_type; offset:0; size:2; signed:0; |
1539 | field:unsigned char common_flags; offset:2; size:1; signed:0; | 1554 | field:unsigned char common_flags; offset:2; size:1; signed:0; |
1540 | field:unsigned char common_preempt_count; offset:3; size:1; signed:0; | 1555 | field:unsigned char common_preempt_count; offset:3; size:1; signed:0; |
1541 | field:int common_pid; offset:4; size:4; signed:1; | 1556 | field:int common_pid; offset:4; size:4; signed:1; |
1542 | field:int common_padding; offset:8; size:4; signed:1; | 1557 | field:int common_padding; offset:8; size:4; signed:1; |
1543 | 1558 | ||
1544 | field:unsigned long call_site; offset:16; size:8; signed:0; | 1559 | field:unsigned long call_site; offset:16; size:8; signed:0; |
1545 | field:const void * ptr; offset:24; size:8; signed:0; | 1560 | field:const void * ptr; offset:24; size:8; signed:0; |
1546 | field:size_t bytes_req; offset:32; size:8; signed:0; | 1561 | field:size_t bytes_req; offset:32; size:8; signed:0; |
1547 | field:size_t bytes_alloc; offset:40; size:8; signed:0; | 1562 | field:size_t bytes_alloc; offset:40; size:8; signed:0; |
1548 | field:gfp_t gfp_flags; offset:48; size:4; signed:0; | 1563 | field:gfp_t gfp_flags; offset:48; size:4; signed:0; |
1549 | 1564 | ||
1550 | 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, | 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, |
1551 | (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)(((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( | 1566 | (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)(((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( |
@@ -1564,24 +1579,24 @@ kmalloc event looks like: :: | |||
1564 | long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"}, | 1579 | long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"}, |
1565 | {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT" | 1580 | {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT" |
1566 | 1581 | ||
1567 | The 'enable' file | 1582 | The ``enable`` file |
1568 | in the tracepoint directory is what allows the user (or tools such as | 1583 | in the tracepoint directory is what allows the user (or tools such as |
1569 | trace-cmd) to actually turn the tracepoint on and off. When enabled, the | 1584 | ``trace-cmd``) to actually turn the tracepoint on and off. When enabled, the |
1570 | corresponding tracepoint will start appearing in the ftrace 'trace' file | 1585 | corresponding tracepoint will start appearing in the ftrace ``trace`` file |
1571 | described previously. For example, this turns on the kmalloc tracepoint: :: | 1586 | described previously. For example, this turns on the ``kmalloc`` tracepoint:: |
1572 | 1587 | ||
1573 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > enable | 1588 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 1 > enable |
1574 | 1589 | ||
1575 | At the moment, we're not interested in the function tracer or | 1590 | At the moment, we're not interested in the function tracer or |
1576 | some other tracer that might be in effect, so we first turn it off, but | 1591 | some other tracer that might be in effect, so we first turn it off, but |
1577 | if we do that, we still need to turn tracing on in order to see the | 1592 | if we do that, we still need to turn tracing on in order to see the |
1578 | events in the output buffer: :: | 1593 | events in the output buffer:: |
1579 | 1594 | ||
1580 | root@sugarbay:/sys/kernel/debug/tracing# echo nop > current_tracer | 1595 | root@sugarbay:/sys/kernel/debug/tracing# echo nop > current_tracer |
1581 | root@sugarbay:/sys/kernel/debug/tracing# echo 1 > tracing_on | 1596 | root@sugarbay:/sys/kernel/debug/tracing# echo 1 > tracing_on |
1582 | 1597 | ||
1583 | Now, if we look at the the 'trace' file, we see nothing | 1598 | Now, if we look at the ``trace`` file, we see nothing |
1584 | but the kmalloc events we just turned on: :: | 1599 | but the ``kmalloc`` events we just turned on:: |
1585 | 1600 | ||
1586 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less | 1601 | root@sugarbay:/sys/kernel/debug/tracing# cat trace | less |
1587 | # tracer: nop | 1602 | # tracer: nop |
@@ -1627,17 +1642,17 @@ but the kmalloc events we just turned on: :: | |||
1627 | <idle>-0 [000] ..s3 18156.400660: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC | 1642 | <idle>-0 [000] ..s3 18156.400660: kmalloc: call_site=ffffffff81619b36 ptr=ffff88006d554800 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC |
1628 | 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 | 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 |
1629 | 1644 | ||
1630 | To again disable the kmalloc event, we need to send 0 to the enable file: :: | 1645 | To again disable the ``kmalloc`` event, we need to send ``0`` to the ``enable`` file:: |
1631 | 1646 | ||
1632 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 > enable | 1647 | root@sugarbay:/sys/kernel/debug/tracing/events/kmem/kmalloc# echo 0 > enable |
1633 | 1648 | ||
1634 | You can enable any number of events or complete subsystems (by | 1649 | You can enable any number of events or complete subsystems (by |
1635 | using the 'enable' file in the subsystem directory) and get an | 1650 | using the ``enable`` file in the subsystem directory) and get an |
1636 | arbitrarily fine-grained idea of what's going on in the system by | 1651 | arbitrarily fine-grained idea of what's going on in the system by |
1637 | enabling as many of the appropriate tracepoints as applicable. | 1652 | enabling as many of the appropriate tracepoints as applicable. |
1638 | 1653 | ||
1639 | A number of the tools described in this HOWTO do just that, including | 1654 | Several tools described in this How-to do just that, including |
1640 | trace-cmd and kernelshark in the next section. | 1655 | ``trace-cmd`` and KernelShark in the next section. |
1641 | 1656 | ||
1642 | .. admonition:: Tying it Together | 1657 | .. admonition:: Tying it Together |
1643 | 1658 | ||
@@ -1645,129 +1660,132 @@ trace-cmd and kernelshark in the next section. | |||
1645 | 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 |
1646 | they form a central point of integration for the various tracers | 1661 | they form a central point of integration for the various tracers |
1647 | available in Linux. They form a central part of the instrumentation | 1662 | available in Linux. They form a central part of the instrumentation |
1648 | for the following tools: perf, lttng, ftrace, blktrace and SystemTap | 1663 | for the following tools: perf, LTTng, ftrace, blktrace and SystemTap |
1649 | 1664 | ||
1650 | .. admonition:: Tying it Together | 1665 | .. admonition:: Tying it Together |
1651 | 1666 | ||
1652 | Eventually all the special-purpose tracers currently available in | 1667 | Eventually all the special-purpose tracers currently available in |
1653 | /sys/kernel/debug/tracing will be removed and replaced with | 1668 | ``/sys/kernel/debug/tracing`` will be removed and replaced with |
1654 | equivalent tracers based on the 'trace events' subsystem. | 1669 | equivalent tracers based on the "trace events" subsystem. |
1655 | 1670 | ||
1656 | trace-cmd/kernelshark | 1671 | trace-cmd / KernelShark |
1657 | --------------------- | 1672 | ----------------------- |
1658 | 1673 | ||
1659 | trace-cmd is essentially an extensive command-line 'wrapper' interface | 1674 | trace-cmd is essentially an extensive command-line "wrapper" interface |
1660 | that hides the details of all the individual files in | 1675 | that hides the details of all the individual files in |
1661 | /sys/kernel/debug/tracing, allowing users to specify specific particular | 1676 | ``/sys/kernel/debug/tracing``, allowing users to specify specific particular |
1662 | events within the /sys/kernel/debug/tracing/events/ subdirectory and to | 1677 | events within the ``/sys/kernel/debug/tracing/events/`` subdirectory and to |
1663 | collect traces and avoid having to deal with those details directly. | 1678 | collect traces and avoid having to deal with those details directly. |
1664 | 1679 | ||
1665 | As yet another layer on top of that, kernelshark provides a GUI that | 1680 | As yet another layer on top of that, KernelShark provides a GUI that |
1666 | allows users to start and stop traces and specify sets of events using | 1681 | allows users to start and stop traces and specify sets of events using |
1667 | an intuitive interface, and view the output as both trace events and as | 1682 | an intuitive interface, and view the output as both trace events and as |
1668 | a per-CPU graphical display. It directly uses 'trace-cmd' as the | 1683 | a per-CPU graphical display. It directly uses trace-cmd as the |
1669 | plumbing that accomplishes all that underneath the covers (and actually | 1684 | plumbing that accomplishes all that underneath the covers (and actually |
1670 | displays the trace-cmd command it uses, as we'll see). | 1685 | displays the trace-cmd command it uses, as we'll see). |
1671 | 1686 | ||
1672 | To start a trace using kernelshark, first start kernelshark: :: | 1687 | To start a trace using KernelShark, first start this tool:: |
1673 | 1688 | ||
1674 | root@sugarbay:~# kernelshark | 1689 | root@sugarbay:~# kernelshark |
1675 | 1690 | ||
1676 | Then bring up the 'Capture' dialog by | 1691 | Then open up the ``Capture`` dialog by choosing from the KernelShark menu:: |
1677 | choosing from the kernelshark menu: :: | ||
1678 | 1692 | ||
1679 | Capture | Record | 1693 | Capture | Record |
1680 | 1694 | ||
1681 | That will display the following dialog, which allows you to choose one or more | 1695 | That will display the following dialog, which allows you to choose one or more |
1682 | events (or even one or more complete subsystems) to trace: | 1696 | events (or even entire subsystems) to trace: |
1683 | 1697 | ||
1684 | .. image:: figures/kernelshark-choose-events.png | 1698 | .. image:: figures/kernelshark-choose-events.png |
1685 | :align: center | 1699 | :align: center |
1700 | :width: 70% | ||
1686 | 1701 | ||
1687 | Note that these are exactly the same sets of events described in the | 1702 | Note that these are exactly the same sets of events described in the |
1688 | previous trace events subsystem section, and in fact is where trace-cmd | 1703 | previous trace events subsystem section, and in fact is where trace-cmd |
1689 | gets them for kernelshark. | 1704 | gets them for KernelShark. |
1690 | 1705 | ||
1691 | In the above screenshot, we've decided to explore the graphics subsystem | 1706 | In the above screenshot, we've decided to explore the graphics subsystem |
1692 | a bit and so have chosen to trace all the tracepoints contained within | 1707 | a bit and so have chosen to trace all the tracepoints contained within |
1693 | the 'i915' and 'drm' subsystems. | 1708 | the ``i915`` and ``drm`` subsystems. |
1694 | 1709 | ||
1695 | After doing that, we can start and stop the trace using the 'Run' and | 1710 | After doing that, we can start and stop the trace using the ``Run`` and |
1696 | 'Stop' button on the lower right corner of the dialog (the same button | 1711 | ``Stop`` button on the lower right corner of the dialog (the same button |
1697 | will turn into the 'Stop' button after the trace has started): | 1712 | will turn into the 'Stop' button after the trace has started): |
1698 | 1713 | ||
1699 | .. image:: figures/kernelshark-output-display.png | 1714 | .. image:: figures/kernelshark-output-display.png |
1700 | :align: center | 1715 | :align: center |
1716 | :width: 70% | ||
1701 | 1717 | ||
1702 | Notice that the right-hand pane shows the exact trace-cmd command-line | 1718 | Notice that the right pane shows the exact trace-cmd command-line |
1703 | that's used to run the trace, along with the results of the trace-cmd | 1719 | that's used to run the trace, along with the results of the trace-cmd |
1704 | run. | 1720 | run. |
1705 | 1721 | ||
1706 | Once the 'Stop' button is pressed, the graphical view magically fills up | 1722 | Once the ``Stop`` button is pressed, the graphical view magically fills up |
1707 | with a colorful per-cpu display of the trace data, along with the | 1723 | with a colorful per-CPU display of the trace data, along with the |
1708 | detailed event listing below that: | 1724 | detailed event listing below that: |
1709 | 1725 | ||
1710 | .. image:: figures/kernelshark-i915-display.png | 1726 | .. image:: figures/kernelshark-i915-display.png |
1711 | :align: center | 1727 | :align: center |
1728 | :width: 70% | ||
1712 | 1729 | ||
1713 | Here's another example, this time a display resulting from tracing 'all | 1730 | Here's another example, this time a display resulting from tracing ``all |
1714 | events': | 1731 | events``: |
1715 | 1732 | ||
1716 | .. image:: figures/kernelshark-all.png | 1733 | .. image:: figures/kernelshark-all.png |
1717 | :align: center | 1734 | :align: center |
1735 | :width: 70% | ||
1718 | 1736 | ||
1719 | The tool is pretty self-explanatory, but for more detailed information | 1737 | The tool is pretty self-explanatory, but for more detailed information |
1720 | on navigating through the data, see the `kernelshark | 1738 | on navigating through the data, see the `KernelShark |
1721 | website <https://rostedt.homelinux.com/kernelshark/>`__. | 1739 | website <https://kernelshark.org/Documentation.html>`__. |
1722 | 1740 | ||
1723 | ftrace Documentation | 1741 | ftrace Documentation |
1724 | -------------------- | 1742 | -------------------- |
1725 | 1743 | ||
1726 | The documentation for ftrace can be found in the kernel Documentation | 1744 | The documentation for ftrace can be found in the kernel Documentation |
1727 | directory: :: | 1745 | directory:: |
1728 | 1746 | ||
1729 | Documentation/trace/ftrace.txt | 1747 | Documentation/trace/ftrace.txt |
1730 | 1748 | ||
1731 | The documentation for the trace event subsystem can also be found in the kernel | 1749 | The documentation for the trace event subsystem can also be found in the kernel |
1732 | Documentation directory: :: | 1750 | Documentation directory:: |
1733 | 1751 | ||
1734 | Documentation/trace/events.txt | 1752 | Documentation/trace/events.txt |
1735 | 1753 | ||
1736 | There is a nice series of articles on using ftrace and trace-cmd at LWN: | 1754 | A nice series of articles on using ftrace and trace-cmd are available at LWN: |
1737 | 1755 | ||
1738 | - `Debugging the kernel using Ftrace - part | 1756 | - `Debugging the kernel using ftrace - part |
1739 | 1 <https://lwn.net/Articles/365835/>`__ | 1757 | 1 <https://lwn.net/Articles/365835/>`__ |
1740 | 1758 | ||
1741 | - `Debugging the kernel using Ftrace - part | 1759 | - `Debugging the kernel using ftrace - part |
1742 | 2 <https://lwn.net/Articles/366796/>`__ | 1760 | 2 <https://lwn.net/Articles/366796/>`__ |
1743 | 1761 | ||
1744 | - `Secrets of the Ftrace function | 1762 | - `Secrets of the ftrace function |
1745 | tracer <https://lwn.net/Articles/370423/>`__ | 1763 | tracer <https://lwn.net/Articles/370423/>`__ |
1746 | 1764 | ||
1747 | - `trace-cmd: A front-end for | 1765 | - `trace-cmd: A front-end for |
1748 | Ftrace <https://lwn.net/Articles/410200/>`__ | 1766 | ftrace <https://lwn.net/Articles/410200/>`__ |
1749 | 1767 | ||
1750 | There's more detailed documentation kernelshark usage here: | 1768 | See also `KernelShark's documentation <https://kernelshark.org/Documentation.html>`__ |
1751 | `KernelShark <https://rostedt.homelinux.com/kernelshark/>`__ | 1769 | for further usage details. |
1752 | 1770 | ||
1753 | An amusing yet useful README (a tracing mini-HOWTO) can be found in | 1771 | An amusing yet useful README (a tracing mini-How-to) can be found in |
1754 | ``/sys/kernel/debug/tracing/README``. | 1772 | ``/sys/kernel/debug/tracing/README``. |
1755 | 1773 | ||
1756 | systemtap | 1774 | SystemTap |
1757 | ========= | 1775 | ========= |
1758 | 1776 | ||
1759 | SystemTap is a system-wide script-based tracing and profiling tool. | 1777 | SystemTap is a system-wide script-based tracing and profiling tool. |
1760 | 1778 | ||
1761 | SystemTap scripts are C-like programs that are executed in the kernel to | 1779 | SystemTap scripts are C-like programs that are executed in the kernel to |
1762 | gather/print/aggregate data extracted from the context they end up being | 1780 | gather / print / aggregate data extracted from the context they end up being |
1763 | invoked under. | 1781 | called under. |
1764 | 1782 | ||
1765 | For example, this probe from the `SystemTap | 1783 | For example, this probe from the `SystemTap |
1766 | tutorial <https://sourceware.org/systemtap/tutorial/>`__ simply prints a | 1784 | tutorial <https://sourceware.org/systemtap/tutorial/>`__ just prints a |
1767 | line every time any process on the system open()s a file. For each line, | 1785 | line every time any process on the system runs ``open()`` on a file. For each line, |
1768 | it prints the executable name of the program that opened the file, along | 1786 | it prints the executable name of the program that opened the file, along |
1769 | with its PID, and the name of the file it opened (or tried to open), | 1787 | with its PID, and the name of the file it opened (or tried to open), which it |
1770 | which it extracts from the open syscall's argstr. | 1788 | extracts from the argument string (``argstr``) of the ``open`` system call. |
1771 | 1789 | ||
1772 | .. code-block:: none | 1790 | .. code-block:: none |
1773 | 1791 | ||
@@ -1782,79 +1800,85 @@ which it extracts from the open syscall's argstr. | |||
1782 | } | 1800 | } |
1783 | 1801 | ||
1784 | Normally, to execute this | 1802 | Normally, to execute this |
1785 | probe, you'd simply install systemtap on the system you want to probe, | 1803 | probe, you'd just install SystemTap on the system you want to probe, |
1786 | and directly run the probe on that system e.g. assuming the name of the | 1804 | and directly run the probe on that system e.g. assuming the name of the |
1787 | file containing the above text is trace_open.stp: :: | 1805 | file containing the above text is ``trace_open.stp``:: |
1788 | 1806 | ||
1789 | # stap trace_open.stp | 1807 | # stap trace_open.stp |
1790 | 1808 | ||
1791 | What systemtap does under the covers to run this probe is 1) parse and | 1809 | What SystemTap does under the covers to run this probe is 1) parse and |
1792 | convert the probe to an equivalent 'C' form, 2) compile the 'C' form | 1810 | convert the probe to an equivalent "C" form, 2) compile the "C" form |
1793 | into a kernel module, 3) insert the module into the kernel, which arms | 1811 | into a kernel module, 3) insert the module into the kernel, which arms |
1794 | it, and 4) collect the data generated by the probe and display it to the | 1812 | it, and 4) collect the data generated by the probe and display it to the |
1795 | user. | 1813 | user. |
1796 | 1814 | ||
1797 | In order to accomplish steps 1 and 2, the 'stap' program needs access to | 1815 | In order to accomplish steps 1 and 2, the ``stap`` program needs access to |
1798 | the kernel build system that produced the kernel that the probed system | 1816 | the kernel build system that produced the kernel that the probed system |
1799 | is running. In the case of a typical embedded system (the 'target'), the | 1817 | is running. In the case of a typical embedded system (the "target"), the |
1800 | kernel build system unfortunately isn't typically part of the image | 1818 | kernel build system unfortunately isn't typically part of the image |
1801 | running on the target. It is normally available on the 'host' system | 1819 | running on the target. It is normally available on the "host" system |
1802 | that produced the target image however; in such cases, steps 1 and 2 are | 1820 | that produced the target image however; in such cases, steps 1 and 2 are |
1803 | executed on the host system, and steps 3 and 4 are executed on the | 1821 | executed on the host system, and steps 3 and 4 are executed on the |
1804 | target system, using only the systemtap 'runtime'. | 1822 | target system, using only the SystemTap "runtime". |
1805 | 1823 | ||
1806 | The systemtap support in Yocto assumes that only steps 3 and 4 are run | 1824 | The SystemTap support in Yocto assumes that only steps 3 and 4 are run |
1807 | on the target; it is possible to do everything on the target, but this | 1825 | on the target; it is possible to do everything on the target, but this |
1808 | section assumes only the typical embedded use-case. | 1826 | section assumes only the typical embedded use-case. |
1809 | 1827 | ||
1810 | So basically what you need to do in order to run a systemtap script on | 1828 | Therefore, what you need to do in order to run a SystemTap script on |
1811 | the target is to 1) on the host system, compile the probe into a kernel | 1829 | the target is to 1) on the host system, compile the probe into a kernel |
1812 | module that makes sense to the target, 2) copy the module onto the | 1830 | module that makes sense to the target, 2) copy the module onto the |
1813 | target system and 3) insert the module into the target kernel, which | 1831 | target system and 3) insert the module into the target kernel, which |
1814 | arms it, and 4) collect the data generated by the probe and display it | 1832 | arms it, and 4) collect the data generated by the probe and display it |
1815 | to the user. | 1833 | to the user. |
1816 | 1834 | ||
1817 | systemtap Setup | 1835 | SystemTap Setup |
1818 | --------------- | 1836 | --------------- |
1819 | 1837 | ||
1820 | Those are a lot of steps and a lot of details, but fortunately Yocto | 1838 | Those are many steps and details, but fortunately Yocto |
1821 | includes a script called 'crosstap' that will take care of those | 1839 | includes a script called ``crosstap`` that will take care of those |
1822 | details, allowing you to simply execute a systemtap script on the remote | 1840 | details, allowing you to just execute a SystemTap script on the remote |
1823 | target, with arguments if necessary. | 1841 | target, with arguments if necessary. |
1824 | 1842 | ||
1825 | In order to do this from a remote host, however, you need to have access | 1843 | In order to do this from a remote host, however, you need to have access |
1826 | to the build for the image you booted. The 'crosstap' script provides | 1844 | to the build for the image you booted. The ``crosstap`` script provides |
1827 | details on how to do this if you run the script on the host without | 1845 | details on how to do this if you run the script on the host without |
1828 | having done a build: :: | 1846 | having done a build:: |
1829 | 1847 | ||
1830 | $ crosstap root@192.168.1.88 trace_open.stp | 1848 | $ crosstap root@192.168.1.88 trace_open.stp |
1831 | 1849 | ||
1832 | Error: No target kernel build found. | 1850 | Error: No target kernel build found. |
1833 | Did you forget to create a local build of your image? | 1851 | Did you forget to create a local build of your image? |
1834 | 1852 | ||
1835 | 'crosstap' requires a local sdk build of the target system | 1853 | 'crosstap' requires a local SDK build of the target system |
1836 | (or a build that includes 'tools-profile') in order to build | 1854 | (or a build that includes 'tools-profile') in order to build |
1837 | kernel modules that can probe the target system. | 1855 | kernel modules that can probe the target system. |
1838 | 1856 | ||
1839 | Practically speaking, that means you need to do the following: | 1857 | Practically speaking, that means you need to do the following: |
1840 | - If you're running a pre-built image, download the release | 1858 | |
1841 | and/or BSP tarballs used to build the image. | 1859 | - If you're running a pre-built image, download the release |
1842 | - If you're working from git sources, just clone the metadata | 1860 | and/or BSP tarballs used to build the image. |
1843 | and BSP layers needed to build the image you'll be booting. | 1861 | |
1844 | - Make sure you're properly set up to build a new image (see | 1862 | - If you're working from git sources, just clone the metadata |
1845 | the BSP README and/or the widely available basic documentation | 1863 | and BSP layers needed to build the image you'll be booting. |
1846 | that discusses how to build images). | 1864 | |
1847 | - Build an -sdk version of the image e.g.: | 1865 | - Make sure you're properly set up to build a new image (see |
1848 | $ bitbake core-image-sato-sdk | 1866 | the BSP README and/or the widely available basic documentation |
1849 | OR | 1867 | that discusses how to build images). |
1850 | - Build a non-sdk image but include the profiling tools: | 1868 | |
1851 | [ edit local.conf and add 'tools-profile' to the end of | 1869 | - Build an ``-sdk`` version of the image e.g.:: |
1852 | the EXTRA_IMAGE_FEATURES variable ] | 1870 | |
1853 | $ bitbake core-image-sato | 1871 | $ bitbake core-image-sato-sdk |
1872 | |||
1873 | - Or build a non-SDK image but include the profiling tools | ||
1874 | (edit ``local.conf`` and add ``tools-profile`` to the end of | ||
1875 | :term:`EXTRA_IMAGE_FEATURES` variable):: | ||
1876 | |||
1877 | $ bitbake core-image-sato | ||
1854 | 1878 | ||
1855 | Once you've build the image on the host system, you're ready to | 1879 | Once you've build the image on the host system, you're ready to |
1856 | boot it (or the equivalent pre-built image) and use 'crosstap' | 1880 | boot it (or the equivalent pre-built image) and use ``crosstap`` |
1857 | to probe it (you need to source the environment as usual first): | 1881 | to probe it (you need to source the environment as usual first):: |
1858 | 1882 | ||
1859 | $ source oe-init-build-env | 1883 | $ source oe-init-build-env |
1860 | $ cd ~/my/systemtap/scripts | 1884 | $ cd ~/my/systemtap/scripts |
@@ -1862,30 +1886,28 @@ having done a build: :: | |||
1862 | 1886 | ||
1863 | .. note:: | 1887 | .. note:: |
1864 | 1888 | ||
1865 | SystemTap, which uses 'crosstap', assumes you can establish an ssh | 1889 | SystemTap, which uses ``crosstap``, assumes you can establish an SSH |
1866 | connection to the remote target. Please refer to the crosstap wiki | 1890 | connection to the remote target. Please refer to the crosstap wiki |
1867 | page for details on verifying ssh connections at | 1891 | page for details on verifying SSH connections. Also, the ability to SSH |
1868 | . Also, the ability to ssh into the target system is not enabled by | 1892 | into the target system is not enabled by default in ``*-minimal`` images. |
1869 | default in \*-minimal images. | ||
1870 | 1893 | ||
1871 | So essentially what you need to | 1894 | Therefore, what you need to do is build an SDK image or image with |
1872 | do is build an SDK image or image with 'tools-profile' as detailed in | 1895 | ``tools-profile`` as detailed in the ":ref:`profile-manual/intro:General Setup`" |
1873 | the ":ref:`profile-manual/intro:General Setup`" section of this | 1896 | section of this manual, and boot the resulting target image. |
1874 | manual, and boot the resulting target image. | ||
1875 | 1897 | ||
1876 | .. note:: | 1898 | .. note:: |
1877 | 1899 | ||
1878 | If you have a build directory containing multiple machines, you need | 1900 | If you have a :term:`Build Directory` containing multiple machines, you need |
1879 | to have the MACHINE you're connecting to selected in local.conf, and | 1901 | to have the :term:`MACHINE` you're connecting to selected in ``local.conf``, and |
1880 | the kernel in that machine's build directory must match the kernel on | 1902 | the kernel in that machine's :term:`Build Directory` must match the kernel on |
1881 | the booted system exactly, or you'll get the above 'crosstap' message | 1903 | the booted system exactly, or you'll get the above ``crosstap`` message |
1882 | when you try to invoke a script. | 1904 | when you try to call a script. |
1883 | 1905 | ||
1884 | Running a Script on a Target | 1906 | Running a Script on a Target |
1885 | ---------------------------- | 1907 | ---------------------------- |
1886 | 1908 | ||
1887 | Once you've done that, you should be able to run a systemtap script on | 1909 | Once you've done that, you should be able to run a SystemTap script on |
1888 | the target: :: | 1910 | the target:: |
1889 | 1911 | ||
1890 | $ cd /path/to/yocto | 1912 | $ cd /path/to/yocto |
1891 | $ source oe-init-build-env | 1913 | $ source oe-init-build-env |
@@ -1900,26 +1922,25 @@ the target: :: | |||
1900 | meta-toolchain | 1922 | meta-toolchain |
1901 | meta-ide-support | 1923 | meta-ide-support |
1902 | 1924 | ||
1903 | You can also run generated qemu images with a command like 'runqemu qemux86-64' | 1925 | You can also run generated QEMU images with a command like 'runqemu qemux86-64' |
1904 | 1926 | ||
1905 | Once you've done that, you can cd to whatever | 1927 | Once you've done that, you can ``cd`` to whatever |
1906 | directory contains your scripts and use 'crosstap' to run the script: :: | 1928 | directory contains your scripts and use ``crosstap`` to run the script:: |
1907 | 1929 | ||
1908 | $ cd /path/to/my/systemap/script | 1930 | $ cd /path/to/my/systemap/script |
1909 | $ crosstap root@192.168.7.2 trace_open.stp | 1931 | $ crosstap root@192.168.7.2 trace_open.stp |
1910 | 1932 | ||
1911 | If you get an error connecting to the target e.g.: :: | 1933 | If you get an error connecting to the target e.g.:: |
1912 | 1934 | ||
1913 | $ crosstap root@192.168.7.2 trace_open.stp | 1935 | $ crosstap root@192.168.7.2 trace_open.stp |
1914 | error establishing ssh connection on remote 'root@192.168.7.2' | 1936 | error establishing ssh connection on remote 'root@192.168.7.2' |
1915 | 1937 | ||
1916 | Try ssh'ing to the target and see what happens: :: | 1938 | Try connecting to the target through SSH and see what happens:: |
1917 | 1939 | ||
1918 | $ ssh root@192.168.7.2 | 1940 | $ ssh root@192.168.7.2 |
1919 | 1941 | ||
1920 | A lot of the time, connection | 1942 | Connection problems are often due specifying a wrong IP address or having a ``host key |
1921 | problems are due specifying a wrong IP address or having a 'host key | 1943 | verification error``. |
1922 | verification error'. | ||
1923 | 1944 | ||
1924 | If everything worked as planned, you should see something like this | 1945 | If everything worked as planned, you should see something like this |
1925 | (enter the password when prompted, or press enter if it's set up to use | 1946 | (enter the password when prompted, or press enter if it's set up to use |
@@ -1932,7 +1953,7 @@ no password): | |||
1932 | matchbox-termin(1036) open ("/tmp/vte3FS2LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) | 1953 | matchbox-termin(1036) open ("/tmp/vte3FS2LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) |
1933 | matchbox-termin(1036) open ("/tmp/vteJMC7LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) | 1954 | matchbox-termin(1036) open ("/tmp/vteJMC7LW", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) |
1934 | 1955 | ||
1935 | systemtap Documentation | 1956 | SystemTap Documentation |
1936 | ----------------------- | 1957 | ----------------------- |
1937 | 1958 | ||
1938 | The SystemTap language reference can be found here: `SystemTap Language | 1959 | The SystemTap language reference can be found here: `SystemTap Language |
@@ -1945,7 +1966,7 @@ page <https://sourceware.org/systemtap/documentation.html>`__ | |||
1945 | Sysprof | 1966 | Sysprof |
1946 | ======= | 1967 | ======= |
1947 | 1968 | ||
1948 | Sysprof is a very easy to use system-wide profiler that consists of a | 1969 | Sysprof is an easy to use system-wide profiler that consists of a |
1949 | single window with three panes and a few buttons which allow you to | 1970 | single window with three panes and a few buttons which allow you to |
1950 | start, stop, and view the profile from one place. | 1971 | start, stop, and view the profile from one place. |
1951 | 1972 | ||
@@ -1955,41 +1976,43 @@ Sysprof Setup | |||
1955 | For this section, we'll assume you've already performed the basic setup | 1976 | For this section, we'll assume you've already performed the basic setup |
1956 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. | 1977 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. |
1957 | 1978 | ||
1958 | Sysprof is a GUI-based application that runs on the target system. For | 1979 | Sysprof is a GUI-based application that runs on the target system. For the rest |
1959 | the rest of this document we assume you've ssh'ed to the host and will | 1980 | of this document we assume you're connected to the host through SSH and will be |
1960 | be running Sysprof on the target (you can use the '-X' option to ssh and | 1981 | running Sysprof on the target (you can use the ``-X`` option to ``ssh`` and |
1961 | have the Sysprof GUI run on the target but display remotely on the host | 1982 | have the Sysprof GUI run on the target but display remotely on the host |
1962 | if you want). | 1983 | if you want). |
1963 | 1984 | ||
1964 | Basic Sysprof Usage | 1985 | Basic Sysprof Usage |
1965 | ------------------- | 1986 | ------------------- |
1966 | 1987 | ||
1967 | To start profiling the system, you simply press the 'Start' button. To | 1988 | To start profiling the system, you just press the ``Start`` button. To |
1968 | stop profiling and to start viewing the profile data in one easy step, | 1989 | stop profiling and to start viewing the profile data in one easy step, |
1969 | press the 'Profile' button. | 1990 | press the ``Profile`` button. |
1970 | 1991 | ||
1971 | Once you've pressed the profile button, the three panes will fill up | 1992 | Once you've pressed the profile button, the three panes will fill up |
1972 | with profiling data: | 1993 | with profiling data: |
1973 | 1994 | ||
1974 | .. image:: figures/sysprof-copy-to-user.png | 1995 | .. image:: figures/sysprof-copy-to-user.png |
1975 | :align: center | 1996 | :align: center |
1997 | :width: 70% | ||
1976 | 1998 | ||
1977 | The left pane shows a list of functions and processes. Selecting one of | 1999 | The left pane shows a list of functions and processes. Selecting one of |
1978 | those expands that function in the right pane, showing all its callees. | 2000 | those expands that function in the right pane, showing all its callees. |
1979 | Note that this caller-oriented display is essentially the inverse of | 2001 | Note that this caller-oriented display is essentially the inverse of |
1980 | perf's default callee-oriented callchain display. | 2002 | perf's default callee-oriented call chain display. |
1981 | 2003 | ||
1982 | In the screenshot above, we're focusing on ``__copy_to_user_ll()`` and | 2004 | In the screenshot above, we're focusing on ``__copy_to_user_ll()`` and |
1983 | looking up the callchain we can see that one of the callers of | 2005 | looking up the call chain we can see that one of the callers of |
1984 | ``__copy_to_user_ll`` is sys_read() and the complete callpath between them. | 2006 | ``__copy_to_user_ll`` is ``sys_read()`` and the complete call path between them. |
1985 | Notice that this is essentially a portion of the same information we saw | 2007 | Notice that this is essentially a portion of the same information we saw |
1986 | in the perf display shown in the perf section of this page. | 2008 | in the perf display shown in the perf section of this page. |
1987 | 2009 | ||
1988 | .. image:: figures/sysprof-copy-from-user.png | 2010 | .. image:: figures/sysprof-copy-from-user.png |
1989 | :align: center | 2011 | :align: center |
2012 | :width: 70% | ||
1990 | 2013 | ||
1991 | Similarly, the above is a snapshot of the Sysprof display of a | 2014 | Similarly, the above is a snapshot of the Sysprof display of a |
1992 | copy-from-user callchain. | 2015 | ``copy-from-user`` call chain. |
1993 | 2016 | ||
1994 | Finally, looking at the third Sysprof pane in the lower left, we can see | 2017 | Finally, looking at the third Sysprof pane in the lower left, we can see |
1995 | a list of all the callers of a particular function selected in the top | 2018 | a list of all the callers of a particular function selected in the top |
@@ -1998,24 +2021,24 @@ left pane. In this case, the lower pane is showing all the callers of | |||
1998 | 2021 | ||
1999 | .. image:: figures/sysprof-callers.png | 2022 | .. image:: figures/sysprof-callers.png |
2000 | :align: center | 2023 | :align: center |
2024 | :width: 70% | ||
2001 | 2025 | ||
2002 | Double-clicking on one of those functions will in turn change the focus | 2026 | Double-clicking on one of those functions will in turn change the focus |
2003 | to the selected function, and so on. | 2027 | to the selected function, and so on. |
2004 | 2028 | ||
2005 | .. admonition:: Tying it Together | 2029 | .. admonition:: Tying it Together |
2006 | 2030 | ||
2007 | If you like sysprof's 'caller-oriented' display, you may be able to | 2031 | If you like Sysprof's ``caller-oriented`` display, you may be able to |
2008 | approximate it in other tools as well. For example, 'perf report' has | 2032 | approximate it in other tools as well. For example, ``perf report`` has |
2009 | the -g (--call-graph) option that you can experiment with; one of the | 2033 | the ``-g`` (``--call-graph``) option that you can experiment with; one of the |
2010 | options is 'caller' for an inverted caller-based callgraph display. | 2034 | options is ``caller`` for an inverted caller-based call graph display. |
2011 | 2035 | ||
2012 | Sysprof Documentation | 2036 | Sysprof Documentation |
2013 | --------------------- | 2037 | --------------------- |
2014 | 2038 | ||
2015 | There doesn't seem to be any documentation for Sysprof, but maybe that's | 2039 | There doesn't seem to be any documentation for Sysprof, but maybe that's |
2016 | because it's pretty self-explanatory. The Sysprof website, however, is | 2040 | because it's pretty self-explanatory. The Sysprof website, however, is here: |
2017 | here: `Sysprof, System-wide Performance Profiler for | 2041 | `Sysprof, System-wide Performance Profiler for Linux <http://sysprof.com/>`__ |
2018 | Linux <http://sysprof.com/>`__ | ||
2019 | 2042 | ||
2020 | LTTng (Linux Trace Toolkit, next generation) | 2043 | LTTng (Linux Trace Toolkit, next generation) |
2021 | ============================================ | 2044 | ============================================ |
@@ -2025,20 +2048,20 @@ LTTng Setup | |||
2025 | 2048 | ||
2026 | For this section, we'll assume you've already performed the basic setup | 2049 | For this section, we'll assume you've already performed the basic setup |
2027 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. | 2050 | outlined in the ":ref:`profile-manual/intro:General Setup`" section. |
2028 | LTTng is run on the target system by ssh'ing to it. | 2051 | LTTng is run on the target system by connecting to it through SSH. |
2029 | 2052 | ||
2030 | Collecting and Viewing Traces | 2053 | Collecting and Viewing Traces |
2031 | ----------------------------- | 2054 | ----------------------------- |
2032 | 2055 | ||
2033 | Once you've applied the above commits and built and booted your image | 2056 | Once you've applied the above commits and built and booted your image |
2034 | (you need to build the core-image-sato-sdk image or use one of the other | 2057 | (you need to build the ``core-image-sato-sdk`` image or use one of the other |
2035 | methods described in the ":ref:`profile-manual/intro:General Setup`" section), you're ready to start | 2058 | methods described in the ":ref:`profile-manual/intro:General Setup`" section), you're ready to start |
2036 | tracing. | 2059 | tracing. |
2037 | 2060 | ||
2038 | Collecting and viewing a trace on the target (inside a shell) | 2061 | Collecting and viewing a trace on the target (inside a shell) |
2039 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ | 2062 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ |
2040 | 2063 | ||
2041 | First, from the host, ssh to the target: :: | 2064 | First, from the host, connect to the target through SSH:: |
2042 | 2065 | ||
2043 | $ ssh -l root 192.168.1.47 | 2066 | $ ssh -l root 192.168.1.47 |
2044 | The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. | 2067 | The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. |
@@ -2047,30 +2070,30 @@ First, from the host, ssh to the target: :: | |||
2047 | Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts. | 2070 | Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts. |
2048 | root@192.168.1.47's password: | 2071 | root@192.168.1.47's password: |
2049 | 2072 | ||
2050 | Once on the target, use these steps to create a trace: :: | 2073 | Once on the target, use these steps to create a trace:: |
2051 | 2074 | ||
2052 | root@crownbay:~# lttng create | 2075 | root@crownbay:~# lttng create |
2053 | Spawning a session daemon | 2076 | Spawning a session daemon |
2054 | Session auto-20121015-232120 created. | 2077 | Session auto-20121015-232120 created. |
2055 | Traces will be written in /home/root/lttng-traces/auto-20121015-232120 | 2078 | Traces will be written in /home/root/lttng-traces/auto-20121015-232120 |
2056 | 2079 | ||
2057 | Enable the events you want to trace (in this case all kernel events): :: | 2080 | Enable the events you want to trace (in this case all kernel events):: |
2058 | 2081 | ||
2059 | root@crownbay:~# lttng enable-event --kernel --all | 2082 | root@crownbay:~# lttng enable-event --kernel --all |
2060 | All kernel events are enabled in channel channel0 | 2083 | All kernel events are enabled in channel channel0 |
2061 | 2084 | ||
2062 | Start the trace: :: | 2085 | Start the trace:: |
2063 | 2086 | ||
2064 | root@crownbay:~# lttng start | 2087 | root@crownbay:~# lttng start |
2065 | Tracing started for session auto-20121015-232120 | 2088 | Tracing started for session auto-20121015-232120 |
2066 | 2089 | ||
2067 | And then stop the trace after awhile or after running a particular workload that | 2090 | And then stop the trace after awhile or after running a particular workload that |
2068 | you want to trace: :: | 2091 | you want to trace:: |
2069 | 2092 | ||
2070 | root@crownbay:~# lttng stop | 2093 | root@crownbay:~# lttng stop |
2071 | Tracing stopped for session auto-20121015-232120 | 2094 | Tracing stopped for session auto-20121015-232120 |
2072 | 2095 | ||
2073 | You can now view the trace in text form on the target: :: | 2096 | You can now view the trace in text form on the target:: |
2074 | 2097 | ||
2075 | root@crownbay:~# lttng view | 2098 | root@crownbay:~# lttng view |
2076 | [23:21:56.989270399] (+?.?????????) sys_geteuid: { 1 }, { } | 2099 | [23:21:56.989270399] (+?.?????????) sys_geteuid: { 1 }, { } |
@@ -2115,42 +2138,42 @@ You can now view the trace in text form on the target: :: | |||
2115 | . | 2138 | . |
2116 | 2139 | ||
2117 | You can now safely destroy the trace | 2140 | You can now safely destroy the trace |
2118 | session (note that this doesn't delete the trace - it's still there in | 2141 | session (note that this doesn't delete the trace --- it's still there in |
2119 | ~/lttng-traces): :: | 2142 | ``~/lttng-traces``):: |
2120 | 2143 | ||
2121 | root@crownbay:~# lttng destroy | 2144 | root@crownbay:~# lttng destroy |
2122 | Session auto-20121015-232120 destroyed at /home/root | 2145 | Session auto-20121015-232120 destroyed at /home/root |
2123 | 2146 | ||
2124 | Note that the trace is saved in a directory of the same name as returned by | 2147 | Note that the trace is saved in a directory of the same name as returned by |
2125 | 'lttng create', under the ~/lttng-traces directory (note that you can change this by | 2148 | ``lttng create``, under the ``~/lttng-traces`` directory (note that you can change this by |
2126 | supplying your own name to 'lttng create'): :: | 2149 | supplying your own name to ``lttng create``):: |
2127 | 2150 | ||
2128 | root@crownbay:~# ls -al ~/lttng-traces | 2151 | root@crownbay:~# ls -al ~/lttng-traces |
2129 | drwxrwx--- 3 root root 1024 Oct 15 23:21 . | 2152 | drwxrwx--- 3 root root 1024 Oct 15 23:21 . |
2130 | drwxr-xr-x 5 root root 1024 Oct 15 23:57 .. | 2153 | drwxr-xr-x 5 root root 1024 Oct 15 23:57 .. |
2131 | drwxrwx--- 3 root root 1024 Oct 15 23:21 auto-20121015-232120 | 2154 | drwxrwx--- 3 root root 1024 Oct 15 23:21 auto-20121015-232120 |
2132 | 2155 | ||
2133 | Collecting and viewing a userspace trace on the target (inside a shell) | 2156 | Collecting and viewing a user space trace on the target (inside a shell) |
2134 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ | 2157 | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ |
2135 | 2158 | ||
2136 | For LTTng userspace tracing, you need to have a properly instrumented | 2159 | For LTTng user space tracing, you need to have a properly instrumented |
2137 | userspace program. For this example, we'll use the 'hello' test program | 2160 | user space program. For this example, we'll use the ``hello`` test program |
2138 | generated by the lttng-ust build. | 2161 | generated by the ``lttng-ust`` build. |
2139 | 2162 | ||
2140 | The 'hello' test program isn't installed on the rootfs by the lttng-ust | 2163 | The ``hello`` test program isn't installed on the root filesystem by the ``lttng-ust`` |
2141 | build, so we need to copy it over manually. First cd into the build | 2164 | build, so we need to copy it over manually. First ``cd`` into the build |
2142 | directory that contains the hello executable: :: | 2165 | directory that contains the ``hello`` executable:: |
2143 | 2166 | ||
2144 | $ cd build/tmp/work/core2_32-poky-linux/lttng-ust/2.0.5-r0/git/tests/hello/.libs | 2167 | $ cd build/tmp/work/core2_32-poky-linux/lttng-ust/2.0.5-r0/git/tests/hello/.libs |
2145 | 2168 | ||
2146 | Copy that over to the target machine: :: | 2169 | Copy that over to the target machine:: |
2147 | 2170 | ||
2148 | $ scp hello root@192.168.1.20: | 2171 | $ scp hello root@192.168.1.20: |
2149 | 2172 | ||
2150 | You now have the instrumented lttng 'hello world' test program on the | 2173 | You now have the instrumented LTTng "hello world" test program on the |
2151 | target, ready to test. | 2174 | target, ready to test. |
2152 | 2175 | ||
2153 | First, from the host, ssh to the target: :: | 2176 | First, from the host, connect to the target through SSH:: |
2154 | 2177 | ||
2155 | $ ssh -l root 192.168.1.47 | 2178 | $ ssh -l root 192.168.1.47 |
2156 | The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. | 2179 | The authenticity of host '192.168.1.47 (192.168.1.47)' can't be established. |
@@ -2159,35 +2182,35 @@ First, from the host, ssh to the target: :: | |||
2159 | Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts. | 2182 | Warning: Permanently added '192.168.1.47' (RSA) to the list of known hosts. |
2160 | root@192.168.1.47's password: | 2183 | root@192.168.1.47's password: |
2161 | 2184 | ||
2162 | Once on the target, use these steps to create a trace: :: | 2185 | Once on the target, use these steps to create a trace:: |
2163 | 2186 | ||
2164 | root@crownbay:~# lttng create | 2187 | root@crownbay:~# lttng create |
2165 | Session auto-20190303-021943 created. | 2188 | Session auto-20190303-021943 created. |
2166 | Traces will be written in /home/root/lttng-traces/auto-20190303-021943 | 2189 | Traces will be written in /home/root/lttng-traces/auto-20190303-021943 |
2167 | 2190 | ||
2168 | Enable the events you want to trace (in this case all userspace events): :: | 2191 | Enable the events you want to trace (in this case all user space events):: |
2169 | 2192 | ||
2170 | root@crownbay:~# lttng enable-event --userspace --all | 2193 | root@crownbay:~# lttng enable-event --userspace --all |
2171 | All UST events are enabled in channel channel0 | 2194 | All UST events are enabled in channel channel0 |
2172 | 2195 | ||
2173 | Start the trace: :: | 2196 | Start the trace:: |
2174 | 2197 | ||
2175 | root@crownbay:~# lttng start | 2198 | root@crownbay:~# lttng start |
2176 | Tracing started for session auto-20190303-021943 | 2199 | Tracing started for session auto-20190303-021943 |
2177 | 2200 | ||
2178 | Run the instrumented hello world program: :: | 2201 | Run the instrumented "hello world" program:: |
2179 | 2202 | ||
2180 | root@crownbay:~# ./hello | 2203 | root@crownbay:~# ./hello |
2181 | Hello, World! | 2204 | Hello, World! |
2182 | Tracing... done. | 2205 | Tracing... done. |
2183 | 2206 | ||
2184 | And then stop the trace after awhile or after running a particular workload | 2207 | And then stop the trace after awhile or after running a particular workload |
2185 | that you want to trace: :: | 2208 | that you want to trace:: |
2186 | 2209 | ||
2187 | root@crownbay:~# lttng stop | 2210 | root@crownbay:~# lttng stop |
2188 | Tracing stopped for session auto-20190303-021943 | 2211 | Tracing stopped for session auto-20190303-021943 |
2189 | 2212 | ||
2190 | You can now view the trace in text form on the target: :: | 2213 | You can now view the trace in text form on the target:: |
2191 | 2214 | ||
2192 | root@crownbay:~# lttng view | 2215 | root@crownbay:~# lttng view |
2193 | [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 } | 2216 | [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 } |
@@ -2199,7 +2222,7 @@ You can now view the trace in text form on the target: :: | |||
2199 | . | 2222 | . |
2200 | 2223 | ||
2201 | You can now safely destroy the trace session (note that this doesn't delete the | 2224 | You can now safely destroy the trace session (note that this doesn't delete the |
2202 | trace - it's still there in ~/lttng-traces): :: | 2225 | trace --- it's still there in ``~/lttng-traces``):: |
2203 | 2226 | ||
2204 | root@crownbay:~# lttng destroy | 2227 | root@crownbay:~# lttng destroy |
2205 | Session auto-20190303-021943 destroyed at /home/root | 2228 | Session auto-20190303-021943 destroyed at /home/root |
@@ -2237,27 +2260,27 @@ the entire blktrace and blkparse pipeline on the target, or you can run | |||
2237 | blktrace in 'listen' mode on the target and have blktrace and blkparse | 2260 | blktrace in 'listen' mode on the target and have blktrace and blkparse |
2238 | collect and analyze the data on the host (see the | 2261 | collect and analyze the data on the host (see the |
2239 | ":ref:`profile-manual/usage:Using blktrace Remotely`" section | 2262 | ":ref:`profile-manual/usage:Using blktrace Remotely`" section |
2240 | below). For the rest of this section we assume you've ssh'ed to the host and | 2263 | below). For the rest of this section we assume you've to the host through SSH |
2241 | will be running blkrace on the target. | 2264 | and will be running blktrace on the target. |
2242 | 2265 | ||
2243 | Basic blktrace Usage | 2266 | Basic blktrace Usage |
2244 | -------------------- | 2267 | -------------------- |
2245 | 2268 | ||
2246 | To record a trace, simply run the 'blktrace' command, giving it the name | 2269 | To record a trace, just run the ``blktrace`` command, giving it the name |
2247 | of the block device you want to trace activity on: :: | 2270 | of the block device you want to trace activity on:: |
2248 | 2271 | ||
2249 | root@crownbay:~# blktrace /dev/sdc | 2272 | root@crownbay:~# blktrace /dev/sdc |
2250 | 2273 | ||
2251 | In another shell, execute a workload you want to trace. :: | 2274 | In another shell, execute a workload you want to trace:: |
2252 | 2275 | ||
2253 | 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 | 2276 | root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2; sync |
2254 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 2277 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
2255 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA | 2278 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA |
2256 | 2279 | ||
2257 | Press Ctrl-C in the blktrace shell to stop the trace. It | 2280 | Press ``Ctrl-C`` in the blktrace shell to stop the trace. It |
2258 | will display how many events were logged, along with the per-cpu file | 2281 | will display how many events were logged, along with the per-cpu file |
2259 | sizes (blktrace records traces in per-cpu kernel buffers and simply | 2282 | sizes (blktrace records traces in per-cpu kernel buffers and just |
2260 | dumps them to userspace for blkparse to merge and sort later). :: | 2283 | dumps them to user space for blkparse to merge and sort later):: |
2261 | 2284 | ||
2262 | ^C=== sdc === | 2285 | ^C=== sdc === |
2263 | CPU 0: 7082 events, 332 KiB data | 2286 | CPU 0: 7082 events, 332 KiB data |
@@ -2265,7 +2288,7 @@ dumps them to userspace for blkparse to merge and sort later). :: | |||
2265 | Total: 8660 events (dropped 0), 406 KiB data | 2288 | Total: 8660 events (dropped 0), 406 KiB data |
2266 | 2289 | ||
2267 | If you examine the files saved to disk, you see multiple files, one per CPU and | 2290 | If you examine the files saved to disk, you see multiple files, one per CPU and |
2268 | with the device name as the first part of the filename: :: | 2291 | with the device name as the first part of the filename:: |
2269 | 2292 | ||
2270 | root@crownbay:~# ls -al | 2293 | root@crownbay:~# ls -al |
2271 | drwxr-xr-x 6 root root 1024 Oct 27 22:39 . | 2294 | drwxr-xr-x 6 root root 1024 Oct 27 22:39 . |
@@ -2273,9 +2296,9 @@ with the device name as the first part of the filename: :: | |||
2273 | -rw-r--r-- 1 root root 339938 Oct 27 22:40 sdc.blktrace.0 | 2296 | -rw-r--r-- 1 root root 339938 Oct 27 22:40 sdc.blktrace.0 |
2274 | -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1 | 2297 | -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1 |
2275 | 2298 | ||
2276 | To view the trace events, simply invoke 'blkparse' in the directory | 2299 | To view the trace events, just call ``blkparse`` in the directory |
2277 | containing the trace files, giving it the device name that forms the | 2300 | containing the trace files, giving it the device name that forms the |
2278 | first part of the filenames: :: | 2301 | first part of the filenames:: |
2279 | 2302 | ||
2280 | root@crownbay:~# blkparse sdc | 2303 | root@crownbay:~# blkparse sdc |
2281 | 2304 | ||
@@ -2332,29 +2355,29 @@ first part of the filenames: :: | |||
2332 | 8,32 1 0 58.516990819 0 m N cfq3551 put_queue | 2355 | 8,32 1 0 58.516990819 0 m N cfq3551 put_queue |
2333 | 2356 | ||
2334 | CPU0 (sdc): | 2357 | CPU0 (sdc): |
2335 | Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB | 2358 | Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB |
2336 | Read Dispatches: 0, 0KiB Write Dispatches: 485, 40,484KiB | 2359 | Read Dispatches: 0, 0KiB Write Dispatches: 485, 40,484KiB |
2337 | Reads Requeued: 0 Writes Requeued: 0 | 2360 | Reads Requeued: 0 Writes Requeued: 0 |
2338 | Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB | 2361 | Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB |
2339 | Read Merges: 0, 0KiB Write Merges: 13, 160KiB | 2362 | Read Merges: 0, 0KiB Write Merges: 13, 160KiB |
2340 | Read depth: 0 Write depth: 2 | 2363 | Read depth: 0 Write depth: 2 |
2341 | IO unplugs: 23 Timer unplugs: 0 | 2364 | IO unplugs: 23 Timer unplugs: 0 |
2342 | CPU1 (sdc): | 2365 | CPU1 (sdc): |
2343 | Reads Queued: 0, 0KiB Writes Queued: 249, 15,800KiB | 2366 | Reads Queued: 0, 0KiB Writes Queued: 249, 15,800KiB |
2344 | Read Dispatches: 0, 0KiB Write Dispatches: 42, 1,600KiB | 2367 | Read Dispatches: 0, 0KiB Write Dispatches: 42, 1,600KiB |
2345 | Reads Requeued: 0 Writes Requeued: 0 | 2368 | Reads Requeued: 0 Writes Requeued: 0 |
2346 | Reads Completed: 0, 0KiB Writes Completed: 16, 1,084KiB | 2369 | Reads Completed: 0, 0KiB Writes Completed: 16, 1,084KiB |
2347 | Read Merges: 0, 0KiB Write Merges: 40, 276KiB | 2370 | Read Merges: 0, 0KiB Write Merges: 40, 276KiB |
2348 | Read depth: 0 Write depth: 2 | 2371 | Read depth: 0 Write depth: 2 |
2349 | IO unplugs: 30 Timer unplugs: 1 | 2372 | IO unplugs: 30 Timer unplugs: 1 |
2350 | 2373 | ||
2351 | Total (sdc): | 2374 | Total (sdc): |
2352 | Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB | 2375 | Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB |
2353 | Read Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB | 2376 | Read Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB |
2354 | Reads Requeued: 0 Writes Requeued: 0 | 2377 | Reads Requeued: 0 Writes Requeued: 0 |
2355 | Reads Completed: 0, 0KiB Writes Completed: 527, 42,084KiB | 2378 | Reads Completed: 0, 0KiB Writes Completed: 527, 42,084KiB |
2356 | Read Merges: 0, 0KiB Write Merges: 53, 436KiB | 2379 | Read Merges: 0, 0KiB Write Merges: 53, 436KiB |
2357 | IO unplugs: 53 Timer unplugs: 1 | 2380 | IO unplugs: 53 Timer unplugs: 1 |
2358 | 2381 | ||
2359 | Throughput (R/W): 0KiB/s / 719KiB/s | 2382 | Throughput (R/W): 0KiB/s / 719KiB/s |
2360 | Events (sdc): 6,592 entries | 2383 | Events (sdc): 6,592 entries |
@@ -2365,15 +2388,15 @@ first part of the filenames: :: | |||
2365 | The report shows each event that was | 2388 | The report shows each event that was |
2366 | found in the blktrace data, along with a summary of the overall block | 2389 | found in the blktrace data, along with a summary of the overall block |
2367 | I/O traffic during the run. You can look at the | 2390 | I/O traffic during the run. You can look at the |
2368 | `blkparse <https://linux.die.net/man/1/blkparse>`__ manpage to learn the | 2391 | `blkparse <https://linux.die.net/man/1/blkparse>`__ manual page to learn the |
2369 | meaning of each field displayed in the trace listing. | 2392 | meaning of each field displayed in the trace listing. |
2370 | 2393 | ||
2371 | Live Mode | 2394 | Live Mode |
2372 | ~~~~~~~~~ | 2395 | ~~~~~~~~~ |
2373 | 2396 | ||
2374 | blktrace and blkparse are designed from the ground up to be able to | 2397 | blktrace and blkparse are designed from the ground up to be able to |
2375 | operate together in a 'pipe mode' where the stdout of blktrace can be | 2398 | operate together in a "pipe mode" where the standard output of blktrace can be |
2376 | fed directly into the stdin of blkparse: :: | 2399 | fed directly into the standard input of blkparse:: |
2377 | 2400 | ||
2378 | root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i - | 2401 | root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i - |
2379 | 2402 | ||
@@ -2386,7 +2409,7 @@ identify and capture conditions of interest. | |||
2386 | 2409 | ||
2387 | There's actually another blktrace command that implements the above | 2410 | There's actually another blktrace command that implements the above |
2388 | pipeline as a single command, so the user doesn't have to bother typing | 2411 | pipeline as a single command, so the user doesn't have to bother typing |
2389 | in the above command sequence: :: | 2412 | in the above command sequence:: |
2390 | 2413 | ||
2391 | root@crownbay:~# btrace /dev/sdc | 2414 | root@crownbay:~# btrace /dev/sdc |
2392 | 2415 | ||
@@ -2400,39 +2423,40 @@ tracer writes to, blktrace provides a way to trace without perturbing | |||
2400 | the traced device at all by providing native support for sending all | 2423 | the traced device at all by providing native support for sending all |
2401 | trace data over the network. | 2424 | trace data over the network. |
2402 | 2425 | ||
2403 | To have blktrace operate in this mode, start blktrace on the target | 2426 | To have blktrace operate in this mode, start blktrace in server mode on the |
2404 | system being traced with the -l option, along with the device to trace: :: | 2427 | host system, which is going to store the captured data:: |
2405 | 2428 | ||
2406 | root@crownbay:~# blktrace -l /dev/sdc | 2429 | $ blktrace -l |
2407 | server: waiting for connections... | 2430 | server: waiting for connections... |
2408 | 2431 | ||
2409 | On the host system, use the -h option to connect to the target system, | 2432 | On the target system that is going to be traced, start blktrace in client |
2410 | also passing it the device to trace: :: | 2433 | mode with the -h option to connect to the host system, also passing it the |
2434 | device to trace:: | ||
2411 | 2435 | ||
2412 | $ blktrace -d /dev/sdc -h 192.168.1.43 | 2436 | root@crownbay:~# blktrace -d /dev/sdc -h 192.168.1.43 |
2413 | blktrace: connecting to 192.168.1.43 | 2437 | blktrace: connecting to 192.168.1.43 |
2414 | blktrace: connected! | 2438 | blktrace: connected! |
2415 | 2439 | ||
2416 | On the target system, you should see this: :: | 2440 | On the host system, you should see this:: |
2417 | 2441 | ||
2418 | server: connection from 192.168.1.43 | 2442 | server: connection from 192.168.1.43 |
2419 | 2443 | ||
2420 | In another shell, execute a workload you want to trace. :: | 2444 | In another shell, execute a workload you want to trace:: |
2421 | 2445 | ||
2422 | 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 | 2446 | root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget &YOCTO_DL_URL;/mirror/sources/linux-2.6.19.2.tar.bz2; sync |
2423 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) | 2447 | Connecting to downloads.yoctoproject.org (140.211.169.59:80) |
2424 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA | 2448 | linux-2.6.19.2.tar.b 100% \|*******************************\| 41727k 0:00:00 ETA |
2425 | 2449 | ||
2426 | When it's done, do a Ctrl-C on the host system to stop the | 2450 | When it's done, do a ``Ctrl-C`` on the target system to stop the |
2427 | trace: :: | 2451 | trace:: |
2428 | 2452 | ||
2429 | ^C=== sdc === | 2453 | ^C=== sdc === |
2430 | CPU 0: 7691 events, 361 KiB data | 2454 | CPU 0: 7691 events, 361 KiB data |
2431 | CPU 1: 4109 events, 193 KiB data | 2455 | CPU 1: 4109 events, 193 KiB data |
2432 | Total: 11800 events (dropped 0), 554 KiB data | 2456 | Total: 11800 events (dropped 0), 554 KiB data |
2433 | 2457 | ||
2434 | On the target system, you should also see a trace summary for the trace | 2458 | On the host system, you should also see a trace summary for the trace |
2435 | just ended: :: | 2459 | just ended:: |
2436 | 2460 | ||
2437 | server: end of run for 192.168.1.43:sdc | 2461 | server: end of run for 192.168.1.43:sdc |
2438 | === sdc === | 2462 | === sdc === |
@@ -2441,20 +2465,20 @@ just ended: :: | |||
2441 | Total: 11800 events (dropped 0), 554 KiB data | 2465 | Total: 11800 events (dropped 0), 554 KiB data |
2442 | 2466 | ||
2443 | The blktrace instance on the host will | 2467 | The blktrace instance on the host will |
2444 | save the target output inside a hostname-timestamp directory: :: | 2468 | save the target output inside a ``<hostname>-<timestamp>`` directory:: |
2445 | 2469 | ||
2446 | $ ls -al | 2470 | $ ls -al |
2447 | drwxr-xr-x 10 root root 1024 Oct 28 02:40 . | 2471 | drwxr-xr-x 10 root root 1024 Oct 28 02:40 . |
2448 | drwxr-sr-x 4 root root 1024 Oct 26 18:24 .. | 2472 | drwxr-sr-x 4 root root 1024 Oct 26 18:24 .. |
2449 | drwxr-xr-x 2 root root 1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56 | 2473 | drwxr-xr-x 2 root root 1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56 |
2450 | 2474 | ||
2451 | cd into that directory to see the output files: :: | 2475 | ``cd`` into that directory to see the output files:: |
2452 | 2476 | ||
2453 | $ ls -l | 2477 | $ ls -l |
2454 | -rw-r--r-- 1 root root 369193 Oct 28 02:44 sdc.blktrace.0 | 2478 | -rw-r--r-- 1 root root 369193 Oct 28 02:44 sdc.blktrace.0 |
2455 | -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1 | 2479 | -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1 |
2456 | 2480 | ||
2457 | And run blkparse on the host system using the device name: :: | 2481 | And run blkparse on the host system using the device name:: |
2458 | 2482 | ||
2459 | $ blkparse sdc | 2483 | $ blkparse sdc |
2460 | 2484 | ||
@@ -2476,29 +2500,29 @@ And run blkparse on the host system using the device name: :: | |||
2476 | 8,32 1 0 177.266696560 0 m N cfq1267 put_queue | 2500 | 8,32 1 0 177.266696560 0 m N cfq1267 put_queue |
2477 | 2501 | ||
2478 | CPU0 (sdc): | 2502 | CPU0 (sdc): |
2479 | Reads Queued: 0, 0KiB Writes Queued: 270, 21,708KiB | 2503 | Reads Queued: 0, 0KiB Writes Queued: 270, 21,708KiB |
2480 | Read Dispatches: 59, 2,628KiB Write Dispatches: 495, 39,964KiB | 2504 | Read Dispatches: 59, 2,628KiB Write Dispatches: 495, 39,964KiB |
2481 | Reads Requeued: 0 Writes Requeued: 0 | 2505 | Reads Requeued: 0 Writes Requeued: 0 |
2482 | Reads Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB | 2506 | Reads Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB |
2483 | Read Merges: 0, 0KiB Write Merges: 9, 344KiB | 2507 | Read Merges: 0, 0KiB Write Merges: 9, 344KiB |
2484 | Read depth: 2 Write depth: 2 | 2508 | Read depth: 2 Write depth: 2 |
2485 | IO unplugs: 20 Timer unplugs: 1 | 2509 | IO unplugs: 20 Timer unplugs: 1 |
2486 | CPU1 (sdc): | 2510 | CPU1 (sdc): |
2487 | Reads Queued: 688, 2,752KiB Writes Queued: 381, 20,652KiB | 2511 | Reads Queued: 688, 2,752KiB Writes Queued: 381, 20,652KiB |
2488 | Read Dispatches: 31, 124KiB Write Dispatches: 59, 2,396KiB | 2512 | Read Dispatches: 31, 124KiB Write Dispatches: 59, 2,396KiB |
2489 | Reads Requeued: 0 Writes Requeued: 0 | 2513 | Reads Requeued: 0 Writes Requeued: 0 |
2490 | Reads Completed: 0, 0KiB Writes Completed: 11, 764KiB | 2514 | Reads Completed: 0, 0KiB Writes Completed: 11, 764KiB |
2491 | Read Merges: 598, 2,392KiB Write Merges: 88, 448KiB | 2515 | Read Merges: 598, 2,392KiB Write Merges: 88, 448KiB |
2492 | Read depth: 2 Write depth: 2 | 2516 | Read depth: 2 Write depth: 2 |
2493 | IO unplugs: 52 Timer unplugs: 0 | 2517 | IO unplugs: 52 Timer unplugs: 0 |
2494 | 2518 | ||
2495 | Total (sdc): | 2519 | Total (sdc): |
2496 | Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB | 2520 | Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB |
2497 | Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB | 2521 | Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB |
2498 | Reads Requeued: 0 Writes Requeued: 0 | 2522 | Reads Requeued: 0 Writes Requeued: 0 |
2499 | Reads Completed: 90, 2,752KiB Writes Completed: 554, 42,360KiB | 2523 | Reads Completed: 90, 2,752KiB Writes Completed: 554, 42,360KiB |
2500 | Read Merges: 598, 2,392KiB Write Merges: 97, 792KiB | 2524 | Read Merges: 598, 2,392KiB Write Merges: 97, 792KiB |
2501 | IO unplugs: 72 Timer unplugs: 1 | 2525 | IO unplugs: 72 Timer unplugs: 1 |
2502 | 2526 | ||
2503 | Throughput (R/W): 15KiB/s / 238KiB/s | 2527 | Throughput (R/W): 15KiB/s / 238KiB/s |
2504 | Events (sdc): 9,301 entries | 2528 | Events (sdc): 9,301 entries |
@@ -2513,29 +2537,29 @@ Tracing Block I/O via 'ftrace' | |||
2513 | It's also possible to trace block I/O using only | 2537 | It's also possible to trace block I/O using only |
2514 | :ref:`profile-manual/usage:The 'trace events' Subsystem`, which | 2538 | :ref:`profile-manual/usage:The 'trace events' Subsystem`, which |
2515 | can be useful for casual tracing if you don't want to bother dealing with the | 2539 | can be useful for casual tracing if you don't want to bother dealing with the |
2516 | userspace tools. | 2540 | user space tools. |
2517 | 2541 | ||
2518 | To enable tracing for a given device, use /sys/block/xxx/trace/enable, | 2542 | To enable tracing for a given device, use ``/sys/block/xxx/trace/enable``, |
2519 | where xxx is the device name. This for example enables tracing for | 2543 | where ``xxx`` is the device name. This for example enables tracing for |
2520 | /dev/sdc: :: | 2544 | ``/dev/sdc``:: |
2521 | 2545 | ||
2522 | root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable | 2546 | root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable |
2523 | 2547 | ||
2524 | Once you've selected the device(s) you want | 2548 | Once you've selected the device(s) you want |
2525 | to trace, selecting the 'blk' tracer will turn the blk tracer on: :: | 2549 | to trace, selecting the ``blk`` tracer will turn the blk tracer on:: |
2526 | 2550 | ||
2527 | root@crownbay:/sys/kernel/debug/tracing# cat available_tracers | 2551 | root@crownbay:/sys/kernel/debug/tracing# cat available_tracers |
2528 | blk function_graph function nop | 2552 | blk function_graph function nop |
2529 | 2553 | ||
2530 | root@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer | 2554 | root@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer |
2531 | 2555 | ||
2532 | Execute the workload you're interested in: :: | 2556 | Execute the workload you're interested in:: |
2533 | 2557 | ||
2534 | root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt | 2558 | root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt |
2535 | 2559 | ||
2536 | And look at the output (note here that we're using 'trace_pipe' instead of | 2560 | And look at the output (note here that we're using ``trace_pipe`` instead of |
2537 | trace to capture this trace - this allows us to wait around on the pipe | 2561 | trace to capture this trace --- this allows us to wait around on the pipe |
2538 | for data to appear): :: | 2562 | for data to appear):: |
2539 | 2563 | ||
2540 | root@crownbay:/sys/kernel/debug/tracing# cat trace_pipe | 2564 | root@crownbay:/sys/kernel/debug/tracing# cat trace_pipe |
2541 | cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat] | 2565 | cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat] |
@@ -2554,14 +2578,14 @@ for data to appear): :: | |||
2554 | cat-3587 [001] d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1 | 2578 | cat-3587 [001] d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1 |
2555 | cat-3587 [001] d..2 3023.276500: 8,32 D R 1699848 + 8 [cat] | 2579 | cat-3587 [001] d..2 3023.276500: 8,32 D R 1699848 + 8 [cat] |
2556 | 2580 | ||
2557 | And this turns off tracing for the specified device: :: | 2581 | And this turns off tracing for the specified device:: |
2558 | 2582 | ||
2559 | root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable | 2583 | root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable |
2560 | 2584 | ||
2561 | blktrace Documentation | 2585 | blktrace Documentation |
2562 | ---------------------- | 2586 | ---------------------- |
2563 | 2587 | ||
2564 | Online versions of the man pages for the commands discussed in this | 2588 | Online versions of the manual pages for the commands discussed in this |
2565 | section can be found here: | 2589 | section can be found here: |
2566 | 2590 | ||
2567 | - https://linux.die.net/man/8/blktrace | 2591 | - https://linux.die.net/man/8/blktrace |
@@ -2570,8 +2594,8 @@ section can be found here: | |||
2570 | 2594 | ||
2571 | - https://linux.die.net/man/8/btrace | 2595 | - https://linux.die.net/man/8/btrace |
2572 | 2596 | ||
2573 | The above manpages, along with manpages for the other blktrace utilities | 2597 | The above manual pages, along with manuals for the other blktrace utilities |
2574 | (btt, blkiomon, etc) can be found in the /doc directory of the blktrace | 2598 | (``btt``, ``blkiomon``, etc) can be found in the ``/doc`` directory of the blktrace |
2575 | tools git repo: :: | 2599 | tools git repository:: |
2576 | 2600 | ||
2577 | $ git clone git://git.kernel.dk/blktrace.git | 2601 | $ git clone git://git.kernel.dk/blktrace.git |