Time how long calls to _get_destination_retry_timings take

This commit is contained in:
Erik Johnston 2015-01-06 15:22:28 +00:00
parent 52b2c6c9c7
commit 03a501456c
2 changed files with 64 additions and 12 deletions

View file

@ -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,))

View file

@ -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