diff --git a/tldp/doctypes/common.py b/tldp/doctypes/common.py index 8ad5ecd..f8f17ca 100644 --- a/tldp/doctypes/common.py +++ b/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__ diff --git a/tldp/utils.py b/tldp/utils.py index 98bac0d..baa8a24 100644 --- a/tldp/utils.py +++ b/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: