Time how long calls to _get_destination_retry_timings take

2 files changed, 64 insertions, 12 deletions

diff --git a/synapse/storage/transactions.py b/synapse/storage/transactions.py
index e06ef35690..36ddf30d65 100644
--- a/synapse/storage/transactions.py
+++ b/synapse/storage/transactions.py
@@ -19,6 +19,8 @@ from collections import namedtuple
 
 from twisted.internet import defer
 
+from synapse.util.logutils import time_function
+
 import logging
 
 logger = logging.getLogger(__name__)
@@ -228,6 +230,7 @@ class TransactionStore(SQLBaseStore):
             "get_destination_retry_timings",
             self._get_destination_retry_timings, destination)
 
+    @time_function
     def _get_destination_retry_timings(cls, txn, destination):
         query = DestinationsTable.select_statement("destination = ?")
         txn.execute(query, (destination,))
diff --git a/synapse/util/logutils.py b/synapse/util/logutils.py
index 18ba405c47..c4dfb69c51 100644
--- a/synapse/util/logutils.py
+++ b/synapse/util/logutils.py
@@ -19,14 +19,37 @@ from functools import wraps
 
 import logging
 import inspect
+import time
+
+
+_TIME_FUNC_ID = 0
+
+
+def _log_debug_as_f(f, msg, msg_args):
+    name = f.__module__
+    logger = logging.getLogger(name)
+
+    if logger.isEnabledFor(logging.DEBUG):
+        lineno = f.func_code.co_firstlineno
+        pathname = f.func_code.co_filename
+
+        record = logging.LogRecord(
+            name=name,
+            level=logging.DEBUG,
+            pathname=pathname,
+            lineno=lineno,
+            msg=msg,
+            args=msg_args,
+            exc_info=None
+        )
+
+        logger.handle(record)
 
 
 def log_function(f):
     """ Function decorator that logs every call to that function.
     """
     func_name = f.__name__
-    lineno = f.func_code.co_firstlineno
-    pathname = f.func_code.co_filename
 
     @wraps(f)
     def wrapped(*args, **kwargs):
@@ -52,24 +75,50 @@ def log_function(f):
                 "args": ", ".join(func_args)
             }
 
-            record = logging.LogRecord(
-                name=name,
-                level=level,
-                pathname=pathname,
-                lineno=lineno,
-                msg="Invoked '%(func_name)s' with args: %(args)s",
-                args=msg_args,
-                exc_info=None
+            _log_debug_as_f(
+                f,
+                "Invoked '%(func_name)s' with args: %(args)s",
+                msg_args
             )
 
-            logger.handle(record)
-
         return f(*args, **kwargs)
 
     wrapped.__name__ = func_name
     return wrapped
 
 
+def time_function(f):
+    func_name = f.__name__
+
+    @wraps(f)
+    def wrapped(*args, **kwargs):
+        global _TIME_FUNC_ID
+        id = _TIME_FUNC_ID
+        _TIME_FUNC_ID += 1
+
+        start = time.clock() * 1000
+
+        try:
+            _log_debug_as_f(
+                f,
+                "[FUNC START] {%s-%d}",
+                (func_name, _TIME_FUNC_ID),
+            )
+
+            r = f(*args, **kwargs)
+        finally:
+            end = time.clock() * 1000
+            _log_debug_as_f(
+                f,
+                "[FUNC END] {%s-%d} %f",
+                (func_name, _TIME_FUNC_ID, end-start,),
+            )
+
+        return r
+
+    return wrapped
+
+
 def trace_function(f):
     func_name = f.__name__
     linenum = f.func_code.co_firstlineno