Profiling Puppet Catalog Compilations

Fri May 16 17:07:00 +0000 2014 Puppet (notice): Compiled catalog for web_srv_001 in environment production in 284.33 seconds.

This was the beginning of a frustrating day. Many of our nodes’ catalogs were taking substantially longer than the agent normally allows for catalog compilation. Systems weren’t getting updated. In general, a great start to a monday morning.

We had already updated the configtimeout setting in puppet.conf on most of our nodes, but didn’t have it high enough. We bandaided this by further increasing the timeout value, and started work on profiling our catalog compilation.

Vagrant setup

Fortunately, I’d already setup a vagrantized puppetmaster for our environment. If you don’t already have this, I’d strongly recommend taking the time to do so now. It will help you immeasurably for myriad things. The specifics of doing this are outside the scope of this post. In general, take your Puppetmaster setup runbook and use that to generate a vagrant config to spin up a master as close to your environment’s master as possible.

Since we’re going to be asking our vagrant master to generate catalogs for a collection of nodes, we’re going to want to tweak auth.conf a little bit to permit us to request catalogs for arbitrary nodes from the vagrant master.

Update auth.conf

Puppet’s auth.conf is responsible for access control to Puppet’s HTTP API. The last bit in the file is

# deny everything else; this ACL is not strictly necessary, but
# illustrates the default policy.
path /
auth any

We changed it thusly on our vagrant master:

This assumes your vagrant net is 10.254.254.0/24. change this to reflect proper network info

# deny everything else; this ACL is not strictly necessary, but
# illustrates the default policy.
path /
auth any
allow_ip 127.0.0.0/8
allow_ip 10.254.254.0/24

Note that anytime you change auth.conf, the Puppetmaster process needs to be restarted. We run Puppet under Passenger, so an Apache restart is the way to go.

Collecting canary node facts

Now you have to decide on a collection of bogus nodes that represents a cross section of your environment. We need this because the Puppetmaster needs a nodes’ facts in order to generate its’ catalog. Since we’re simulating the existence of these nodes, we need to lay down simulated facts for the canary nodes. Generating the list of canary nodes is very environment specific. For our case we used one node of each functional type (web, db, bastion, smtp, etc) in each of our main puppet environments (dev, test, stage, prod), in each region. Your mileage will vary.

This generated a list of canary nodes like so:

web_300.dev.sjc.foomatic.com
web_300.tst.sjc.foomatic.com
web_300.stg.sjc.foomatic.com
web_300.prd.sjc.foomatic.com
mdb_300.dev.sjc.foomatic.com
mdb_300.tst.sjc.foomatic.com
mdb_300.stg.sjc.foomatic.com
mdb_300.prd.sjc.foomatic.com
bst_300.dev.sjc.foomatic.com
bst_300.tst.sjc.foomatic.com
bst_300.stg.sjc.foomatic.com
bst_300.prd.sjc.foomatic.com
eml_300.dev.sjc.foomatic.com
eml_300.tst.sjc.foomatic.com
eml_300.stg.sjc.foomatic.com
eml_300.prd.sjc.foomatic.com
web_300.dev.lon.foomatic.com
web_300.tst.lon.foomatic.com
web_300.stg.lon.foomatic.com
web_300.prd.lon.foomatic.com
mdb_300.dev.lon.foomatic.com
mdb_300.tst.lon.foomatic.com
mdb_300.stg.lon.foomatic.com
mdb_300.prd.lon.foomatic.com
bst_300.dev.lon.foomatic.com
bst_300.tst.lon.foomatic.com
bst_300.stg.lon.foomatic.com
bst_300.prd.lon.foomatic.com
eml_300.dev.lon.foomatic.com
eml_300.tst.lon.foomatic.com
eml_300.stg.lon.foomatic.com
eml_300.prd.lon.foomatic.com

I logged into the real servers closest to this canary nodelist, and generated facter output on them:

wnoble@node:~ $ sudo facter -p --yaml |sort > /tmp/`hostname`.yaml

After doing this, you will have facter output as yaml. This must be manipulated to your needs, and subsequently stored on your master.
The facter output is raw yaml. The master expects facts to be in a serialized Puppet::Node::Facts object. Some transformation is required.
It would be nice if facter could generate that by itself, but in the meantime, simply append a few lines to the beginning of the file, and increase the spacing of the yaml appropriately. Also, you will want to be aware of the expiration, and environment keys.
Here is an example of what a facts yaml file should contain

