{"id":2977,"date":"2013-10-10T15:25:31","date_gmt":"2013-10-10T14:25:31","guid":{"rendered":"http:\/\/www.devco.net\/?p=2977"},"modified":"2013-10-10T16:17:06","modified_gmt":"2013-10-10T15:17:06","slug":"cli-report-viewer-for-puppet","status":"publish","type":"post","link":"https:\/\/www.devco.net\/archives\/2013\/10\/10\/cli-report-viewer-for-puppet.php","title":{"rendered":"CLI Report viewer for Puppet"},"content":{"rendered":"

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<\/em> 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. <\/p>\n

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.<\/p>\n

Puppet now saves reports in it’s state dir including with apply if you ran it with –write-catalog-summary<\/em> and in recent versions these reports include the performance data that you’d only find from –evaltrace<\/em>.<\/p>\n

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<\/em> it was slow to run.<\/p>\n

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.<\/p>\n

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<\/a>.<\/p>\n

First it’s going to show you some metadata about the report, what node, when for etc:<\/p>\n

<\/p>\n

\r\nsudo report_print.rb\r\nReport for puppetmaster.example.com in environment production at Thu Oct 10 13:37:04 +0000 2013\r\n\r\n             Report File: \/var\/lib\/puppet\/state\/last_run_report.yaml\r\n             Report Kind: apply\r\n          Puppet Version: 3.3.1\r\n           Report Format: 4\r\n   Configuration Version: 1381412220\r\n                    UUID: 99503fe8-38f2-4441-a530-d555ede9067b\r\n               Log Lines: 350 (show with --log)\r\n<\/pre>\n
<\/code><\/p>\n
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.<\/p>\n
Next up it shows you a bunch of metrics from the report:<\/p>\n
<\/p>\n
\r\nReport Metrics:\r\n\r\n   Changes:\r\n                        Total: 320\r\n\r\n   Events:\r\n                        Total: 320\r\n                      Success: 320\r\n                      Failure: 0\r\n\r\n   Resources:\r\n                        Total: 436\r\n                  Out of sync: 317\r\n                      Changed: 317\r\n                    Restarted: 7\r\n            Failed to restart: 0\r\n                      Skipped: 0\r\n                       Failed: 0\r\n                    Scheduled: 0\r\n\r\n   Time:\r\n                        Total: 573.671295\r\n                      Package: 509.544123\r\n                         Exec: 33.242635\r\n      Puppetdb conn validator: 22.767754\r\n             Config retrieval: 4.096973\r\n                         File: 1.343388\r\n                         User: 1.337979\r\n                      Service: 1.180588\r\n                  Ini setting: 0.127856\r\n                       Anchor: 0.013984\r\n            Datacat collector: 0.008954\r\n                         Host: 0.003265\r\n             Datacat fragment: 0.00277\r\n                     Schedule: 0.000504\r\n                        Group: 0.00039\r\n                   Filebucket: 0.000132\r\n<\/pre>\n
<\/code><\/p>\n
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.<\/p>\n
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:<\/p>\n
<\/p>\n
\r\nResources by resource type:\r\n\r\n    288 File\r\n     30 Datacat_fragment\r\n     25 Anchor\r\n     24 Ini_setting\r\n     22 User\r\n     18 Package\r\n      9 Exec\r\n      7 Service\r\n      6 Schedule\r\n      3 Datacat_collector\r\n      1 Group\r\n      1 Host\r\n      1 Puppetdb_conn_validator\r\n      1 Filebucket\r\n<\/pre>\n
<\/code><\/p>\n
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<\/em> argument.<\/p>\n
First we see the evaluation time by resource, this is how long the agent spent to complete a specific resource:<\/p>\n
<\/p>\n
\r\nSlowest 20 resources by evaluation time:\r\n\r\n    356.94 Package[activemq]\r\n     41.71 Package[puppetdb]\r\n     33.31 Package[apache2-prefork-dev]\r\n     33.05 Exec[compile-passenger]\r\n     23.41 Package[passenger]\r\n     22.77 Puppetdb_conn_validator[puppetdb_conn]\r\n     22.12 Package[libcurl4-openssl-dev]\r\n     10.94 Package[httpd]\r\n      4.78 Package[libapr1-dev]\r\n      3.95 Package[puppetmaster]\r\n      3.32 Package[ntp]\r\n      2.75 Package[puppetdb-terminus]\r\n      2.71 Package[mcollective-client]\r\n      1.86 Package[ruby-stomp]\r\n      1.72 Package[mcollective]\r\n      0.58 Service[puppet]\r\n      0.30 Service[puppetdb]\r\n      0.18 User[jack]\r\n      0.16 User[jill]\r\n      0.16 User[ant]\r\n<\/pre>\n
<\/code><\/p>\n
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.<\/p>\n
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<\/em> or content<\/em> 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:<\/p>\n
<\/p>\n
\r\n20 largest managed files (only those with full path as resource name that are readable)\r\n\r\n     6.50 KB \/usr\/local\/share\/mcollective\/mcollective\/util\/actionpolicy.rb\r\n     3.90 KB \/etc\/mcollective\/facts.yaml\r\n     3.83 KB \/var\/lib\/puppet\/concat\/bin\/concatfragments.sh\r\n     2.78 KB \/etc\/sudoers\r\n     1.69 KB \/etc\/apache2\/conf.d\/puppetmaster.conf\r\n     1.49 KB \/etc\/puppet\/fileserver.conf\r\n     1.20 KB \/etc\/puppet\/rack\/config.ru\r\n    944.00 B \/etc\/apache2\/apache2.conf\r\n    573.00 B \/etc\/ntp.conf\r\n    412.00 B \/usr\/local\/share\/mcollective\/mcollective\/util\/actionpolicy.ddl\r\n    330.00 B \/etc\/apache2\/mods-enabled\/passenger.conf\r\n    330.00 B \/etc\/apache2\/mods-available\/passenger.conf\r\n    262.00 B \/etc\/default\/puppet\r\n    215.00 B \/etc\/apache2\/mods-enabled\/worker.conf\r\n    215.00 B \/etc\/apache2\/mods-available\/worker.conf\r\n    195.00 B \/etc\/apache2\/ports.conf\r\n    195.00 B \/var\/lib\/puppet\/concat\/_etc_apache2_ports.conf\/fragments.concat\r\n    195.00 B \/var\/lib\/puppet\/concat\/_etc_apache2_ports.conf\/fragments.concat.out\r\n    164.00 B \/var\/lib\/puppet\/concat\/_etc_apache2_ports.conf\/fragments\/10_Apache ports header\r\n    158.00 B \/etc\/puppet\/hiera.yaml\r\n<\/pre>\n
<\/code><\/p>\n
And finally if I ran it with –log<\/em> I’d get the individual log lines:<\/p>\n
<\/p>\n
\r\n350 Log lines:\r\n\r\n   Thu Oct 10 13:37:06 +0000 2013 \/Stage[main]\/Concat::Setup\/File[\/var\/lib\/puppet\/concat]\/ensure (notice): created\r\n   Thu Oct 10 13:37:06 +0000 2013 \/Stage[main]\/Concat::Setup\/File[\/var\/lib\/puppet\/concat\/bin]\/ensure (notice): created\r\n   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'\r\n   .\r\n   .\r\n   .\r\n<\/pre>\n
<\/code><\/p>\n
The code is on GitHub<\/a>, 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.<\/p>\n","protected":false},"excerpt":{"rendered":"
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 […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_et_pb_use_builder":"","_et_pb_old_content":"","footnotes":""},"categories":[7],"tags":[121,85,21,13],"_links":{"self":[{"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/posts\/2977"}],"collection":[{"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/comments?post=2977"}],"version-history":[{"count":17,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/posts\/2977\/revisions"}],"predecessor-version":[{"id":2995,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/posts\/2977\/revisions\/2995"}],"wp:attachment":[{"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/media?parent=2977"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/categories?post=2977"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.devco.net\/wp-json\/wp\/v2\/tags?post=2977"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}