Time how long calls to _get_destination_retry_timings take

1 files changed, 61 insertions, 12 deletions

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