--- !ruby/object:Puppet::Node::Facts
  name: ec2-eng-e1d-wsm-tcb-dm5-150.wsm.local
  values:
    architecture: amd64
    augeasversion: 0.7.2
    concat_basedir: /var/lib/puppet/concat
    dns_all_nameservers: 123.123.123.10 123.123.123.11
    dns_nameserver: 123.123.123.10
    domain: foomatic.com
    environment: development
    facterversion: 1.6.18
    fqdn: web_001.dev.sjc.foomatic.com
    hardwareisa: unknown
    hardwaremodel: x86_64
    hostname: web_001
    id: root
    interfaces: "eth0,lo"
    ipaddress: 123.123.123.11
    ipaddress_eth0: 123.123.123.11
    ipaddress_lo: "127.0.0.1"
    ipaddress_lo: 127.0.0.1
    is_pe: false
    is_virtual: "false"
    kernel: Linux
    kernelmajversion: "2.6"
    kernelrelease: 2.6.35-24-virtual
    kernelversion: 2.6.35
    lsbdistcodename: squeeze
    lsbdistdescription: Debian GNU/Linux 6.0.7 (squeeze)
    lsbdistid: Debian
    lsbdistrelease: 6.0.7
    lsbmajdistrelease: "6"
    macaddress: 02:d6:29:b6:c9:78
    macaddress_eth0: 02:d6:29:b6:c9:78
    memoryfree: 6.08 GB
    memorysize: 2000
    memorytotal: 7.29 GB
    mtu_eth0: "1500"
    mtu_lo: "16436"
    netmask: 255.255.240.0
    netmask_eth0: 255.255.240.0
    netmask_lo: 255.0.0.0
    network_eth0: 123.123.123.11
    network_lo: 127.0.0.0
    operatingsystem: Debian
    operatingsystemrelease: 6.0.7
    os_maj_version: "6"
    osfamily: Debian
    path: /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin
    physicalprocessorcount: 1
    processor0: Intel(R) Xeon(R) CPU           E5507  @ 2.27GHz
    processor1: Intel(R) Xeon(R) CPU           E5507  @ 2.27GHz
    processorcount: "2"
    ps: ps -ef
    puppet_vardir: /var/lib/puppet
    puppetversion: 3.1.1
    root_home: /root
    rubysitedir: /usr/local/lib/site_ruby/1.8
    rubyversion: 1.8.7
    rvm_installed: false
    selinux: "false"
    sshdsakey: removed
    sshrsakey: removed
    swapfree: 0.00 kB
    swapsize: 0.00 kB
    timezone: UTC
    uniqueid: 800a9d10
    uptime: 103 days
    uptime_days: 103
    uptime_hours: 2472
    uptime_seconds: 8902718
    virtual: physical
  expiration: 2023-10-14 21:05:44.529826 +00:00

The leading spaces on each fact line is really important. These files should be placed on your vagrant master in /var/lib/puppet/yaml/facts/node_fqdn.yaml

Create a script to compile canary node catalogs

To verify that things are working properly, try and generate a catalog for your vagrant master, and then one of your canary nodes.

root@vagrantmaster:/tmp#  curl --silent --insecure -o /tmp/vagrantmaster.pson  -H 'Accept: pson' https://puppetmaster:8140/production/catalog/vagrantmaster.fqdn

If everything is configured correctly, this should generate a catalog for your master, and save the pson file as /tmp/vagrantmaster.pson. If this didn’t work, don’t keep going! Get this sorted first. Look at your various system logs to verify that the master compiled the catalog, and inspect the pson catalog for the resources you expect to exist.

Assuming it worked, try and generate a catalog for one of your canary nodes. Note that the puppet environment is present in the url that you’re requesting.

root@vagrantmaster:/tmp# curl --silent --insecure -o /tmp/web_300_dev_sjc.pson  -H 'Accept: pson' https://puppetmaster:8140/development/catalog/web_300.dev.sjc.foomatic.com

at this point, you should have a catalog for your web_300 node. It should be relatively trivial to write a quick shell script to generate the catalogs for the nodes in each environment. Mine looked something like this, but yours may vary a bit:

