feat: Add request timing w/validation breakdown.

Add's full request timing with validation and routing break-outs. Also logs the request
and validation timing even if validation fails or routing otherwise errors out.

Closes #758

autopush/logging.py

@@ -165,8 +165,15 @@ def to_fields(kv):
         if ci and isinstance(ci, dict):
             msg['Fields'].update(
                 to_fields(ci.iteritems()))
-        # Add the nicely formatted message
 
+        # flatten timings into Fields
+        ti = event.get('timings')
+        if ti and isinstance(ti, dict):
+            msg["Fields"].update(
+                to_fields(ti.iteritems())
+            )
+
+        # Add the nicely formatted message
         msg["Fields"]["message"] = formatEvent(event)
         return json.dumps(msg, skipkeys=True) + "\n"
 

autopush/router/simple.py

@@ -6,10 +6,10 @@
 
 """
 import json
-import requests
 from urllib import urlencode
 from StringIO import StringIO
 
+import requests
 from boto.dynamodb2.exceptions import (
     ItemNotFound,
     ProvisionedThroughputExceededException,

autopush/tests/test_logging.py

@@ -50,10 +50,12 @@ def test_sentry_logging(self):
         pl = PushLogger.setup_logging("Autopush", sentry_dsn=True)
         pl._output = out
         _client_info = dict(key='value')
+        _timings = dict(key2='value')
 
         log.failure(format="error",
                     failure=failure.Failure(Exception("eek")),
-                    client_info=_client_info)
+                    client_info=_client_info,
+                    timings=_timings)
         self.flushLoggedErrors()
         d = Deferred()
 
@@ -70,7 +72,9 @@ def check():
             # Check that the json written actually contains the client info
             # collapsed up into 'Fields'.
             out.seek(0)
-            eq_(json.loads(out.readline())['Fields']['key'], 'value')
+            payload = json.loads(out.readline())
+            eq_(payload['Fields']['key'], 'value')
+            eq_(payload['Fields']['key2'], 'value')
             self._port.stopListening()
             pl.stop()
             d.callback(True)

autopush/tests/test_web_validation.py

@@ -72,6 +72,7 @@ def _write_validation_err(rh, errors):
         app.ui_modules = dict()
         app.ui_methods = dict()
         vr = ValidateRequest(app, request)
+        vr._timings = dict()
         vr.ap_settings = Mock()
         return vr
 
@@ -97,17 +98,19 @@ def test_validate_invalid_schema(self):
         eq_(d, {})
 
     def test_call_func_no_error(self):
+        start_time = time.time()
         mock_func = Mock()
         tv, rh = self._make_full()
         result = tv._validate_request(rh)
-        tv._call_func(result, mock_func, rh)
+        tv._call_func(result, mock_func, rh, start_time)
         mock_func.assert_called()
 
     def test_call_func_error(self):
+        start_time = time.time()
         mock_func = Mock()
         tv, rh = self._make_full(schema=InvalidSchema)
         result = tv._validate_request(rh)
-        tv._call_func(result, mock_func, rh)
+        tv._call_func(result, mock_func, rh, start_time)
         self._mock_errors.assert_called()
         eq_(len(mock_func.mock_calls), 0)
 
@@ -127,6 +130,7 @@ def get(self):
         app.ui_modules = dict()
         app.ui_methods = dict()
         vr = AHandler(app, req)
+        vr._timings = dict()
         d = Deferred()
         vr.finish = lambda: d.callback(True)
         vr.write = Mock()

autopush/web/base.py

@@ -5,6 +5,8 @@
 from attr import attrs, attrib
 from boto.dynamodb2.exceptions import ProvisionedThroughputExceededException
 from boto.exception import BotoServerError
+from marshmallow.schema import UnmarshalResult  # noqa
+from typing import Any  # noqa
 from twisted.internet.threads import deferToThread
 from twisted.logger import Logger
 
@@ -43,6 +45,7 @@ def __init__(self, schema):
         self.schema = schema
 
     def _validate_request(self, request_handler):
+        # type: (BaseWebHandler) -> UnmarshalResult
         """Validates a schema_class against a cyclone request"""
         data = {
             "headers": request_handler.request.headers,
@@ -64,12 +67,21 @@ def _call_func(self, result, func, request_handler, *args, **kwargs):
             request_handler.valid_input = output
             return func(request_handler, *args, **kwargs)
 
+    def _track_validation_timing(self, result, request_handler, start_time):
+        # type: (Any, BaseWebHandler, float) -> None
+        """Track the validation timing"""
+        request_handler._timings["validation_time"] = time.time() - start_time
+        return result
+
     def _decorator(self, func):
         @wraps(func)
         def wrapper(request_handler, *args, **kwargs):
+            start_time = time.time()
             # Wrap the handler in @cyclone.web.synchronous
             request_handler._auto_finish = False
             d = deferToThread(self._validate_request, request_handler)
+            d.addBoth(self._track_validation_timing, request_handler,
+                      start_time)
             d.addCallback(self._call_func, func, request_handler, *args,
                           **kwargs)
             d.addErrback(request_handler._overload_err)
@@ -124,9 +136,10 @@ class BaseWebHandler(BaseHandler):
     def initialize(self, ap_settings):
         """Setup basic aliases and attributes"""
         super(BaseWebHandler, self).initialize(ap_settings)
-        self.start_time = time.time()
         self.metrics = ap_settings.metrics
         self._base_tags = {}
+        self._start_time = time.time()
+        self._timings = {}
 
     def prepare(self):
         """Common request preparation"""
@@ -171,6 +184,7 @@ def _write_response(self, status_code, errno, message=None, error=None,
         if headers:
             for header in headers.keys():
                 self.set_header(header, headers.get(header))
+        self._track_timing()
         self.finish()
 
     def _validation_err(self, fail):
@@ -224,6 +238,7 @@ def _router_response(self, response):
         if 200 <= response.status_code < 300:
             self.set_status(response.status_code, reason=None)
             self.write(response.response_body)
+            self._track_timing(status_code=response.logged_status)
             self.finish()
         else:
             self._write_response(
@@ -264,6 +279,7 @@ def _write_validation_err(self, errors):
             errors=errors
         )
         self.write(json.dumps(error_data))
+        self._track_timing()
         self.finish()
 
     def _db_error_handling(self, d):
@@ -273,3 +289,18 @@ def _db_error_handling(self, d):
         d.addErrback(self._boto_err)
         d.addErrback(self._response_err)
         return d
+
+    #############################################################
+    #                    Utility Methods
+    #############################################################
+    def _track_timing(self, status_code=None):
+        """Logs out the request timing tracking stats
+
+        Note: The status code should be set before calling this function or
+        passed in.
+
+        """
+        status_code = status_code or self.get_status()
+        self._timings["request_time"] = time.time() - self._start_time
+        self.log.info("Request timings", client_info=self._client_info,
+                      timings=self._timings, status_code=status_code)

autopush/web/simplepush.py

@@ -131,7 +131,7 @@ def _router_completed(self, response, uaid_data, warning=""):
         elif response.status_code == 202 or response.logged_status == 202:
             self.log.info(format="Router miss, message stored.",
                           client_info=self._client_info)
-        time_diff = time.time() - self.start_time
+        time_diff = time.time() - self._start_time
         self.metrics.timing("updates.handled", duration=time_diff)
         response.response_body = (
             response.response_body + " " + warning).strip()

autopush/web/webpush.py

@@ -348,6 +348,7 @@ def post(self, *args, **kwargs):
         self._client_info["message_size"] = len(notification.data or "")
         self._client_info["ttl"] = notification.ttl
         self._client_info["version"] = notification.version
+        self._router_time = time.time()
         d = Deferred()
         d.addCallback(router.route_notification, user_data)
         d.addCallback(self._router_completed, user_data, "")
@@ -359,9 +360,10 @@ def post(self, *args, **kwargs):
 
     def _router_completed(self, response, uaid_data, warning=""):
         """Called after router has completed successfully"""
+        # Log the time taken for routing
+        self._timings["route_time"] = time.time() - self._router_time
         # Were we told to update the router data?
-        time_diff = time.time() - self.start_time
-        self._client_info["route_time"] = time_diff
+        time_diff = time.time() - self._start_time
         if response.router_data is not None:
             if not response.router_data:
                 # An empty router_data object indicates that the record should