Adding simple benchmarking, and using it in a few of the more obvious places. Also, fixed a bug in Scope#gennode.

git-svn-id: https://reductivelabs.com/svn/puppet/trunk@1098 980ebf18-57e1-0310-9a29-db15c13687c0

8 files changed, 138 insertions, 57 deletions

diff --git a/lib/puppet/client.rb b/lib/puppet/client.rb
index 200834dc5..ae7449240 100644
--- a/lib/puppet/client.rb
+++ b/lib/puppet/client.rb
@@ -11,12 +11,15 @@ module Puppet
         include Puppet
         include SignalObserver
 
+        include Puppet::Util
+
+
         # FIXME The cert stuff should only come up with networking, so it
         # should be in the network client, not the normal client.  But if i do
         # that, it's hard to tell whether the certs have been initialized.
         include Puppet::Daemon
         attr_reader :secureinit
-        attr_accessor :schedule, :lastrun, :local
+        attr_accessor :schedule, :lastrun, :local, :stopping
 
         class << self
             attr_reader :drivername
@@ -85,6 +88,10 @@ module Puppet
 
         # A wrapper method to run and then store the last run time
         def runnow
+            if self.stopping
+                Puppet.notice "In shutdown progress; skipping run"
+                return
+            end
             begin
                 self.run
                 self.lastrun = Time.now.to_i
@@ -112,9 +119,15 @@ module Puppet
             @driver.ca_file = @cacertfile
         end
 
+        # FIXME this should probably not store every single time.
         def shutdown
-            Puppet::Storage.store
-            exit
+            if self.stopping
+                Puppet.notice "Already in shutdown"
+            else
+                self.stopping = true
+                Puppet::Storage.store
+                exit
+            end
         end
 
         # Start listening for events.  We're pretty much just listening for
diff --git a/lib/puppet/client/master.rb b/lib/puppet/client/master.rb
index 390c07220..6c30a4431 100644
--- a/lib/puppet/client/master.rb
+++ b/lib/puppet/client/master.rb
@@ -26,9 +26,6 @@ class Puppet::Client::MasterClient < Puppet::Client
     # objects.  For now, just descend into the tree and perform and
     # necessary manipulations.
     def apply
-        unless @local
-            Puppet.notice "Beginning configuration run"
-        end
         dostorage()
         unless defined? @objects
             raise Puppet::Error, "Cannot apply; objects not defined"
@@ -67,9 +64,6 @@ class Puppet::Client::MasterClient < Puppet::Client
             Metric.store
             Metric.graph
         end
-        unless @local
-            Puppet.notice "Finished configuration run"
-        end
 
         return transaction
     end
@@ -181,16 +175,18 @@ class Puppet::Client::MasterClient < Puppet::Client
 
             textfacts = CGI.escape(YAML.dump(facts))
 
-            # error handling for this is done in the network client
-            begin
-                textobjects = @driver.getconfig(textfacts, "yaml")
-            rescue => detail
-                Puppet.err "Could not retrieve configuration: %s" % detail
-
-                unless Puppet[:usecacheonfailure]
-                    @objects = nil
-                    Puppet.warning "Not using cache on failed configuration"
-                    return
+            benchmark(:debug, "Retrieved configuration") do
+                # error handling for this is done in the network client
+                begin
+                    textobjects = @driver.getconfig(textfacts, "yaml")
+                rescue => detail
+                    Puppet.err "Could not retrieve configuration: %s" % detail
+
+                    unless Puppet[:usecacheonfailure]
+                        @objects = nil
+                        Puppet.warning "Not using cache on failed configuration"
+                        return
+                    end
                 end
             end
 
@@ -275,7 +271,12 @@ class Puppet::Client::MasterClient < Puppet::Client
             self.getconfig
 
             if defined? @objects and @objects
-                self.apply
+                unless @local
+                    Puppet.notice "Starting configuration run"
+                end
+                benchmark(:notice, "Finished configuration run") do
+                    self.apply
+                end
             end
         end
     end
diff --git a/lib/puppet/parser/interpreter.rb b/lib/puppet/parser/interpreter.rb
index 35c122c43..5f5ecbe1f 100644
--- a/lib/puppet/parser/interpreter.rb
+++ b/lib/puppet/parser/interpreter.rb
@@ -10,6 +10,8 @@ require 'puppet/parser/scope'
 module Puppet
     module Parser
         class Interpreter