#!/bin/bash
for node in `ls -la /var/lib/puppet/yaml/facts/|grep dev|awk ' sub(/.yaml/,"") {print $9}'`; do
  #start the  process
  echo  ${node}
  echo "  Starting at `date +%H:%M:%S`"
  #generate a catalog
  echo "  Starting curl   at `date +%H:%M:%S`"
  curl --silent --insecure -o /vagrant/${node}.pson  -H 'Accept: pson' https://puppetmaster:8140/development/catalog/${node}
  echo "  Done!           at `date +%H:%M:%S`"
  sleep 5
  echo
done

I use a script similar to this to generate catalogs for my canary environment. I can simulate deploying large changes to our infrastructure code in vagrant to help prevent unexpected breakage. That’s a topic for another post however. We’re talking about profiling, right?

Profiling your environment

So now that we can generate simulated catalogs, we can start digging into performance. A few words first on setting up a proper testbed:

  • Don’t do this on the laptop or desktop you’re using to do your everyday work.
    • It seems like common sense, but when you’re trying to generate performance statistics, you want to make sure that you have as much consistency in your test environment as possible. That means not changing the performance characteristics of the system doing the profiling. If the system you’re doing your performance testing on has a variable workload, it stands to reason that the resulting statistics will have variance that you won’t be able to explain. Save yourself some headache and use a dedicated system to do the profiling. This system doesn’t have to be fast, it’s going to sit and churn unattended on catalogs. The performance data you get from it will differ from the performance data on your real master, but the percentages of time spent doing a particular thing will translate pretty closely.
  • Don’t use the data from JUST ONE PASS to determine your performance.
    • Collect at least three catalogs, and average the numbers generated. This will help average out random anomalies in your statistics.
  • Use a ramdisk to store the profiling logs.
    • There is an extra IO penalty when enabling debug mode and profiling data. There is a lot of data logged. I tried to offset this by creating a small memory disk. (my logfile was about 1.5Mb/catalog).
    • To do this:
      root@vagrantmaster:~# mkdir /perflogs
      root@vagrantmaster:~# echo "tmpfs			/perflogs	tmpfs	size=32M	0 0" >> /etc/fstab
      root@vagrantmaster:~# mount -a
      

      I’ll use /perflogs as the logdest later. if you use a different path, be sure to use the proper path.

Enough already. How do I generate profiling information?!

Update config.ru (passenger)

Our puppetmaster setup runs Puppet under Passenger. The rack config, is laid down in /usr/share/puppet/rack/puppetmasterd/config.ru. Your environment may vary. You can look at your Puppetmaster vhost’s documentroot to get a sense of where it lives on your system.
Our (stock) config.ru looks like this:

root@vagrantmaster:~# cat /usr/share/puppet/rack/puppetmasterd/config.ru
# a config.ru, for use with every rack-compatible webserver.
# SSL needs to be handled outside this, though.

# if puppet is not in your RUBYLIB:
# $LOAD_PATH.unshift('/opt/puppet/lib')

$0 = "master"

# if you want debugging:
# ARGV << "--debug"

ARGV << "--rack"

# Rack applications typically don't start as root.  Set --confdir and --vardir
# to prevent reading configuration from ~puppet/.puppet/puppet.conf and writing
# to ~puppet/.puppet
ARGV << "--confdir" << "/etc/puppet"
ARGV << "--vardir"  << "/var/lib/puppet"

# NOTE: it's unfortunate that we have to use the "CommandLine" class
#  here to launch the app, but it contains some initialization logic
#  (such as triggering the parsing of the config file) that is very
#  important.  We should do something less nasty here when we've
#  gotten our API and settings initialization logic cleaned up.
#
# Also note that the "$0 = master" line up near the top here is
#  the magic that allows the CommandLine class to know that it's
#  supposed to be running master.
#
# --cprice 2012-05-22

require 'puppet/util/command_line'
# we're usually running inside a Rack::Builder.new {} block,
# therefore we need to call run *here*.
run Puppet::Util::CommandLine.new.execute

Lets just use sed to add the command line flags we need to enable in order to get the master to run in debug mode and to generate profiling data.

