Core: collect more performance statistics

4 files changed, 76 insertions, 36 deletions

diff --git a/src/lib/Bcfg2/Server/BuiltinCore.py b/src/lib/Bcfg2/Server/BuiltinCore.py
index b433595b9..d15c4eebc 100644
--- a/src/lib/Bcfg2/Server/BuiltinCore.py
+++ b/src/lib/Bcfg2/Server/BuiltinCore.py
@@ -55,8 +55,7 @@ class Core(BaseCore):
             try:
                 result = method_func(*args)
             finally:
-                self.instance_statistics.add_value(method,
-                                                   time.time() - method_start)
+                self.stats.add_value(method, time.time() - method_start)
         except xmlrpclib.Fault:
             raise
         except Exception:
diff --git a/src/lib/Bcfg2/Server/CherryPyCore.py b/src/lib/Bcfg2/Server/CherryPyCore.py
index e6023173a..60dec88c0 100644
--- a/src/lib/Bcfg2/Server/CherryPyCore.py
+++ b/src/lib/Bcfg2/Server/CherryPyCore.py
@@ -80,8 +80,7 @@ class Core(BaseCore):
         try:
             body = handler(*rpcparams, **params)
         finally:
-            self.instance_statistics.add_value(rpcmethod,
-                                               time.time() - method_start)
+            self.stats.add_value(rpcmethod, time.time() - method_start)
         
         xmlrpcutil.respond(body, 'utf-8', True)
         return cherrypy.serving.response.body
diff --git a/src/lib/Bcfg2/Server/Core.py b/src/lib/Bcfg2/Server/Core.py
index 4ff0d2b98..e7ff2552a 100644
--- a/src/lib/Bcfg2/Server/Core.py
+++ b/src/lib/Bcfg2/Server/Core.py
@@ -30,6 +30,28 @@ def exposed(func):
     func.exposed = True
     return func
 
+class track_statistics(object):
+    """ decorator that tracks execution time for the given
+    function """
+
+    def __init__(self, name=None):
+        self.name = name
+
+    def __call__(self, func):
+        if self.name is None:
+            self.name = func.__name__
+
+        def inner(obj, *args, **kwargs):
+            name = "%s:%s" % (obj.__class__.__name__, self.name)
+
+            start = time.time()
+            try:
+                return func(obj, *args, **kwargs)
+            finally:
+                obj.stats.add_value(name, time.time() - start)
+
+        return inner
+
 def sort_xml(node, key=None):
     for child in node:
         sort_xml(child, key)
@@ -175,7 +197,7 @@ class BaseCore(object):
             self.fam_thread.start()
             self.fam.AddMonitor(self.cfile, self.setup)
 