+            include Puppet::Util
+
             Puppet.setdefaults("ldap",
                 :ldapnodes => [false,
                     "Whether to search for node configurations in LDAP."],
@@ -107,7 +109,7 @@ module Puppet
                     end
 
                     if nodeclasses
-                        Puppet.info "Found %s in %s" % [client, source]
+                        Puppet.info "Found %s in %s" % [node, source]
                         return parent, nodeclasses
                     end
                 end
@@ -206,12 +208,11 @@ module Puppet
                             "Cannot evaluate nodes with a nil client"
                     end
 
-                    Puppet.debug "Nodes defined"
                     args[:names] = names
 
                     parent, nodeclasses = nodesearch(client)
 
-                    classes += nodeclasses if nodeclasses
+                    args[:classes] += nodeclasses if nodeclasses
 
                     args[:parentnode] = parent if parent
                 end
@@ -290,7 +291,10 @@ module Puppet
                 else
                     @parser.file = @file
                 end
-                @ast = @parser.parse
+
+                @ast = benchmark(:info, "Parsed manifest") do
+                    @parser.parse
+                end
 
                 # Mark when we parsed, so we can check freshness
                 @parsedate = Time.now.to_i
diff --git a/lib/puppet/parser/scope.rb b/lib/puppet/parser/scope.rb
index 35137fda7..27de8ffd8 100644
--- a/lib/puppet/parser/scope.rb
+++ b/lib/puppet/parser/scope.rb
@@ -297,13 +297,18 @@ module Puppet::Parser
                 raise Puppet::DevError, "Node names must be provided to gennode"
             facts = hash[:facts]
             classes = hash[:classes]
-            parent = hash[:parent]
+            parent = hash[:parentnode]
             name = names.shift
             arghash = {
                 :type => name,
                 :code => AST::ASTArray.new(:pin => "[]")
             }
 
+            #Puppet.notice "hash is %s" %
+            #    hash.inspect
+            Puppet.notice "Classes are %s, parent is %s" %
+                [classes.inspect, parent.inspect]
+
             if parent
                 arghash[:parentclass] = parent
             end
diff --git a/lib/puppet/server/master.rb b/lib/puppet/server/master.rb
index 7e719452f..719b115ac 100644
--- a/lib/puppet/server/master.rb
+++ b/lib/puppet/server/master.rb
@@ -9,6 +9,8 @@ module Puppet
 class Server
     class MasterError < Puppet::Error; end
     class Master < Handler
+        include Puppet::Util
+
         attr_accessor :ast, :local
         attr_reader :ca
 
@@ -66,8 +68,8 @@ class Server
                 args[:UseNodes] = false
             end
 
-            # This is only used by the cfengine module, or if --loadclasses was specified
-            # in +puppet+.
+            # This is only used by the cfengine module, or if --loadclasses was
+            # specified in +puppet+.
             if hash.include?(:Classes)
                 args[:Classes] = hash[:Classes]
             end
@@ -113,19 +115,36 @@ class Server
                 clientip = facts["ipaddress"]
             end
 
-            unless @local
-                Puppet.notice("Compiling configuration for %s" % client)
-            end
-            begin
-                retobjects = @interpreter.run(client, facts)
-            rescue Puppet::Error => detail
-                Puppet.err detail
-                raise XMLRPC::FaultException.new(
-                    1, detail.to_s
-                )
-            rescue => detail
-                Puppet.err detail.to_s
-                return ""
+            retobjects = nil
+
+            # This is hackish, but there's no "silence" option for benchmarks
+            # right now
+            if @local
+                begin
+                    retobjects = @interpreter.run(client, facts)
+                rescue Puppet::Error => detail
+                    Puppet.err detail
+                    raise XMLRPC::FaultException.new(
+                        1, detail.to_s
+                    )
+                rescue => detail
+                    Puppet.err detail.to_s
+                    return ""
+                end
+            else
+                benchmark(:notice, "Compiled configuration for %s" % client) do
+                    begin
+                        retobjects = @interpreter.run(client, facts)
+                    rescue Puppet::Error => detail
+                        Puppet.err detail
+                        raise XMLRPC::FaultException.new(
+                            1, detail.to_s
+                        )
+                    rescue => detail
+                        Puppet.err detail.to_s
+                        return ""
+                    end
+                end
             end
 
             if @local
diff --git a/lib/puppet/storage.rb b/lib/puppet/storage.rb
index 2c21f9228..2fe781f03 100644
--- a/lib/puppet/storage.rb
+++ b/lib/puppet/storage.rb
@@ -6,6 +6,7 @@ module Puppet
     # a class for storing state
     class Storage
         include Singleton
+        include Puppet::Util
 
         def initialize
             self.class.load
@@ -47,19 +48,21 @@ module Puppet
                 end
                 return
             end
-            Puppet::Util.readlock(Puppet[:statefile]) do |file|
-                begin
-                    @@state = YAML.load(file)
-                rescue => detail
-                    Puppet.err "Checksumfile %s is corrupt (%s); replacing" %
-                        [Puppet[:statefile], detail]
+            Puppet::Util.benchmark(:debug, "Loaded state") do
+                Puppet::Util.readlock(Puppet[:statefile]) do |file|
                     begin
-                        File.rename(Puppet[:statefile],
-                            Puppet[:statefile] + ".bad")
-                    rescue
-                        raise Puppet::Error,
-                            "Could not rename corrupt %s; remove manually" %
-                            Puppet[:statefile]
+                        @@state = YAML.load(file)
+                    rescue => detail
+                        Puppet.err "Checksumfile %s is corrupt (%s); replacing" %
+                            [Puppet[:statefile], detail]
+                        begin
+                            File.rename(Puppet[:statefile],
+                                Puppet[:statefile] + ".bad")
+                        rescue
+                            raise Puppet::Error,
+                                "Could not rename corrupt %s; remove manually" %
+                                Puppet[:statefile]
+                        end
                     end
                 end
             end
@@ -84,10 +87,11 @@ module Puppet
                 Puppet.info "Creating state file %s" % Puppet[:statefile]
             end
 
-            Puppet::Util.writelock(Puppet[:statefile], 0660) do |file|
-                file.print YAML.dump(@@state)
+            Puppet::Util.benchmark(:debug, "Stored state") do
+                Puppet::Util.writelock(Puppet[:statefile], 0660) do |file|
+                    file.print YAML.dump(@@state)
+                end
             end
-            Puppet.debug "Stored state"
         end
     end
 end
diff --git a/lib/puppet/type/symlink.rb b/lib/puppet/type/symlink.rb
index bedd64219..e6634a2df 100755
--- a/lib/puppet/type/symlink.rb
+++ b/lib/puppet/type/symlink.rb
@@ -102,8 +102,6 @@ module Puppet
         copyparam(Puppet.type(:file), :path)
 
         newparam(:recurse) do
-            attr_reader :setparent
-
             desc "If target is a directory, recursively create
                 directories (using `file`'s `source` parameter) and link all
                 contained files.  For instance::
diff --git a/lib/puppet/util.rb b/lib/puppet/util.rb
index e842ffd3f..7da32e280 100644
--- a/lib/puppet/util.rb
+++ b/lib/puppet/util.rb
@@ -5,6 +5,8 @@ require 'puppet/lock'
 
 module Puppet
 module Util
+    require 'benchmark'
+
     # Create a sync point for any threads
     @@sync = Sync.new
     # Execute a block as a given user or group
@@ -301,6 +303,41 @@ module Util
             File.umask(cur)
         end
     end
+
+    def benchmark(*args)
+        msg = args.pop
+        level = args.pop
+        object = nil
+
+        if args.empty?
+            object = Puppet
+        else
+            object = args.pop
+        end
+
+        unless level
+            puts caller.join("\n")
+            raise Puppet::DevError, "Failed to provide level"
+        end
+
+        unless object.respond_to? level
+            raise Puppet::DevError, "Benchmarked object does not respond to %s" % level
+        end
+
+        # Only benchmark if our log level is high enough
+        if Puppet::Log.sendlevel?(level)
+            result = nil
+            seconds = Benchmark.realtime {
+                result = yield
+            }
+            object.send(level, msg + (" in %0.2f seconds" % seconds))
+            result
+        else
+            yield
+        end
+    end
+
+    module_function :benchmark
 end
 end