diff --git a/lib/puppet/util/profiler.rb b/lib/puppet/util/profiler.rb index 820231f27..a50461edd 100644 --- a/lib/puppet/util/profiler.rb +++ b/lib/puppet/util/profiler.rb @@ -1,53 +1,53 @@ require 'benchmark' # A simple profiling callback system. # # @api public module Puppet::Util::Profiler require 'puppet/util/profiler/wall_clock' require 'puppet/util/profiler/object_counts' require 'puppet/util/profiler/around_profiler' @profiler = Puppet::Util::Profiler::AroundProfiler.new # Reset the profiling system to the original state # # @api private def self.clear @profiler.clear end # Retrieve the current list of profilers # # @api private def self.current @profiler.current end # @param profiler [#profile] A profiler for the current thread # @api private def self.add_profiler(profiler) @profiler.add_profiler(profiler) end # @param profiler [#profile] A profiler to remove from the current thread # @api private def self.remove_profiler(profiler) @profiler.remove_profiler(profiler) end # Profile a block of code and log the time it took to execute. # # This outputs logs entries to the Puppet masters logging destination # providing the time it took, a message describing the profiled code # and a leaf location marking where the profile method was called # in the profiled hierachy. # # @param message [String] A description of the profiled event # @param metric_id [Array] A list of strings making up the ID of a metric to profile # @param block [Block] The segment of code to profile # @api public - def self.profile(message, metric_id = nil, &block) + def self.profile(message, metric_id, &block) @profiler.profile(message, metric_id, &block) end end diff --git a/lib/puppet/util/profiler/around_profiler.rb b/lib/puppet/util/profiler/around_profiler.rb index 0b408c6d8..b2cf04998 100644 --- a/lib/puppet/util/profiler/around_profiler.rb +++ b/lib/puppet/util/profiler/around_profiler.rb @@ -1,67 +1,67 @@ # A Profiler that can be used to wrap around blocks of code. It is configured # with other profilers and controls them to start before the block is executed # and finish after the block is executed. # # @api private class Puppet::Util::Profiler::AroundProfiler def initialize @profilers = [] end # Reset the profiling system to the original state # # @api private def clear @profilers = [] end # Retrieve the current list of profilers # # @api private def current @profilers end # @param profiler [#profile] A profiler for the current thread # @api private def add_profiler(profiler) @profilers << profiler profiler end # @param profiler [#profile] A profiler to remove from the current thread # @api private def remove_profiler(profiler) @profilers.delete(profiler) end # Profile a block of code and log the time it took to execute. # # This outputs logs entries to the Puppet masters logging destination # providing the time it took, a message describing the profiled code # and a leaf location marking where the profile method was called # in the profiled hierachy. # # @param message [String] A description of the profiled event # @param metric_id [Array] A list of strings making up the ID of a metric to profile # @param block [Block] The segment of code to profile # @api private - def profile(message, metric_id = nil) + def profile(message, metric_id) retval = nil contexts = {} @profilers.each do |profiler| contexts[profiler] = profiler.start(message, metric_id) end begin retval = yield ensure @profilers.each do |profiler| profiler.finish(contexts[profiler], message, metric_id) end end retval end end diff --git a/spec/unit/util/profiler/aggregate_spec.rb b/spec/unit/util/profiler/aggregate_spec.rb index 8d38d4673..6a70a4b2e 100644 --- a/spec/unit/util/profiler/aggregate_spec.rb +++ b/spec/unit/util/profiler/aggregate_spec.rb @@ -1,59 +1,55 @@ require 'spec_helper' require 'puppet/util/profiler' require 'puppet/util/profiler/around_profiler' require 'puppet/util/profiler/aggregate' describe Puppet::Util::Profiler::Aggregate do let(:logger) { AggregateSimpleLog.new } let(:profiler) { Puppet::Util::Profiler::Aggregate.new(logger, nil) } let(:profiler_mgr) do p = Puppet::Util::Profiler::AroundProfiler.new p.add_profiler(profiler) p end it "tracks the aggregate counts and time for the hierarchy of metrics" do profiler_mgr.profile("Looking up hiera data in production environment", ["function", "hiera_lookup", "production"]) { sleep 0.01 } profiler_mgr.profile("Looking up hiera data in test environment", ["function", "hiera_lookup", "test"]) {} profiler_mgr.profile("looking up stuff for compilation", ["compiler", "lookup"]) { sleep 0.01 } profiler_mgr.profile("COMPILING ALL OF THE THINGS!", ["compiler", "compiling"]) {} profiler.values["function"].count.should == 2 profiler.values["function"].time.should be > 0 profiler.values["function"]["hiera_lookup"].count.should == 2 profiler.values["function"]["hiera_lookup"]["production"].count.should == 1 profiler.values["function"]["hiera_lookup"]["test"].count.should == 1 profiler.values["function"].time.should be >= profiler.values["function"]["hiera_lookup"]["test"].time profiler.values["compiler"].count.should == 2 profiler.values["compiler"].time.should be > 0 profiler.values["compiler"]["lookup"].count.should == 1 profiler.values["compiler"]["compiling"].count.should == 1 profiler.values["compiler"].time.should be >= profiler.values["compiler"]["lookup"].time profiler.shutdown logger.output.should =~ /function -> hiera_lookup: .*\(2 calls\)\nfunction -> hiera_lookup ->.*\(1 calls\)/ logger.output.should =~ /compiler: .*\(2 calls\)\ncompiler ->.*\(1 calls\)/ end - it "tolerates calls to `profile` that don't include a metric id" do - profiler_mgr.profile("yo") {} - end - it "supports both symbols and strings as components of a metric id" do profiler_mgr.profile("yo", [:foo, "bar"]) {} end class AggregateSimpleLog attr_reader :output def initialize @output = "" end def call(msg) @output << msg << "\n" end end end diff --git a/spec/unit/util/profiler_spec.rb b/spec/unit/util/profiler_spec.rb index c7fc48cb9..7ef70c240 100644 --- a/spec/unit/util/profiler_spec.rb +++ b/spec/unit/util/profiler_spec.rb @@ -1,55 +1,47 @@ require 'spec_helper' require 'puppet/util/profiler' describe Puppet::Util::Profiler do let(:profiler) { TestProfiler.new() } it "supports adding profilers" do subject.add_profiler(profiler) subject.current[0].should == profiler end it "supports removing profilers" do subject.add_profiler(profiler) subject.remove_profiler(profiler) subject.current.length.should == 0 end it "supports clearing profiler list" do subject.add_profiler(profiler) subject.clear subject.current.length.should == 0 end it "supports profiling" do subject.add_profiler(profiler) subject.profile("hi", ["mymetric"]) {} profiler.context[:metric_id].should == ["mymetric"] profiler.context[:description].should == "hi" profiler.description.should == "hi" end - it "supports profiling without a metric id" do - subject.add_profiler(profiler) - subject.profile("hi") {} - profiler.context[:metric_id].should == nil - profiler.context[:description].should == "hi" - profiler.description.should == "hi" - end - class TestProfiler attr_accessor :context, :metric, :description def start(description, metric_id) {:metric_id => metric_id, :description => description} end def finish(context, description, metric_id) @context = context @metric_id = metric_id @description = description end end end