-        self.instance_statistics = Statistics()
+        self.stats = Statistics()
 
     def plugins_by_type(self, base_cls):
         """Return a list of loaded plugins that match the passed type.
@@ -248,19 +270,26 @@ class BaseCore(object):
 
     def client_run_hook(self, hook, metadata):
         """Checks the data structure."""
-        for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.ClientRunHooks):
-            try:
-                getattr(plugin, hook)(metadata)
-            except AttributeError:
-                err = sys.exc_info()[1]
-                self.logger.error("Unknown attribute: %s" % err)
-                raise
-            except:
-                err = sys.exc_info()[1]
-                self.logger.error("%s: Error invoking hook %s: %s" % (plugin,
-                                                                      hook,
-                                                                      err))
-
+        start = time.time()
+        try:
+            for plugin in \
+                    self.plugins_by_type(Bcfg2.Server.Plugin.ClientRunHooks):
+                try:
+                    getattr(plugin, hook)(metadata)
+                except AttributeError:
+                    err = sys.exc_info()[1]
+                    self.logger.error("Unknown attribute: %s" % err)
+                    raise
+                except:
+                    err = sys.exc_info()[1]
+                    self.logger.error("%s: Error invoking hook %s: %s" %
+                                      (plugin, hook, err))
+        finally:
+            self.stats.add_value("%s:client_run_hook:%s" %
+                                 (self.__class__.__name__, hook),
+                                 time.time() - start)
+
+    @track_statistics()
     def validate_structures(self, metadata, data):
         """Checks the data structure."""
         for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.StructureValidator):
@@ -275,6 +304,7 @@ class BaseCore(object):
                 self.logger.error("Plugin %s: unexpected structure validation "
                                   "failure" % plugin.name, exc_info=1)
 
+    @track_statistics()
     def validate_goals(self, metadata, data):
         """Checks that the config matches the goals enforced by the plugins."""
         for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.GoalValidator):
@@ -289,6 +319,7 @@ class BaseCore(object):
                 self.logger.error("Plugin %s: unexpected goal validation "
                                   "failure" % plugin.name, exc_info=1)
 
+    @track_statistics()
     def GetStructures(self, metadata):
         """Get all structures for client specified by metadata."""
         structures = reduce(lambda x, y: x + y,
@@ -301,6 +332,16 @@ class BaseCore(object):
                               (metadata.hostname, ':'.join(missing)))
         return structures
 
+    @track_statistics()
+    def BindStructures(self, structures, metadata, config):
+        for astruct in structures:
+            try:
+                self.BindStructure(astruct, metadata)
+                config.append(astruct)
+            except:
+                self.logger.error("error in BindStructure", exc_info=1)
+
+    @track_statistics()
     def BindStructure(self, structure, metadata):
         """Bind a complete structure."""
         for entry in structure.getchildren():
@@ -324,6 +365,7 @@ class BaseCore(object):
 
     def Bind(self, entry, metadata):
         """Bind an entry using the appropriate generator."""
+        start = time.time()
         if 'altsrc' in entry.attrib:
             oldname = entry.get('name')
             entry.set('name', entry.get('altsrc'))
@@ -353,11 +395,16 @@ class BaseCore(object):
                               (entry.tag, entry.get('name'), generators))
         g2list = [gen for gen in self.generators if
                   gen.HandlesEntry(entry, metadata)]
-        if len(g2list) == 1:
-            return g2list[0].HandleEntry(entry, metadata)
-        entry.set('failure', 'no matching generator')
-        raise PluginExecutionError("No matching generator: %s:%s" %
-                                   (entry.tag, entry.get('name')))
+        try:
+            if len(g2list) == 1:
+                return g2list[0].HandleEntry(entry, metadata)
+            entry.set('failure', 'no matching generator')
+            raise PluginExecutionError("No matching generator: %s:%s" %
+                                       (entry.tag, entry.get('name')))
+        finally:
+            self.stats.add_value("%s:Bind:%s" % (self.__class__.__name__,
+                                                 entry.tag),
+                                 time.time() - start)
 
     def BuildConfiguration(self, client):
         """Build configuration for clients."""
@@ -394,12 +441,8 @@ class BaseCore(object):
                     esrcs[key] = entry.get('altsrc', None)
         del esrcs
 
-        for astruct in structures:
-            try:
-                self.BindStructure(astruct, meta)
-                config.append(astruct)
-            except:
-                self.logger.error("error in BindStructure", exc_info=1)
+        self.BindStructures(structures, meta, config)
+
         self.validate_goals(meta, config)
 
         self.client_run_hook("end_client_run", meta)
@@ -453,6 +496,7 @@ class BaseCore(object):
                                   % plugin.name, exc_info=1)
         return result
 
+    @track_statistics()
     def build_metadata(self, client_name):
         """Build the metadata structure."""
         if not hasattr(self, 'metadata'):
@@ -644,4 +688,4 @@ class BaseCore(object):
     @exposed
     def get_statistics(self, _):
         """Get current statistics about component execution"""
-        return self.instance_statistics.display()
+        return self.stats.display()
diff --git a/src/lib/Bcfg2/Statistics.py b/src/lib/Bcfg2/Statistics.py
index a0cb8f39b..bee90bbf4 100644
--- a/src/lib/Bcfg2/Statistics.py
+++ b/src/lib/Bcfg2/Statistics.py
@@ -1,4 +1,3 @@
-
 class Statistic(object):
     def __init__(self, name, initial_value):
         self.name = name
@@ -8,16 +7,15 @@ class Statistic(object):
         self.count = 1
 
     def add_value(self, value):
-        if value < self.min:
-            self.min = value
-        if value > self.max:
-            self.max = value
-        self.count += 1
+        self.min = min(self.min, value)
+        self.max = max(self.max, value)
         self.ave = (((self.ave * (self.count - 1)) + value) / self.count)
+        self.count += 1
 
     def get_value(self):
         return (self.name, (self.min, self.max, self.ave, self.count))
 
+
 class Statistics(object):
     def __init__(self):
         self.data = dict()