Log some times to identify very slow parts

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 <http://www.gnu.org/licenses/>.
 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 <http://www.gnu.org/licenses/>.
-
+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 <http://www.gnu.org/licenses/>.
+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