Merge pull request #756 from matrix-org/markjh/more_metrics

Report per request metrics for all of the things using request_handler

synapse/http/server.py

@@ -74,7 +74,12 @@ response_db_txn_duration = metrics.register_distribution(
 _next_request_id = 0
 
 
-def request_handler(request_handler):
+def request_handler(report_metrics=True):
+    """Decorator for ``wrap_request_handler``"""
+    return lambda request_handler: wrap_request_handler(request_handler, report_metrics)
+
+
+def wrap_request_handler(request_handler, report_metrics):
     """Wraps a method that acts as a request handler with the necessary logging
     and exception handling.
 
@@ -96,6 +101,10 @@ def request_handler(request_handler):
         global _next_request_id
         request_id = "%s-%s" % (request.method, _next_request_id)
         _next_request_id += 1
+        if report_metrics:
+            request_metrics = RequestMetrics()
+            request_metrics.start(self.clock)
+
         with LoggingContext(request_id) as request_context:
             request_context.request = request_id
             with request.processing():
@@ -133,6 +142,14 @@ def request_handler(request_handler):
                         },
                         send_cors=True
                     )
+                finally:
+                    try:
+                        if report_metrics:
+                            request_metrics.stop(
+                                self.clock, request, self.__class__.__name__
+                            )
+                    except:
+                        pass
     return wrapped_request_handler
 
 
@@ -197,19 +214,23 @@ class JsonResource(HttpServer, resource.Resource):
         self._async_render(request)
         return server.NOT_DONE_YET
 
-    @request_handler
+    # Disable metric reporting because _async_render does its own metrics.
+    # It does its own metric reporting because _async_render dispatches to
+    # a callback and it's the class name of that callback we want to report
+    # against rather than the JsonResource itself.
+    @request_handler(report_metrics=False)
     @defer.inlineCallbacks
     def _async_render(self, request):
         """ This gets called from render() every time someone sends us a request.
             This checks if anyone has registered a callback for that method and
             path.
         """
-        start = self.clock.time_msec()
         if request.method == "OPTIONS":
             self._send_response(request, 200, {})
             return
 
-        start_context = LoggingContext.current_context()
+        request_metrics = RequestMetrics()
+        request_metrics.start(self.clock)
 
         # Loop through all the registered callbacks to check if the method
         # and path regex match
@@ -241,6 +262,45 @@ class JsonResource(HttpServer, resource.Resource):
                 self._send_response(request, code, response)
 
             try:
+                request_metrics.stop(self.clock, request, servlet_classname)
+            except:
+                pass
+
+            return
+
+        # Huh. No one wanted to handle that? Fiiiiiine. Send 400.
+        raise UnrecognizedRequestError()
+
+    def _send_response(self, request, code, response_json_object,
+                       response_code_message=None):
+        # could alternatively use request.notifyFinish() and flip a flag when
+        # the Deferred fires, but since the flag is RIGHT THERE it seems like
+        # a waste.
+        if request._disconnected:
+            logger.warn(
+                "Not sending response to request %s, already disconnected.",
+                request)
+            return
+
+        outgoing_responses_counter.inc(request.method, str(code))
+
+        # TODO: Only enable CORS for the requests that need it.
+        respond_with_json(
+            request, code, response_json_object,
+            send_cors=True,
+            response_code_message=response_code_message,
+            pretty_print=_request_user_agent_is_curl(request),
+            version_string=self.version_string,
+            canonical_json=self.canonical_json,
+        )
+
+
+class RequestMetrics(object):
+    def start(self, clock):
+        self.start = clock.time_msec()
+        self.start_context = LoggingContext.current_context()
+
+    def stop(self, clock, request, servlet_classname):
         context = LoggingContext.current_context()
 
         tag = ""
@@ -275,36 +335,6 @@ class JsonResource(HttpServer, resource.Resource):
         response_db_txn_duration.inc_by(
             context.db_txn_duration, request.method, servlet_classname, tag
         )
-            except:
-                pass
-
-            return
-
-        # Huh. No one wanted to handle that? Fiiiiiine. Send 400.
-        raise UnrecognizedRequestError()
-
-    def _send_response(self, request, code, response_json_object,
-                       response_code_message=None):
-        # could alternatively use request.notifyFinish() and flip a flag when
-        # the Deferred fires, but since the flag is RIGHT THERE it seems like
-        # a waste.
-        if request._disconnected:
-            logger.warn(
-                "Not sending response to request %s, already disconnected.",
-                request)
-            return
-
-        outgoing_responses_counter.inc(request.method, str(code))
-
-        # TODO: Only enable CORS for the requests that need it.
-        respond_with_json(
-            request, code, response_json_object,
-            send_cors=True,
-            response_code_message=response_code_message,
-            pretty_print=_request_user_agent_is_curl(request),
-            version_string=self.version_string,
-            canonical_json=self.canonical_json,
-        )
 
 
 class RootRedirect(resource.Resource):

synapse/replication/pusher_resource.py

@@ -31,12 +31,13 @@ class PusherResource(Resource):
         self.version_string = hs.version_string
         self.store = hs.get_datastore()
         self.notifier = hs.get_notifier()
+        self.clock = hs.get_clock()
 
     def render_POST(self, request):
         self._async_render_POST(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_POST(self, request):
         content = parse_json_object_from_request(request)

synapse/replication/resource.py

@@ -112,6 +112,7 @@ class ReplicationResource(Resource):
         self.presence_handler = hs.get_handlers().presence_handler
         self.typing_handler = hs.get_handlers().typing_notification_handler
         self.notifier = hs.notifier
+        self.clock = hs.get_clock()
 
         self.putChild("remove_pushers", PusherResource(hs))
 
@@ -139,7 +140,7 @@ class ReplicationResource(Resource):
             state_token,
         ))
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_GET(self, request):
         limit = parse_integer(request, "limit", 100)

synapse/rest/key/v1/server_key_resource.py

@@ -49,7 +49,6 @@ class LocalKey(Resource):
     """
 
     def __init__(self, hs):
-        self.hs = hs
         self.version_string = hs.version_string
         self.response_body = encode_canonical_json(
             self.response_json_object(hs.config)

synapse/rest/key/v2/remote_key_resource.py

@@ -97,7 +97,7 @@ class RemoteKey(Resource):
         self.async_render_GET(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def async_render_GET(self, request):
         if len(request.postpath) == 1:
@@ -122,7 +122,7 @@ class RemoteKey(Resource):
         self.async_render_POST(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def async_render_POST(self, request):
         content = parse_json_object_from_request(request)

synapse/rest/media/v1/download_resource.py

@@ -36,12 +36,13 @@ class DownloadResource(Resource):
         self.server_name = hs.hostname
         self.store = hs.get_datastore()
         self.version_string = hs.version_string
+        self.clock = hs.get_clock()
 
     def render_GET(self, request):
         self._async_render_GET(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_GET(self, request):
         server_name, media_id, name = parse_media_id(request)

synapse/rest/media/v1/preview_url_resource.py

@@ -74,7 +74,7 @@ class PreviewUrlResource(Resource):
         self._async_render_GET(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_GET(self, request):
 

synapse/rest/media/v1/thumbnail_resource.py

@@ -39,12 +39,13 @@ class ThumbnailResource(Resource):
         self.dynamic_thumbnails = hs.config.dynamic_thumbnails
         self.server_name = hs.hostname
         self.version_string = hs.version_string
+        self.clock = hs.get_clock()
 
     def render_GET(self, request):
         self._async_render_GET(request)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_GET(self, request):
         server_name, media_id, _ = parse_media_id(request)

synapse/rest/media/v1/upload_resource.py

@@ -41,6 +41,7 @@ class UploadResource(Resource):
         self.auth = hs.get_auth()
         self.max_upload_size = hs.config.max_upload_size
         self.version_string = hs.version_string
+        self.clock = hs.get_clock()
 
     def render_POST(self, request):
         self._async_render_POST(request)
@@ -50,7 +51,7 @@ class UploadResource(Resource):
         respond_with_json(request, 200, {}, send_cors=True)
         return NOT_DONE_YET
 
-    @request_handler
+    @request_handler()
     @defer.inlineCallbacks
     def _async_render_POST(self, request):
         requester = yield self.auth.get_user_by_req(request)