root@vagrantmaster:~# cp /usr/share/puppet/rack/puppetmasterd/config.ru /usr/share/puppet/rack/puppetmasterd/config.ru.backup
root@vagrantmaster:~# sed -i -e 's/ARGV << "--rack"/ARGV << "--debug"\
ARGV << "--profile"\
ARGV << "--evaltrace"\
ARGV << "--logdest=\/perflogs\/profiling.log"\
ARGV << "--rack"/' /usr/share/puppet/rack/puppetmasterd/config.ru
  • Make sure that the logdest path is relevant to your vagrant master.
  • Remember to restart Apache to pick up the changes.

Once you’ve done this, try running curl again to generate a catalog. You’ll notice the profiling.log file starting to fill up with loads of incredibly interesting information. When trying to evaluate how my whole environment performs, I adapted my catalog script to also copy the profiling log, and subsequently truncate it afterwards. This way I get one logfile per catalog generated:

~/profiling$ cat devprofile.sh
#!/bin/bash
for node in `ls -la /var/lib/puppet/yaml/facts/|grep dev|awk ' sub(/.yaml/,"") {print $9}'`; do
  #nuke the log file
  >/vagrant/profiling/${node}.pson
  #start the  process
  echo  ${node}
  echo "  Starting at `date +%H:%M:%S`"
  #generate a catalog
  echo "  Starting curl   at `date +%H:%M:%S`"
  curl --silent --insecure -o /perflogs/profiling/${node}.pson  -H 'Accept: pson' https://puppetmaster:8140/development/catalog/${node}
  echo "  Done!           at `date +%H:%M:%S`"
  echo "positioning logs  at `date +%H:%M:%S`"
  cat /perflogs/profiling.log >/vagrant/profiling/${node}.log&&>/perflogs/profiling.log
  sleep 5
  echo
done

Now, with this script, I can generate a catalog, and the log data for each nodetype. The most relevant profiling information logged has PROFILE in each line, so simply grepping for PROFILE should give you some helpful information, right?

