From adb04b1e572d13b75541f4684aac3683e94d70b8 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 6 Jan 2015 13:21:39 +0000 Subject: Update copyright notices --- synapse/storage/transactions.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'synapse/storage/transactions.py') diff --git a/synapse/storage/transactions.py b/synapse/storage/transactions.py index 423cc3f02a..e06ef35690 100644 --- a/synapse/storage/transactions.py +++ b/synapse/storage/transactions.py @@ -1,5 +1,5 @@ # -*- coding: utf-8 -*- -# Copyright 2014 OpenMarket Ltd +# Copyright 2014, 2015 OpenMarket Ltd # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. -- cgit 1.4.1 From 03a501456ca8815a7d6fd8ea84d9c2a1feba33cf Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 6 Jan 2015 15:22:28 +0000 Subject: Time how long calls to _get_destination_retry_timings take --- synapse/storage/transactions.py | 3 ++ synapse/util/logutils.py | 73 ++++++++++++++++++++++++++++++++++------- 2 files changed, 64 insertions(+), 12 deletions(-) (limited to 'synapse/storage/transactions.py') 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 -- cgit 1.4.1 From 9bd07bed238337151ae79dc948f49cdf7141578c Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 6 Jan 2015 15:28:56 +0000 Subject: Actually time that function --- synapse/storage/transactions.py | 1 + 1 file changed, 1 insertion(+) (limited to 'synapse/storage/transactions.py') diff --git a/synapse/storage/transactions.py b/synapse/storage/transactions.py index 36ddf30d65..9d14f89303 100644 --- a/synapse/storage/transactions.py +++ b/synapse/storage/transactions.py @@ -200,6 +200,7 @@ class TransactionStore(SQLBaseStore): self._get_transactions_after, transaction_id, destination ) + @time_function def _get_transactions_after(cls, txn, transaction_id, destination): where = ( "destination = ? AND id > (select id FROM %s WHERE " -- cgit 1.4.1 From f6da237c353d598946a6c81260653203602800c2 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 6 Jan 2015 15:40:38 +0000 Subject: Add index on transaction_id to sent_transcations --- synapse/storage/schema/transactions.sql | 1 + synapse/storage/transactions.py | 4 ---- 2 files changed, 1 insertion(+), 4 deletions(-) (limited to 'synapse/storage/transactions.py') diff --git a/synapse/storage/schema/transactions.sql b/synapse/storage/schema/transactions.sql index 86f530d82a..2d30f99b06 100644 --- a/synapse/storage/schema/transactions.sql +++ b/synapse/storage/schema/transactions.sql @@ -42,6 +42,7 @@ CREATE INDEX IF NOT EXISTS sent_transaction_dest ON sent_transactions(destinatio CREATE INDEX IF NOT EXISTS sent_transaction_dest_referenced ON sent_transactions( destination ); +CREATE INDEX IF NOT EXISTS sent_transaction_txn_id ON sent_transactions(transaction_id); -- So that we can do an efficient look up of all transactions that have yet to be successfully -- sent. CREATE INDEX IF NOT EXISTS sent_transaction_sent ON sent_transactions(response_code); diff --git a/synapse/storage/transactions.py b/synapse/storage/transactions.py index 9d14f89303..e06ef35690 100644 --- a/synapse/storage/transactions.py +++ b/synapse/storage/transactions.py @@ -19,8 +19,6 @@ from collections import namedtuple from twisted.internet import defer -from synapse.util.logutils import time_function - import logging logger = logging.getLogger(__name__) @@ -200,7 +198,6 @@ class TransactionStore(SQLBaseStore): self._get_transactions_after, transaction_id, destination ) - @time_function def _get_transactions_after(cls, txn, transaction_id, destination): where = ( "destination = ? AND id > (select id FROM %s WHERE " @@ -231,7 +228,6 @@ 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,)) -- cgit 1.4.1