From 621386b121dd6b3befd531ed72cca9293b463c41 Mon Sep 17 00:00:00 2001 From: Folker Bernitt Date: Tue, 2 Feb 2016 14:47:11 +0100 Subject: Log some times to identify very slow parts --- .../pixelated/adapter/mailstore/leap_mailstore.py | 26 +-------------- service/pixelated/adapter/search/__init__.py | 3 +- service/pixelated/adapter/services/mail_service.py | 3 ++ service/pixelated/resources/__init__.py | 2 ++ service/pixelated/resources/mails_resource.py | 30 +++++++++++++---- service/pixelated/support/__init__.py | 39 ++++++++++++++++++++++ 6 files changed, 71 insertions(+), 32 deletions(-) diff --git a/service/pixelated/adapter/mailstore/leap_mailstore.py b/service/pixelated/adapter/mailstore/leap_mailstore.py index 98758d1f..6cbbe10a 100644 --- a/service/pixelated/adapter/mailstore/leap_mailstore.py +++ b/service/pixelated/adapter/mailstore/leap_mailstore.py @@ -14,10 +14,7 @@ # You should have received a copy of the GNU Affero General Public License # along with Pixelated. If not, see . import re -import logging -import time from email.header import decode_header -from functools import wraps from uuid import uuid4 from leap.mail.adaptors.soledad import SoledadMailAdaptor @@ -28,12 +25,10 @@ from twisted.internet.defer import FirstError, DeferredList from pixelated.adapter.mailstore.body_parser import BodyParser from pixelated.adapter.mailstore.mailstore import MailStore, underscore_uuid from pixelated.adapter.model.mail import Mail, InputMail +from pixelated.support import log_time_deferred from pixelated.support.functional import to_unicode -log = logging.getLogger(__name__) - - class AttachmentInfo(object): def __init__(self, ident, name, encoding=None, ctype='application/octet-stream', size=0): self.ident = ident @@ -193,25 +188,6 @@ def _extract_filename_from_name_header_part(header_value): return filename -def log_time_deferred(f): - - def log_time(result, start): - log.info('after callback: Needed %f ms to execute %s' % ((time.clock() - start), f)) - return result - - @wraps(f) - def wrapper(*args, **kwds): - start = time.clock() - result = f(*args, **kwds) - if isinstance(result, defer.Deferred): - result.addCallback(log_time, start=start) - else: - log.warn('No Deferred returned, perhaps need to re-order annotations?') - return result - - return wrapper - - class LeapMailStore(MailStore): __slots__ = ('soledad') diff --git a/service/pixelated/adapter/search/__init__.py b/service/pixelated/adapter/search/__init__.py index 35087101..e137b392 100644 --- a/service/pixelated/adapter/search/__init__.py +++ b/service/pixelated/adapter/search/__init__.py @@ -13,7 +13,7 @@ # # You should have received a copy of the GNU Affero General Public License # along with Pixelated. If not, see . - +from pixelated.support import log_time from pixelated.support.encrypted_file_storage import EncryptedFileStorage import os @@ -172,6 +172,7 @@ class SearchEngine(object): results = searcher.search(query, **options) return results + @log_time def search(self, query, window=25, page=1, all_mails=False): query = self.prepare_query(query) return self._search_all_mails(query) if all_mails else self._paginated_search_mails(query, window, page) diff --git a/service/pixelated/adapter/services/mail_service.py b/service/pixelated/adapter/services/mail_service.py index bfe45cad..2da2cca6 100644 --- a/service/pixelated/adapter/services/mail_service.py +++ b/service/pixelated/adapter/services/mail_service.py @@ -25,6 +25,8 @@ from pixelated.adapter.model.status import Status from pixelated.adapter.services.tag_service import extract_reserved_tags from leap.mail.adaptors.soledad import SoledadMailAdaptor +from pixelated.support import log_time_deferred + class MailService(object): @@ -43,6 +45,7 @@ class MailService(object): def save_attachment(self, content, content_type): return self.attchment_store.add_attachment(content, content_type) + @log_time_deferred @defer.inlineCallbacks def mails(self, query, window_size, page): mail_ids, total = self.search_engine.search(query, window_size, page) diff --git a/service/pixelated/resources/__init__.py b/service/pixelated/resources/__init__.py index 06fcbe54..2e451a69 100644 --- a/service/pixelated/resources/__init__.py +++ b/service/pixelated/resources/__init__.py @@ -21,6 +21,7 @@ from twisted.web.resource import Resource # from pixelated.resources.login_resource import LoginResource from pixelated.resources.session import IPixelatedSession +from pixelated.support import log_time class SetEncoder(json.JSONEncoder): @@ -37,6 +38,7 @@ def respond_json(entity, request, status_code=200): return json_response +@log_time def respond_json_deferred(entity, request, status_code=200): json_response = json.dumps(entity, cls=SetEncoder) request.responseHeaders.addRawHeader(b"content-type", b"application/json") diff --git a/service/pixelated/resources/mails_resource.py b/service/pixelated/resources/mails_resource.py index c81cbd3b..7b5d1af4 100644 --- a/service/pixelated/resources/mails_resource.py +++ b/service/pixelated/resources/mails_resource.py @@ -1,4 +1,6 @@ +import time import json +import logging from pixelated.adapter.services.mail_sender import SMTPDownException from pixelated.adapter.model.mail import InputMail from twisted.web.server import NOT_DONE_YET @@ -9,9 +11,13 @@ from twisted.internet import defer from twisted.python.log import err from leap.common import events +from pixelated.support import log_time from pixelated.support.functional import to_unicode +log = logging.getLogger(__name__) + + class MailsUnreadResource(Resource): isLeaf = True @@ -139,19 +145,31 @@ class MailsResource(BaseResource): if action == 'unread': return MailsUnreadResource(_mail_service) + @log_time + def _build_mails_response(self, (mails, total)): + return { + "stats": { + "total": total, + }, + "mails": [mail.as_dict() for mail in mails] + } + def render_GET(self, request): + start = time.clock() + + def log_after_completion(result, start): + end = time.clock() + log.info('Needed %f ms to render response' % (end - start)) + return result + _mail_service = self.mail_service(request) query, window_size, page = request.args.get('q')[0], request.args.get('w')[0], request.args.get('p')[0] unicode_query = to_unicode(query) d = _mail_service.mails(unicode_query, window_size, page) - d.addCallback(lambda (mails, total): { - "stats": { - "total": total, - }, - "mails": [mail.as_dict() for mail in mails] - }) + d.addCallback(self._build_mails_response) d.addCallback(lambda res: respond_json_deferred(res, request)) + d.addCallback(log_after_completion, start=start) def error_handler(error): print error diff --git a/service/pixelated/support/__init__.py b/service/pixelated/support/__init__.py index 2756a319..80ecaa2e 100644 --- a/service/pixelated/support/__init__.py +++ b/service/pixelated/support/__init__.py @@ -13,3 +13,42 @@ # # You should have received a copy of the GNU Affero General Public License # along with Pixelated. If not, see . +import time +import logging +from functools import wraps +from twisted.internet import defer + + +log = logging.getLogger(__name__) + + +def log_time(f): + + @wraps(f) + def wrapper(*args, **kwds): + start = time.clock() + result = f(*args, **kwds) + log.info('Needed %f ms to execute %s' % ((time.clock() - start), f)) + + return result + + return wrapper + + +def log_time_deferred(f): + + def log_time(result, start): + log.info('after callback: Needed %f ms to execute %s' % ((time.clock() - start), f)) + return result + + @wraps(f) + def wrapper(*args, **kwds): + start = time.clock() + result = f(*args, **kwds) + if isinstance(result, defer.Deferred): + result.addCallback(log_time, start=start) + else: + log.warn('No Deferred returned, perhaps need to re-order annotations?') + return result + + return wrapper -- cgit v1.2.3