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.
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, andyglick@gmail.com