adding timing to a few methods

tldp/doctypes/common.py

@@ -11,7 +11,7 @@ from tempfile import NamedTemporaryFile as ntf
 from functools import wraps
 import networkx as nx
 
-from tldp.utils import execute
+from tldp.utils import execute, logtimings
 
 logger = logging.getLogger(__name__)
 
@@ -98,6 +98,7 @@ class BaseDoctype(object):
     def hook_build_failure(self):
         self.cleanup()
 
+    @logtimings(logger.debug)
     def shellscript(self, script, preamble=preamble, postamble=postamble):
         source = self.source
         output = self.output
@@ -127,6 +128,7 @@ class BaseDoctype(object):
             return False
         return True
 
+    @logtimings(logger.debug)
     def buildall(self):
         stem = self.source.stem
         order = nx.dag.topological_sort(self.graph)
@@ -142,6 +144,7 @@ class BaseDoctype(object):
                 return False
         return True
 
+    @logtimings(logger.info)
     def generate(self):
         stem = self.source.stem
         classname = self.__class__.__name__

tldp/utils.py

@@ -6,10 +6,12 @@ from __future__ import absolute_import, division, print_function
 import os
 import io
 import sys
+import time
 import errno
 import operator
 import subprocess
 import functools
+from functools import wraps
 from tempfile import mkstemp
 import logging
 logger = logging.getLogger(__name__)
@@ -17,6 +19,20 @@ logger = logging.getLogger(__name__)
 logdir = 'tldp-document-build-logs'
 
 
+def logtimings(logmethod):
+    def anon(f):
+        @wraps(f)
+        def timedfunc(*args, **kwargs):
+            s = time.time()
+            result = f(*args, **kwargs)
+            e = time.time()
+            logmethod('running %s(%r, %r) took %.3f s',
+                      f.__name__, args, kwargs, e - s)
+            return result
+        return timedfunc
+    return anon
+
+
 def firstfoundfile(locations):
     '''return the first existing file from a list of filenames (or None)'''
     for option in locations: