Merge ~powersj/cloud-init:docs/analyze into cloud-init:master
- Git
- lp:~powersj/cloud-init
- docs/analyze
- Merge into master
Proposed by
Joshua Powers
Status: | Merged |
---|---|
Approved by: | Chad Smith |
Approved revision: | f2d60b63e8e9702b22342cfc4df6966de5d231fd |
Merge reported by: | Server Team CI bot |
Merged at revision: | not available |
Proposed branch: | ~powersj/cloud-init:docs/analyze |
Merge into: | cloud-init:master |
Diff against target: |
392 lines (+302/-68) 1 file modified
doc/rtd/topics/analyze.rst (+302/-68) |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
Chad Smith | Approve | ||
Server Team CI bot | continuous-integration | Approve | |
Review via email: mp+372651@code.launchpad.net |
Commit message
docs: added output examples to analyze.rst
Description of the change
To post a comment you must log in.
Revision history for this message
Server Team CI bot (server-team-bot) wrote : | # |
review:
Approve
(continuous-integration)
Preview Diff
[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1 | diff --git a/doc/rtd/topics/analyze.rst b/doc/rtd/topics/analyze.rst | |||
2 | index 5cf38bd..709131b 100644 | |||
3 | --- a/doc/rtd/topics/analyze.rst | |||
4 | +++ b/doc/rtd/topics/analyze.rst | |||
5 | @@ -1,84 +1,318 @@ | |||
33 | 1 | ************************* | 1 | .. _analyze: |
34 | 2 | Cloud-init Analyze Module | 2 | |
35 | 3 | ************************* | 3 | Analyze |
36 | 4 | 4 | ******* | |
37 | 5 | Overview | 5 | |
38 | 6 | ======== | 6 | The analyze subcommand was added to cloud-init in order to help analyze |
39 | 7 | The analyze module was added to cloud-init in order to help analyze cloud-init boot time | 7 | cloud-init boot time performance. It is loosely based on systemd-analyze where |
40 | 8 | performance. It is loosely based on systemd-analyze where there are 4 main actions: | 8 | there are four subcommands: |
41 | 9 | show, blame, dump, and boot. | 9 | |
42 | 10 | 10 | - blame | |
43 | 11 | The 'show' action is similar to 'systemd-analyze critical-chain' which prints a list of units, the | 11 | - show |
44 | 12 | time they started and how long they took. For cloud-init, we have four stages, and within each stage | 12 | - dump |
45 | 13 | a number of modules may run depending on configuration. ‘cloudinit-analyze show’ will, for each | 13 | - boot |
19 | 14 | boot, print this information and a summary total time, per boot. | ||
20 | 15 | |||
21 | 16 | The 'blame' action matches 'systemd-analyze blame' where it prints, in descending order, | ||
22 | 17 | the units that took the longest to run. This output is highly useful for examining where cloud-init | ||
23 | 18 | is spending its time during execution. | ||
24 | 19 | |||
25 | 20 | The 'dump' action simply dumps the cloud-init logs that the analyze module is performing | ||
26 | 21 | the analysis on and returns a list of dictionaries that can be consumed for other reporting needs. | ||
27 | 22 | |||
28 | 23 | The 'boot' action prints out kernel related timestamps that are not included in any of the | ||
29 | 24 | cloud-init logs. There are three different timestamps that are presented to the user: | ||
30 | 25 | kernel start, kernel finish boot, and cloud-init start. This was added for additional | ||
31 | 26 | clarity into the boot process that cloud-init does not have control over, to aid in debugging of | ||
32 | 27 | performance issues related to cloudinit startup or tracking regression. | ||
46 | 28 | 14 | ||
47 | 29 | Usage | 15 | Usage |
48 | 30 | ===== | 16 | ===== |
50 | 31 | Using each of the printing formats is as easy as running one of the following bash commands: | 17 | |
51 | 18 | The analyze command requires one of the four subcommands: | ||
52 | 32 | 19 | ||
53 | 33 | .. code-block:: shell-session | 20 | .. code-block:: shell-session |
54 | 34 | 21 | ||
59 | 35 | cloud-init analyze show | 22 | $ cloud-init analyze blame |
60 | 36 | cloud-init analyze blame | 23 | $ cloud-init analyze show |
61 | 37 | cloud-init analyze dump | 24 | $ cloud-init analyze dump |
62 | 38 | cloud-init analyze boot | 25 | $ cloud-init analyze boot |
63 | 26 | |||
64 | 27 | Availability | ||
65 | 28 | ============ | ||
66 | 29 | |||
67 | 30 | The analyze subcommand is generally available across all distributions with the | ||
68 | 31 | exception of Gentoo and FreeBSD. | ||
69 | 32 | |||
70 | 33 | Subcommands | ||
71 | 34 | =========== | ||
72 | 35 | |||
73 | 36 | Blame | ||
74 | 37 | ----- | ||
75 | 38 | |||
76 | 39 | The ``blame`` action matches ``systemd-analyze blame`` where it prints, in | ||
77 | 40 | descending order, the units that took the longest to run. This output is | ||
78 | 41 | highly useful for examining where cloud-init is spending its time during | ||
79 | 42 | execution. | ||
80 | 43 | |||
81 | 44 | .. code-block:: shell-session | ||
82 | 45 | |||
83 | 46 | $ cloud-init analyze blame | ||
84 | 47 | -- Boot Record 01 -- | ||
85 | 48 | 00.80300s (init-network/config-growpart) | ||
86 | 49 | 00.64300s (init-network/config-resizefs) | ||
87 | 50 | 00.62100s (init-network/config-ssh) | ||
88 | 51 | 00.57300s (modules-config/config-grub-dpkg) | ||
89 | 52 | 00.40300s (init-local/search-NoCloud) | ||
90 | 53 | 00.38200s (init-network/config-users-groups) | ||
91 | 54 | 00.19800s (modules-config/config-apt-configure) | ||
92 | 55 | 00.03700s (modules-final/config-keys-to-console) | ||
93 | 56 | 00.02100s (init-network/config-update_etc_hosts) | ||
94 | 57 | 00.02100s (init-network/check-cache) | ||
95 | 58 | 00.00800s (modules-final/config-ssh-authkey-fingerprints) | ||
96 | 59 | 00.00800s (init-network/consume-vendor-data) | ||
97 | 60 | 00.00600s (modules-config/config-timezone) | ||
98 | 61 | 00.00500s (modules-final/config-final-message) | ||
99 | 62 | 00.00400s (init-network/consume-user-data) | ||
100 | 63 | 00.00400s (init-network/config-mounts) | ||
101 | 64 | 00.00400s (init-network/config-disk_setup) | ||
102 | 65 | 00.00400s (init-network/config-bootcmd) | ||
103 | 66 | 00.00400s (init-network/activate-datasource) | ||
104 | 67 | 00.00300s (init-network/config-update_hostname) | ||
105 | 68 | 00.00300s (init-network/config-set_hostname) | ||
106 | 69 | 00.00200s (modules-final/config-snappy) | ||
107 | 70 | 00.00200s (init-network/config-rsyslog) | ||
108 | 71 | 00.00200s (init-network/config-ca-certs) | ||
109 | 72 | 00.00200s (init-local/check-cache) | ||
110 | 73 | 00.00100s (modules-final/config-scripts-vendor) | ||
111 | 74 | 00.00100s (modules-final/config-scripts-per-once) | ||
112 | 75 | 00.00100s (modules-final/config-salt-minion) | ||
113 | 76 | 00.00100s (modules-final/config-rightscale_userdata) | ||
114 | 77 | 00.00100s (modules-final/config-phone-home) | ||
115 | 78 | 00.00100s (modules-final/config-package-update-upgrade-install) | ||
116 | 79 | 00.00100s (modules-final/config-fan) | ||
117 | 80 | 00.00100s (modules-config/config-ubuntu-advantage) | ||
118 | 81 | 00.00100s (modules-config/config-ssh-import-id) | ||
119 | 82 | 00.00100s (modules-config/config-snap) | ||
120 | 83 | 00.00100s (modules-config/config-set-passwords) | ||
121 | 84 | 00.00100s (modules-config/config-runcmd) | ||
122 | 85 | 00.00100s (modules-config/config-locale) | ||
123 | 86 | 00.00100s (modules-config/config-byobu) | ||
124 | 87 | 00.00100s (modules-config/config-apt-pipelining) | ||
125 | 88 | 00.00100s (init-network/config-write-files) | ||
126 | 89 | 00.00100s (init-network/config-seed_random) | ||
127 | 90 | 00.00100s (init-network/config-migrator) | ||
128 | 91 | 00.00000s (modules-final/config-ubuntu-drivers) | ||
129 | 92 | 00.00000s (modules-final/config-scripts-user) | ||
130 | 93 | 00.00000s (modules-final/config-scripts-per-instance) | ||
131 | 94 | 00.00000s (modules-final/config-scripts-per-boot) | ||
132 | 95 | 00.00000s (modules-final/config-puppet) | ||
133 | 96 | 00.00000s (modules-final/config-power-state-change) | ||
134 | 97 | 00.00000s (modules-final/config-mcollective) | ||
135 | 98 | 00.00000s (modules-final/config-lxd) | ||
136 | 99 | 00.00000s (modules-final/config-landscape) | ||
137 | 100 | 00.00000s (modules-final/config-chef) | ||
138 | 101 | 00.00000s (modules-config/config-snap_config) | ||
139 | 102 | 00.00000s (modules-config/config-ntp) | ||
140 | 103 | 00.00000s (modules-config/config-emit_upstart) | ||
141 | 104 | 00.00000s (modules-config/config-disable-ec2-metadata) | ||
142 | 105 | 00.00000s (init-network/setup-datasource) | ||
143 | 106 | |||
144 | 107 | 1 boot records analyzed | ||
145 | 108 | |||
146 | 109 | Show | ||
147 | 110 | ---- | ||
148 | 111 | |||
149 | 112 | The ``show`` action is similar to ``systemd-analyze critical-chain`` which | ||
150 | 113 | prints a list of units, the time they started and how long they took. | ||
151 | 114 | Cloud-init has four stages and within each stage a number of modules may run | ||
152 | 115 | depending on configuration. ``cloudinit-analyze show`` will, for each boot, | ||
153 | 116 | print this information and a summary total time, per boot. | ||
154 | 117 | |||
155 | 118 | The following is an abbreviated example of the show output: | ||
156 | 119 | |||
157 | 120 | .. code-block:: shell-session | ||
158 | 121 | |||
159 | 122 | $ cloud-init analyze show | ||
160 | 123 | -- Boot Record 01 -- | ||
161 | 124 | The total time elapsed since completing an event is printed after the "@" character. | ||
162 | 125 | The time the event takes is printed after the "+" character. | ||
163 | 126 | |||
164 | 127 | Starting stage: init-local | ||
165 | 128 | |``->no cache found @00.01700s +00.00200s | ||
166 | 129 | |`->found local data from DataSourceNoCloud @00.11000s +00.40300s | ||
167 | 130 | Finished stage: (init-local) 00.94200 seconds | ||
168 | 131 | |||
169 | 132 | Starting stage: init-network | ||
170 | 133 | |`->restored from cache with run check: DataSourceNoCloud [seed=/dev/sr0][dsmode=net] @04.79500s +00.02100s | ||
171 | 134 | |`->setting up datasource @04.88900s +00.00000s | ||
172 | 135 | |`->reading and applying user-data @04.90100s +00.00400s | ||
173 | 136 | |`->reading and applying vendor-data @04.90500s +00.00800s | ||
174 | 137 | |`->activating datasource @04.95200s +00.00400s | ||
175 | 138 | Finished stage: (init-network) 02.72100 seconds | ||
176 | 139 | |||
177 | 140 | Starting stage: modules-config | ||
178 | 141 | |`->config-emit_upstart ran successfully @15.43100s +00.00000s | ||
179 | 142 | |`->config-snap ran successfully @15.43100s +00.00100s | ||
180 | 143 | ... | ||
181 | 144 | |`->config-runcmd ran successfully @16.22300s +00.00100s | ||
182 | 145 | |`->config-byobu ran successfully @16.23400s +00.00100s | ||
183 | 146 | Finished stage: (modules-config) 00.83500 seconds | ||
184 | 147 | |||
185 | 148 | Starting stage: modules-final | ||
186 | 149 | |`->config-snappy ran successfully @16.87400s +00.00200s | ||
187 | 150 | |`->config-package-update-upgrade-install ran successfully @16.87600s +00.00100s | ||
188 | 151 | ... | ||
189 | 152 | |`->config-final-message ran successfully @16.93700s +00.00500s | ||
190 | 153 | |`->config-power-state-change ran successfully @16.94300s +00.00000s | ||
191 | 154 | Finished stage: (modules-final) 00.10300 seconds | ||
192 | 155 | |||
193 | 156 | Total Time: 4.60100 seconds | ||
194 | 157 | |||
195 | 158 | 1 boot records analyzed | ||
196 | 159 | |||
197 | 160 | If additional boot records are detected then they are printed out from oldest | ||
198 | 161 | to newest. | ||
199 | 162 | |||
200 | 163 | Dump | ||
201 | 164 | ---- | ||
202 | 165 | |||
203 | 166 | The ``dump`` action simply dumps the cloud-init logs that the analyze module | ||
204 | 167 | is performing the analysis on and returns a list of dictionaries that can be | ||
205 | 168 | consumed for other reporting needs. Each element in the list is a boot entry. | ||
206 | 169 | |||
207 | 170 | .. code-block:: shell-session | ||
208 | 171 | |||
209 | 172 | $ cloud-init analyze dump | ||
210 | 173 | [ | ||
211 | 174 | { | ||
212 | 175 | "description": "starting search for local datasources", | ||
213 | 176 | "event_type": "start", | ||
214 | 177 | "name": "init-local", | ||
215 | 178 | "origin": "cloudinit", | ||
216 | 179 | "timestamp": 1567057578.037 | ||
217 | 180 | }, | ||
218 | 181 | { | ||
219 | 182 | "description": "attempting to read from cache [check]", | ||
220 | 183 | "event_type": "start", | ||
221 | 184 | "name": "init-local/check-cache", | ||
222 | 185 | "origin": "cloudinit", | ||
223 | 186 | "timestamp": 1567057578.054 | ||
224 | 187 | }, | ||
225 | 188 | { | ||
226 | 189 | "description": "no cache found", | ||
227 | 190 | "event_type": "finish", | ||
228 | 191 | "name": "init-local/check-cache", | ||
229 | 192 | "origin": "cloudinit", | ||
230 | 193 | "result": "SUCCESS", | ||
231 | 194 | "timestamp": 1567057578.056 | ||
232 | 195 | }, | ||
233 | 196 | { | ||
234 | 197 | "description": "searching for local data from DataSourceNoCloud", | ||
235 | 198 | "event_type": "start", | ||
236 | 199 | "name": "init-local/search-NoCloud", | ||
237 | 200 | "origin": "cloudinit", | ||
238 | 201 | "timestamp": 1567057578.147 | ||
239 | 202 | }, | ||
240 | 203 | { | ||
241 | 204 | "description": "found local data from DataSourceNoCloud", | ||
242 | 205 | "event_type": "finish", | ||
243 | 206 | "name": "init-local/search-NoCloud", | ||
244 | 207 | "origin": "cloudinit", | ||
245 | 208 | "result": "SUCCESS", | ||
246 | 209 | "timestamp": 1567057578.55 | ||
247 | 210 | }, | ||
248 | 211 | { | ||
249 | 212 | "description": "searching for local datasources", | ||
250 | 213 | "event_type": "finish", | ||
251 | 214 | "name": "init-local", | ||
252 | 215 | "origin": "cloudinit", | ||
253 | 216 | "result": "SUCCESS", | ||
254 | 217 | "timestamp": 1567057578.979 | ||
255 | 218 | }, | ||
256 | 219 | { | ||
257 | 220 | "description": "searching for network datasources", | ||
258 | 221 | "event_type": "start", | ||
259 | 222 | "name": "init-network", | ||
260 | 223 | "origin": "cloudinit", | ||
261 | 224 | "timestamp": 1567057582.814 | ||
262 | 225 | }, | ||
263 | 226 | { | ||
264 | 227 | "description": "attempting to read from cache [trust]", | ||
265 | 228 | "event_type": "start", | ||
266 | 229 | "name": "init-network/check-cache", | ||
267 | 230 | "origin": "cloudinit", | ||
268 | 231 | "timestamp": 1567057582.832 | ||
269 | 232 | }, | ||
270 | 233 | ... | ||
271 | 234 | { | ||
272 | 235 | "description": "config-power-state-change ran successfully", | ||
273 | 236 | "event_type": "finish", | ||
274 | 237 | "name": "modules-final/config-power-state-change", | ||
275 | 238 | "origin": "cloudinit", | ||
276 | 239 | "result": "SUCCESS", | ||
277 | 240 | "timestamp": 1567057594.98 | ||
278 | 241 | }, | ||
279 | 242 | { | ||
280 | 243 | "description": "running modules for final", | ||
281 | 244 | "event_type": "finish", | ||
282 | 245 | "name": "modules-final", | ||
283 | 246 | "origin": "cloudinit", | ||
284 | 247 | "result": "SUCCESS", | ||
285 | 248 | "timestamp": 1567057594.982 | ||
286 | 249 | } | ||
287 | 250 | ] | ||
288 | 251 | |||
289 | 252 | |||
290 | 253 | Boot | ||
291 | 254 | ---- | ||
292 | 255 | |||
293 | 256 | The ``boot`` action prints out kernel related timestamps that are not included | ||
294 | 257 | in any of the cloud-init logs. There are three different timestamps that are | ||
295 | 258 | presented to the user: | ||
296 | 259 | |||
297 | 260 | - kernel start | ||
298 | 261 | - kernel finish boot | ||
299 | 262 | - cloud-init start | ||
300 | 263 | |||
301 | 264 | This was added for additional clarity into the boot process that cloud-init | ||
302 | 265 | does not have control over, to aid in debugging of performance issues related | ||
303 | 266 | to cloud-init startup, and tracking regression. | ||
304 | 267 | |||
305 | 268 | .. code-block:: shell-session | ||
306 | 269 | |||
307 | 270 | $ cloud-init analyze boot | ||
308 | 271 | -- Most Recent Boot Record -- | ||
309 | 272 | Kernel Started at: 2019-08-29 01:35:37.753790 | ||
310 | 273 | Kernel ended boot at: 2019-08-29 01:35:38.807407 | ||
311 | 274 | Kernel time to boot (seconds): 1.053617000579834 | ||
312 | 275 | Cloud-init activated by systemd at: 2019-08-29 01:35:43.992460 | ||
313 | 276 | Time between Kernel end boot and Cloud-init activation (seconds): 5.185053110122681 | ||
314 | 277 | Cloud-init start: 2019-08-29 08:35:45.867000 | ||
315 | 278 | successful | ||
316 | 279 | |||
317 | 280 | Timestamp Gathering | ||
318 | 281 | ^^^^^^^^^^^^^^^^^^^ | ||
319 | 282 | |||
320 | 283 | The following boot related timestamps are gathered on demand when cloud-init | ||
321 | 284 | analyze boot runs: | ||
322 | 39 | 285 | ||
330 | 40 | Cloud-init analyze boot Timestamp Gathering | 286 | - Kernel startup gathered from system uptime |
331 | 41 | =========================================== | 287 | - Kernel finishes initialization from systemd |
332 | 42 | The following boot related timestamps are gathered on demand when cloud-init analyze boot runs: | 288 | UserSpaceMonotonicTimestamp property |
333 | 43 | - Kernel Startup, which is inferred from system uptime | 289 | - Cloud-init activation from the property InactiveExitTimestamp of the |
334 | 44 | - Kernel Finishes Initialization, which is inferred from systemd UserSpaceMonotonicTimestamp property | 290 | cloud-init local systemd unit |
328 | 45 | - Cloud-init activation, which is inferred from the property InactiveExitTimestamp of the cloud-init | ||
329 | 46 | local systemd unit. | ||
335 | 47 | 291 | ||
337 | 48 | In order to gather the necessary timestamps using systemd, running the commands | 292 | In order to gather the necessary timestamps using systemd, running the |
338 | 293 | commands below will gather the UserspaceTimestamp and InactiveExitTimestamp: | ||
339 | 49 | 294 | ||
340 | 50 | .. code-block:: shell-session | 295 | .. code-block:: shell-session |
341 | 51 | 296 | ||
344 | 52 | systemctl show -p UserspaceTimestampMonotonic | 297 | $ systemctl show -p UserspaceTimestampMonotonic |
345 | 53 | systemctl show cloud-init-local -p InactiveExitTimestampMonotonic | 298 | UserspaceTimestampMonotonic=989279 |
346 | 299 | $ systemctl show cloud-init-local -p InactiveExitTimestampMonotonic | ||
347 | 300 | InactiveExitTimestampMonotonic=4493126 | ||
348 | 54 | 301 | ||
354 | 55 | will gather the UserspaceTimestamp and InactiveExitTimestamp. | 302 | The UserspaceTimestamp tracks when the init system starts, which is used as |
355 | 56 | The UserspaceTimestamp tracks when the init system starts, which is used as an indicator of kernel | 303 | an indicator of kernel finishing initialization. The InactiveExitTimestamp |
356 | 57 | finishing initialization. The InactiveExitTimestamp tracks when a particular systemd unit transitions | 304 | tracks when a particular systemd unit transitions from the Inactive to Active |
357 | 58 | from the Inactive to Active state, which can be used to mark the beginning of systemd's activation | 305 | state, which can be used to mark the beginning of systemd's activation of |
358 | 59 | of cloud-init. | 306 | cloud-init. |
359 | 60 | 307 | ||
362 | 61 | Currently this only works for distros that use systemd as the init process. We will be expanding | 308 | Currently this only works for distros that use systemd as the init process. |
363 | 62 | support for other distros in the future and this document will be updated accordingly. | 309 | We will be expanding support for other distros in the future and this document |
364 | 310 | will be updated accordingly. | ||
365 | 63 | 311 | ||
369 | 64 | If systemd is not present on the system, dmesg is used to attempt to find an event that logs the | 312 | If systemd is not present on the system, dmesg is used to attempt to find an |
370 | 65 | beginning of the init system. However, with this method only the first two timestamps are able to be found; | 313 | event that logs the beginning of the init system. However, with this method |
371 | 66 | dmesg does not monitor userspace processes, so no cloud-init start timestamps are emitted like when | 314 | only the first two timestamps are able to be found; dmesg does not monitor |
372 | 315 | userspace processes, so no cloud-init start timestamps are emitted like when | ||
373 | 67 | using systemd. | 316 | using systemd. |
374 | 68 | 317 | ||
375 | 69 | List of Cloud-init analyze boot supported distros | ||
376 | 70 | ================================================= | ||
377 | 71 | - Arch | ||
378 | 72 | - CentOS | ||
379 | 73 | - Debian | ||
380 | 74 | - Fedora | ||
381 | 75 | - OpenSuSE | ||
382 | 76 | - Red Hat Enterprise Linux | ||
383 | 77 | - Ubuntu | ||
384 | 78 | - SUSE Linux Enterprise Server | ||
385 | 79 | - CoreOS | ||
386 | 80 | |||
387 | 81 | List of Cloud-init analyze boot unsupported distros | ||
388 | 82 | =================================================== | ||
389 | 83 | - FreeBSD | ||
390 | 84 | - Gentoo | ||
391 | 85 | \ No newline at end of file | 318 | \ No newline at end of file |
392 | 319 | .. vi: textwidth=79 |
PASSED: Continuous integration, rev:f2d60b63e8e 9702b22342cfc4d f6966de5d231fd /jenkins. ubuntu. com/server/ job/cloud- init-ci/ 1125/
https:/
Executed test runs:
SUCCESS: Checkout
SUCCESS: Unit & Style Tests
SUCCESS: Ubuntu LTS: Build
SUCCESS: Ubuntu LTS: Integration
IN_PROGRESS: Declarative: Post Actions
Click here to trigger a rebuild: /jenkins. ubuntu. com/server/ job/cloud- init-ci/ 1125//rebuild
https:/