$ grep 'PROFILE' /perflogs/profiling.log
Mon May 19 17:10:07 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.1 Found node information: took 0.0592 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.1 Compile: Set node parameters: took 0.0011 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.2 Compile: Created settings scope: took 0.0038 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.3 Compile: Evaluated main: took 0.0009 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.1 Called include: took 0.1711 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.2.1 Called include: took 0.0164 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.2 Called include: took 0.0216 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.3.1 Called validate_string: took 0.0000 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.3 Called include: took 0.0484 seconds
Mon May 19 17:10:08 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.4 Called extlookup: took 0.0864 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.5 Called validate_array: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.6 Called validate_string: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.7 Called validate_array: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.8 Called validate_string: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.9 Called template: took 0.0057 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.10 Called template: took 0.0029 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.11 Called template: took 0.0029 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.12.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.12 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.13.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.13 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.14.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.14 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.15.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.15 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.16.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.16 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.17.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.17 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.18 Called template: took 0.1014 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.19 Called defined: took 0.0001 seconds
Mon May 19 17:10:09 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.20 Called realize: took 0.0001 seconds
Mon May 19 17:10:14 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.21 Called defined: took 0.0001 seconds
Mon May 19 17:10:14 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.22 Called defined: took 0.0001 seconds
Mon May 19 17:10:14 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.23.1 Called extlookup: took 0.3477 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.23.2 Called extlookup: took 0.3564 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.23 Called include: took 0.9252 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.24 Called merge: took 0.0000 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.25 Called merge: took 0.0000 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.26 Called include: took 0.0289 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.27 Called include: took 0.0124 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.28.1 Called regsubst: took 0.0000 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.28 Called include: took 0.0516 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.29 Called validate_hash: took 0.0000 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.30 Called template: took 0.0040 seconds
Mon May 19 17:10:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.31 Called include: took 0.0118 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.32.1 Called include: took 0.0122 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.32.2 Called validate_hash: took 0.0000 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.32.3 Called template: took 0.0034 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.32 Called include: took 0.1513 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.33 Called template: took 0.0027 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.34 Called template: took 0.0023 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.35 Called validate_string: took 0.0000 seconds
...
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.43 Called include: took 0.0037 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.44.1 Called defined: took 0.0001 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.44.2 Called defined: took 0.0001 seconds
Mon May 19 17:10:16 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.44 Called include: took 0.0041 seconds
...
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.49 Called extlookup: took 0.0862 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.50 Called extlookup: took 0.0876 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.1 Called include: took 0.0059 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.2.1 Called include: took 0.0114 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.2 Called include: took 0.0411 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.3.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.3.2 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.3.3 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.3 Called validate_bool: took 0.0004 seconds
Mon May 19 17:10:17 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4.1 Called hiera: took 0.0199 seconds
...
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4.9 Called fqdn_rand: took 0.0001 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4.10 Called include: took 0.0029 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4.11 Called create_resources: took 0.0331 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4.12 Called create_resources: took 0.1630 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51.4 Called include: took 0.6028 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.51 Called include: took 0.8570 seconds
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.52 Called extlookup: took 0.0041 seconds
...
Mon May 19 17:10:18 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.56 Called realize: took 0.0001 seconds
Mon May 19 17:10:25 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.57.1 Called include: took 6.1317 seconds
Mon May 19 17:10:25 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.57.2.1 Called include: took 0.0160 seconds
Mon May 19 17:10:25 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.57.2 Called include: took 0.3395 seconds
Mon May 19 17:10:25 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.57 Called include: took 6.4773 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.1 Called fqdn_rand: took 0.0002 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.2.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.2 Called validate_bool: took 0.0001 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.3 Called include: took 0.0233 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.4.1 Called is_bool: took 0.0000 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.4 Called validate_bool: took 0.0004 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.5 Called include: took 0.0226 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58.6 Called template: took 0.0041 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.58 Called include: took 1.0234 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.59 Called include: took 0.0058 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.60 Called template: took 0.0037 seconds
...
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.64 Called extlookup: took 0.0884 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.65 Called extlookup: took 0.0879 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.66 Called extlookup: took 0.0880 seconds
Mon May 19 17:10:26 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.67 Called template: took 0.0031 seconds
Mon May 19 17:10:27 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.68 Called extlookup: took 0.0041 seconds
...
Mon May 19 17:10:28 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.1.1 Called validate_string: took 0.0000 seconds
...
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.10 Called include: took 0.5087 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.11.1 Called validate_hash: took 0.0000 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.11.2 Called create_resources: took 0.0591 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.11.3 Called validate_hash: took 0.0000 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.11.4 Called create_resources: took 0.0593 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81.11 Called include: took 0.2130 seconds
Mon May 19 17:10:34 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.81 Called include: took 6.2463 seconds
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.82.1 Called defined: took 0.0367 seconds
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.82.2 Called defined: took 0.0355 seconds
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.82 Called include: took 0.2421 seconds
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4.83 Called template: took 0.0027 seconds
...
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.4 Compile: Evaluated AST node: took 27.8179 seconds
Mon May 19 17:10:35 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.5 Compile: Evaluated node classes: took 0.0000 seconds
Mon May 19 17:10:36 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.1 Evaluated collections: took 0.3187 seconds
...
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.134.1 Called include: took 0.0050 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.134.2 Called include: took 0.0047 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.134.3 Called template: took 0.0028 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.134 Evaluated resource Apt::Source[debiansecurity]: took 0.0375 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.135.1 Called include: took 0.0049 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.135.2 Called include: took 0.0047 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.135.3 Called template: took 0.0028 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.135 Evaluated resource Apt::Source[backports]: took 0.0702 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.136.1 Called include: took 0.0048 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.136.2 Called include: took 0.0043 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.136.3 Called template: took 0.0025 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.136 Evaluated resource Apt::Source[squeeze]: took 0.0698 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.137.1 Called include: took 0.0048 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.137.2 Called include: took 0.0045 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.137.3 Called template: took 0.0029 seconds
Mon May 19 17:10:50 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.137 Evaluated resource Apt::Source[puppetlabs]: took 0.0713 seconds
...
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.200.1 Called include: took 0.0056 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.200.2 Called include: took 0.0049 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.200.3 Called template: took 0.0029 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.200 Evaluated resource Apt::Source[monitoring]: took 0.0383 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.1 Called include: took 0.0047 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.2 Called upcase: took 0.0000 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.3 Called regsubst: took 0.0000 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.4 Called sha1: took 0.0000 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.5 Called defined: took 0.0001 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.6 Called defined: took 0.0001 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201.7 Called defined: took 0.0001 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.201 Evaluated resource Apt::Key[monitoring]: took 0.0077 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2.202.1 Called inline_template: took 0.0009 seconds
...
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1.2 Evaluated definitions: took 15.0173 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.1 Iterated (1) on generators: took 15.3362 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.1 Evaluated collections: took 0.2032 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.1.1 Called defined: took 0.0413 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.1 Evaluated resource Ourusers::Remove_undeclared_user[purgeduser]: took 0.0623 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2.1 Called defined: took 0.0001 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2.2 Called defined: took 0.0001 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2.3 Called extlookup: took 0.3421 seconds
Mon May 19 17:10:51 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2.4 Called defined: took 0.0001 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2.5 Called extlookup: took 0.4387 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.2 Evaluated resource Ourusers::Add_user[someuser]: took 0.7912 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.1 Called defined: took 0.0001 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.2 Called defined: took 0.0001 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.3 Called extlookup: took 0.3506 seconds
Mon May 19 17:10:52 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.4 Called defined: took 0.0001 seconds
Mon May 19 17:10:53 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.5 Called extlookup: took 0.3528 seconds
Mon May 19 17:10:53 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.6 Called defined: took 0.0001 seconds
Mon May 19 17:10:53 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.3.7 Called defined: took 0.0001 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.117 Evaluated resource Apt::Pin[our_apt]: took 0.0192 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.118.1 Called include: took 0.0044 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.118.2 Called upcase: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.118.3 Called regsubst: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.118.4 Called sha1: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.118.5 Called defined: took 0.0001 seconds
...
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.119 Evaluated resource Apt::Key[Add key: 8B48AD6246925553 from Apt::Source backports]: took 0.0075 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120.1 Called include: took 0.0044 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120.2 Called upcase: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120.3 Called regsubst: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120.4 Called sha1: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120.5 Called defined: took 0.0001 seconds
...
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.120 Evaluated resource Apt::Key[Add key: B98321F9 from Apt::Source squeeze]: took 0.0070 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.1 Called include: took 0.0045 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.2 Called upcase: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.3 Called regsubst: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.4 Called sha1: took 0.0000 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.5 Called defined: took 0.0001 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.6 Called defined: took 0.0001 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121.7 Called defined: took 0.0001 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.121 Evaluated resource Apt::Key[Add key: 4BD6EC30 from Apt::Source puppetlabs]: took 0.0081 seconds
...
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.122 Evaluated resource Apt::Key[Add key: D49459D8C762B6E6 from Apt::Source s3tools]: took 0.0822 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2.123 Evaluated resource Github::Git_clone[git-clone-eops-tools-master]: took 0.0007 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2.2 Evaluated definitions: took 71.2911 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.2 Iterated (2) on generators: took 71.4945 seconds
Mon May 19 17:12:02 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.3.1 Evaluated collections: took 0.1876 seconds
Mon May 19 17:12:03 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.3.2 Evaluated definitions: took 0.0042 seconds
Mon May 19 17:12:03 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6.3 Iterated (3) on generators: took 0.1922 seconds
Mon May 19 17:12:03 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.6 Compile: Evaluated generators: took 87.0232 seconds
Mon May 19 17:12:03 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2.7 Compile: Finished catalog: took 0.2267 seconds
Mon May 19 17:12:03 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.2 Compiled catalog for web_300.dev.sjc.foomatic.com in environment development: took 115.7449 seconds
Mon May 19 17:14:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.3 Filtered result for catalog web_300.dev.sjc.foomatic.com: took 16.9024 seconds
Mon May 19 17:15:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.4 Rendered result in Puppet::Network::Format[pson]: took 60.1266 seconds
Mon May 19 17:15:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1.5 Sent response: took 0.0001 seconds
Mon May 19 17:15:15 +0000 2014 Puppet (debug): PROFILE [69997977759780] 1 Processed request GET /development/catalog/web_300.dev.sjc.foomatic.com: took 307.9767 seconds

