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