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
|