Uhm… so… This is really useful, sort-of. It was not immediately intuitive to me what resources are taking the most time.. or where I should start trying to optimize.. Fortunately, Adrien Thebo has made our lives so much easier.

Clone Adrien’s script of awesome

Adrien has a script which will look through the output of your log and give you some actionable information. Lets grab it and use it!

~/profiling/$ git clone git@github.com:adrienthebo/puppet-profile-parser.git
Cloning into 'puppet-profile-parser'...
remote: Counting objects: 5, done.
remote: Compressing objects: 100% (4/4), done.
remote: Total 5 (delta 0), reused 5 (delta 0)
Receiving objects: 100% (5/5), done.
Checking connectivity... done.

Bundle install

~/profiling/$ cd puppet-profile-parser
~/profiling/puppet-profile-parser/$ bundle install
Fetching gem metadata from https://rubygems.org/..
Resolving dependencies...
Using colored (1.2)
Using terminal-table (1.4.5)
Using bundler (1.3.5)
Your bundle is complete!
Use `bundle show [gemname]` to see where a bundled gem is installed.

Awesome! Now lets take a look at that same catalog, but with Adrien’s tool:

~/profiling/puppet-profile-parser/$ ./profile-parser.rb /vagrant/profiling/web_300.dev.sjc.foomatic.com.log
  1 Processed request GET /development/catalog/web_300.dev.sjc.foomatic.com (307.9767 seconds)
    1.1 Found node information (0.0592 seconds)
    1.2 Compiled catalog for web_300.dev.sjc.foomatic.com in environment development (115.7449 seconds)
    ...
    (big waterfall tree here of all the items being profiled)
        1.2.6.3 Iterated (3) on generators (0.1922 seconds)
          1.2.6.3.1 Evaluated collections (0.1876 seconds)
          1.2.6.3.2 Evaluated definitions (0.0042 seconds)
      1.2.7 Compile: Finished catalog (0.2267 seconds)
    1.3 Filtered result for catalog ec2-int-e1a-eop-sec-prt-300.amzn.e1.int (16.9024 seconds)
    1.4 Rendered result in Puppet::Network::Format[pson] (60.1266 seconds)
    1.5 Sent response (0.0001 seconds)
