puppetlabs/puppet — pull request #1511 by zaphod42 (2013-03-01 11:26:41+00:00)
Title: (#17190) Provide on-demand profiling of catalog compiles

The previous version of the catalog compile timings use the
Puppet::Util#benchmark system, which did not allow turning it on and off.
This replaces that system with the Puppet::Util::Profiler and provides a
parameter for requests called "profile" that can be used to perform a
profiled run.

Currently this logs to the debug output, but in the future could
reasonably send the profiling information elsewhere so that the user does
not need to have debug logging enabled in order to get profiling
information.

An example of how to use this. After a node has checked in and the master
has stored the facts for the node make another request from the command
line:

curl -k -H "Accept: yaml" \
'https://localhost:8140/production/catalog/aparker?profile'

The "?profile" is the signal to output the profiling information. The
master will output a log that looks like:

````
Debug: [2166677060] 1.3.6.2 Iterated (2) on generators in 0.0002 seconds
Debug: [2166677060] 1.3.6 Compile: Evaluated generators in 0.0012 seconds
Debug: [2166677060] 1.3.7 Compile: Finished catalog in 0.0004 seconds
Debug: [2166677060] 1.3 Compiled catalog for aparker in environment production in 0.0290 seconds
Debug: [2166677060] 1.4 Filtered result for catalog aparker in 0.0005 seconds
Debug: [2166677060] 1.5 Rendered result in Puppet::Network::Format[yaml] in 0.0047 seconds
Debug: [2166677060] 1.6 Sent response in 0.0000 seconds
Debug: [2166677060] 1 Processed request GET /production/catalog/aparker in 0.0896 seconds
````

The outline style number that preceeds every line is to provide nesting
information. Ideally the time of the nested components should add up to
the higher level time.