When using Puppet you often run it in a single run mode on the CLI and then go afk. When you return you might notice it was slow for some or other reason but did not run it with –evaltrace and in debug mode so the information to help you answer this simply isn’t present – or scrolled off or got rotated away from your logs.
Typically you’d deploy something like foreman or report handlers on your masters which would receive and display reports. But while you’re on the shell it’s a big context switch to go and find the report there.
Puppet now saves reports in it’s state dir including with apply if you ran it with –write-catalog-summary and in recent versions these reports include the performance data that you’d only find from –evaltrace.
So to solve this problem I wrote a little tool to show reports on the CLI. It’s designed to run on the shell of the node in question and as root. If you do this it will automatically pick up the latest report and print it but it will also go through and check the sizes of files and show you stats. You can run it against saved reports on some other node but you’ll lose some utility. The main focus of the information presented is to let you see logs from the past run but also information that help you answer why it was slow to run.
It’s designed to work well with very recent versions of Puppet maybe even only 3.3.0 and newer, I’ve not tested it on older versions but will gladly accept patches.
Here are some snippets of a report of one of my nodes and some comments about the sections. A full sample report can be found here.
First it’s going to show you some metadata about the report, what node, when for etc:
sudo report_print.rb
Report for puppetmaster.example.com in environment production at Thu Oct 10 13:37:04 +0000 2013
Report File: /var/lib/puppet/state/last_run_report.yaml
Report Kind: apply
Puppet Version: 3.3.1
Report Format: 4
Configuration Version: 1381412220
UUID: 99503fe8-38f2-4441-a530-d555ede9067b
Log Lines: 350 (show with --log) |
Some important information here, you can see it figured out where to find the report by parsing the Puppet config – agent section – what version of Puppet and what report format. You can also see the report has 350 lines of logs in it but it isn’t showing them by default.
Next up it shows you a bunch of metrics from the report:
Report Metrics:
Changes:
Total: 320
Events:
Total: 320
Success: 320
Failure: 0
Resources:
Total: 436
Out of sync: 317
Changed: 317
Restarted: 7
Failed to restart: 0
Skipped: 0
Failed: 0
Scheduled: 0
Time:
Total: 573.671295
Package: 509.544123
Exec: 33.242635
Puppetdb conn validator: 22.767754
Config retrieval: 4.096973
File: 1.343388
User: 1.337979
Service: 1.180588
Ini setting: 0.127856
Anchor: 0.013984
Datacat collector: 0.008954
Host: 0.003265
Datacat fragment: 0.00277
Schedule: 0.000504
Group: 0.00039
Filebucket: 0.000132 |
These are numerically sorted and the useful stuff is in the last section – what types were to blame for the biggest slowness in your run. Here we can see we spent 509 seconds just doing packages.
Having seen how long each type of resource took it then shows you a little report of how many resources of each type was found:
Resources by resource type:
288 File
30 Datacat_fragment
25 Anchor
24 Ini_setting
22 User
18 Package
9 Exec
7 Service
6 Schedule
3 Datacat_collector
1 Group
1 Host
1 Puppetdb_conn_validator
1 Filebucket |
From here you’ll see detail about resources and files, times, sizes etc. By default it’s going to show you 20 of each but you can increase that using the –count argument.
First we see the evaluation time by resource, this is how long the agent spent to complete a specific resource:
Slowest 20 resources by evaluation time:
356.94 Package[activemq]
41.71 Package[puppetdb]
33.31 Package[apache2-prefork-dev]
33.05 Exec[compile-passenger]
23.41 Package[passenger]
22.77 Puppetdb_conn_validator[puppetdb_conn]
22.12 Package[libcurl4-openssl-dev]
10.94 Package[httpd]
4.78 Package[libapr1-dev]
3.95 Package[puppetmaster]
3.32 Package[ntp]
2.75 Package[puppetdb-terminus]
2.71 Package[mcollective-client]
1.86 Package[ruby-stomp]
1.72 Package[mcollective]
0.58 Service[puppet]
0.30 Service[puppetdb]
0.18 User[jack]
0.16 User[jill]
0.16 User[ant] |
You can see by far the longest here was the activemq package that took 356 seconds and contributed most to the 509 seconds that Package types took in total. A clear indication that maybe this machine is picking the wrong mirrors or that I should create my own nearby mirror.
File serving in Puppet is notoriously slow so when run as root on the node in question it will look for all File resources and print the sizes. Unfortunately it can’t know if a file contents came from source or content as that information isn’t in the report. Still this might give you some information on where to target optimization. In this case nothing really stands out:
20 largest managed files (only those with full path as resource name that are readable)
6.50 KB /usr/local/share/mcollective/mcollective/util/actionpolicy.rb
3.90 KB /etc/mcollective/facts.yaml
3.83 KB /var/lib/puppet/concat/bin/concatfragments.sh
2.78 KB /etc/sudoers
1.69 KB /etc/apache2/conf.d/puppetmaster.conf
1.49 KB /etc/puppet/fileserver.conf
1.20 KB /etc/puppet/rack/config.ru
944.00 B /etc/apache2/apache2.conf
573.00 B /etc/ntp.conf
412.00 B /usr/local/share/mcollective/mcollective/util/actionpolicy.ddl
330.00 B /etc/apache2/mods-enabled/passenger.conf
330.00 B /etc/apache2/mods-available/passenger.conf
262.00 B /etc/default/puppet
215.00 B /etc/apache2/mods-enabled/worker.conf
215.00 B /etc/apache2/mods-available/worker.conf
195.00 B /etc/apache2/ports.conf
195.00 B /var/lib/puppet/concat/_etc_apache2_ports.conf/fragments.concat
195.00 B /var/lib/puppet/concat/_etc_apache2_ports.conf/fragments.concat.out
164.00 B /var/lib/puppet/concat/_etc_apache2_ports.conf/fragments/10_Apache ports header
158.00 B /etc/puppet/hiera.yaml |
And finally if I ran it with –log I’d get the individual log lines:
350 Log lines:
Thu Oct 10 13:37:06 +0000 2013 /Stage[main]/Concat::Setup/File[/var/lib/puppet/concat]/ensure (notice): created
Thu Oct 10 13:37:06 +0000 2013 /Stage[main]/Concat::Setup/File[/var/lib/puppet/concat/bin]/ensure (notice): created
Thu Oct 10 13:37:06 +0000 2013 /Stage[main]/Concat::Setup/File[/var/lib/puppet/concat/bin/concatfragments.sh]/ensure (notice): defined content as '{md5}2fbba597a1513eb61229551d35d42b9f'
.
.
. |
The code is on GitHub, I’d like to make it available as a Puppet Forge module but there really is no usable option to achieve this. The Puppet Face framework is the best available option but the UX is so poor that I would not like to expose anyone to this to use my code.