--- Function calls ---
Total time: 109.68980000000101
Itemized:
+------------------+------------------------+
| Source           | Time                   |
+------------------+------------------------+
| extlookup        | 72.61219999999997      |
| include          | 29.84699999999999      |
| defined          | 6.168699999999953      |
| create_resources | 0.5039                 |
| template         | 0.29700000000000004    |
| hiera            | 0.2248                 |
| inline_template  | 0.03389999999999999    |
| validate_bool    | 0.0015                 |
| realize          | 0.0005                 |
| fqdn_rand        | 0.00030000000000000003 |
| regsubst         | 0.0                    |
| validate_hash    | 0.0                    |
| merge            | 0.0                    |
| is_bool          | 0.0                    |
| validate_array   | 0.0                    |
| validate_string  | 0.0                    |
| split            | 0.0                    |
| join             | 0.0                    |
| upcase           | 0.0                    |
| sha1             | 0.0                    |
+------------------+------------------------+
--- Resource evaluations ---
Total time: 86.2512
Itemized:
+--------------------------------------+----------------------+
| Source                               | Time                 |
+--------------------------------------+----------------------+
| Ourusers::Add_user                   | 71.31480000000003    |
| Ourusers::User                       | 11.1715              |
| Ourusers::Remove_undeclared_user     | 2.0556999999999994   |
| Apt::Source                          | 0.4619               |
| Apt::Pin                             | 0.1454               |
| Apt::Key                             | 0.1195               |
| Monitoring::Check                    | 0.061799999999999966 |
| Monitoring::Plugin                   | 0.04680000000000001  |
| Github::foomatic_repo                | 0.0464               |
| Sudoers::Add_sudoers                 | 0.039099999999999996 |
| Concat::Fragment                     | 0.0209               |
| Environment_variable                 | 0.0114               |
| Sudoers::Add_sudoers_individuals     | 0.0084               |
| Concat                               | 0.0045               |
| Github::Git_clone                    | 0.0021               |
+--------------------------------------+----------------------+

How freaking sweet is that?!

Thank you Adrien!

So now, with this data, we know where to spend our optimization efforts. In our case, our ourusers module needs to really just be culled, and a tool better suited to user management should be utilized. Your catalogs will very likely show very different bottlenecks.

I’ll write another post soon with further optimization thoughts.

Leave a Reply