Description

Pirated yet another Chef community gem. This one was formerly called chef-handler-profiler - felt that profiling-chef-handler was a better name and the old version required that debug logging mode had to be enabled for profiling output to be displayed. My goal was to allow the profiling data to be available by enabling the gem.

This is a Chef report handler that reports the execution time spent in each: cookbook, recipe, and resource.

http://wiki.opscode.com/display/chef/Exception+and+Report+Handlers

Requirements

Only works on Chef >= 10.14

Usage

There are two ways to use Chef Handlers.

Method 1 (recommended)

Use the chef_handler cookbook by Opscode. Create a recipe with the following:

include_recipe "chef_handler"

# Install `profiling-chef-handler` gem during the compile phase
chef_gem "profiling-chef-handler"

# load the gem here so it gets added to the $LOAD_PATH, otherwise chef_handler
# will fail.
require 'chef/handler/chef_profiler'

# Activate the handler immediately during compile phase
chef_handler "Chef::Handler::Profiler" do
  source "chef/handler/chef_profiler"
  action :nothing
end.run_action(:enable)

Method 2

Install the gem ahead of time, and configure Chef to use them:

gem install profiling-chef-handler

Then add to the configuration (/etc/chef/solo.rb for chef-solo or /etc/chef/client.rb for chef-client):

require "chef/handler/chef_profiler"
report_handlers << Chef::Handler::Profiler.new
exception_handlers << Chef::Handler::Profiler.new

Example output

Run chef to see profiler output, example:

$ chef-solo -j config.json
...
[2012-09-18T17:40:31+00:00] INFO: Running report handlers
[2012-09-18T17:40:31+00:00] INFO: Resources updated this run:
[2012-09-18T17:40:31+00:00] INFO:   chef_handler[Chef::Handler::Profiler]
[2012-09-18T17:40:31+00:00] INFO: Elapsed_time  Cookbook
[2012-09-18T17:40:31+00:00] INFO: ------------  -------------
[2012-09-18T17:40:31+00:00] INFO:    16.040867  python
[2012-09-18T17:40:31+00:00] INFO:     7.831706  nano
[2012-09-18T17:40:31+00:00] INFO:     3.233159  base
[2012-09-18T17:40:31+00:00] INFO:     0.699011  generic-users
[2012-09-18T17:40:31+00:00] INFO:     0.665569  chef
[2012-09-18T17:40:31+00:00] INFO:     0.176383  postfix
[2012-09-18T17:40:31+00:00] INFO:     0.174411  ntp
[2012-09-18T17:40:31+00:00] INFO:     0.001780  chef_handler
[2012-09-18T17:40:31+00:00] INFO: 
[2012-09-18T17:40:31+00:00] INFO: Elapsed_time  Recipe
[2012-09-18T17:40:31+00:00] INFO: ------------  -------------
[2012-09-18T17:40:31+00:00] INFO:    16.040867  python::default
[2012-09-18T17:40:31+00:00] INFO:     7.831706  nano::default
[2012-09-18T17:40:31+00:00] INFO:     1.414983  base::pki
[2012-09-18T17:40:31+00:00] INFO:     1.228345  base::utilities
[2012-09-18T17:40:31+00:00] INFO:     0.699011  generic-users::default
[2012-09-18T17:40:31+00:00] INFO:     0.660846  chef::omnibus
[2012-09-18T17:40:31+00:00] INFO:     0.374277  base::default
[2012-09-18T17:40:31+00:00] INFO:     0.176383  postfix::default
[2012-09-18T17:40:31+00:00] INFO:     0.174411  ntp::default
[2012-09-18T17:40:31+00:00] INFO:     0.103661  base::dracut
[2012-09-18T17:40:31+00:00] INFO:     0.085744  base::users
[2012-09-18T17:40:31+00:00] INFO:     0.010829  base::sshd_allow
[2012-09-18T17:40:31+00:00] INFO:     0.005859  base::kernel
[2012-09-18T17:40:31+00:00] INFO:     0.005025  base::sudoers
[2012-09-18T17:40:31+00:00] INFO:     0.004723  chef::profiler_handler
[2012-09-18T17:40:31+00:00] INFO:     0.004437  base::prelink
[2012-09-18T17:40:31+00:00] INFO:     0.001780  chef_handler::default
[2012-09-18T17:40:31+00:00] INFO: 
[2012-09-18T17:40:31+00:00] INFO: Elapsed_time  Resource
[2012-09-18T17:40:31+00:00] INFO: ------------  -------------
[2012-09-18T17:40:31+00:00] INFO:     7.755572  package[nano]
[2012-09-18T17:40:31+00:00] INFO:     0.549213  remote_file[/usr/local/bin/prlimit]
[2012-09-18T17:40:31+00:00] INFO:     0.483825  chef_gem[gelf]
[2012-09-18T17:40:31+00:00] INFO:     0.433518  execute[remove_pip_pynotify]
[2012-09-18T17:40:31+00:00] INFO:     0.391915  execute[install_clint==0.3.1]
[2012-09-18T17:40:31+00:00] INFO:     0.391519  execute[install_Genshi==0.6]
[2012-09-18T17:40:31+00:00] INFO:     0.389266  execute[install_Jinja2==2.6]
[2012-09-18T17:40:31+00:00] INFO:     0.385632  execute[install_zope.interface==3.8.0]
[2012-09-18T17:40:31+00:00] INFO:     0.384590  execute[install_gitdb==0.5.4]
[2012-09-18T17:40:31+00:00] INFO:     0.384320  execute[install_pycurl==7.19.0]
[2012-09-18T17:40:31+00:00] INFO:     0.382389  gem_package[teamocil]
[2012-09-18T17:40:31+00:00] INFO:     0.382325  execute[install_python-dateutil==1.5]
[2012-09-18T17:40:31+00:00] INFO:     0.381351  execute[install_PyMySQL==0.5]
[2012-09-18T17:40:31+00:00] INFO:     0.380537  execute[install_iso8601==0.1.4]
[2012-09-18T17:40:31+00:00] INFO:     0.380504  execute[install_pycassa==1.4.0]
[2012-09-18T17:40:31+00:00] INFO:     0.379317  execute[install_argparse==1.2.1]
[2012-09-18T17:40:31+00:00] INFO:     0.379029  execute[install_amqplib==1.0.2]
[2012-09-18T17:40:31+00:00] INFO:     0.378980  execute[install_pbs==0.108]
[2012-09-18T17:40:31+00:00] INFO:     0.378710  execute[install_apache-libcloud==
...

Todo

Might be nice to dump output to JSON files.
Different output, such as having resources grouped under their recipes, and recipes grouped under cookbooks.

License and Author

Licensed under the MIT license. See LICENSE file for details.

Author:: Joe Miller https://github.com/joemiller, https://twitter.com/miller_joe 2nd Author:: Andy Glick https://github.com/andyglick, [email protected]