From 39b900b31614ba21e6a24abafba33a51b763534b Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 19 Aug 2016 17:51:08 +0100 Subject: Measure http.server render --- synapse/http/server.py | 58 ++++++++++++++++++++++++++------------------------ 1 file changed, 30 insertions(+), 28 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index 2b3c05a740..f3357d2ff7 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -19,6 +19,7 @@ from synapse.api.errors import ( ) from synapse.util.logcontext import LoggingContext, PreserveLoggingContext from synapse.util.caches import intern_dict +from synapse.util.metrics import Measure import synapse.metrics import synapse.events @@ -234,41 +235,42 @@ class JsonResource(HttpServer, resource.Resource): request_metrics = RequestMetrics() request_metrics.start(self.clock) - # Loop through all the registered callbacks to check if the method - # and path regex match - for path_entry in self.path_regexs.get(request.method, []): - m = path_entry.pattern.match(request.path) - if not m: - continue + with Measure(self.clock, "http.render"): + # Loop through all the registered callbacks to check if the method + # and path regex match + for path_entry in self.path_regexs.get(request.method, []): + m = path_entry.pattern.match(request.path) + if not m: + continue - # We found a match! Trigger callback and then return the - # returned response. We pass both the request and any - # matched groups from the regex to the callback. + # We found a match! Trigger callback and then return the + # returned response. We pass both the request and any + # matched groups from the regex to the callback. - callback = path_entry.callback + callback = path_entry.callback - servlet_instance = getattr(callback, "__self__", None) - if servlet_instance is not None: - servlet_classname = servlet_instance.__class__.__name__ - else: - servlet_classname = "%r" % callback + servlet_instance = getattr(callback, "__self__", None) + if servlet_instance is not None: + servlet_classname = servlet_instance.__class__.__name__ + else: + servlet_classname = "%r" % callback - kwargs = intern_dict({ - name: urllib.unquote(value).decode("UTF-8") if value else value - for name, value in m.groupdict().items() - }) + kwargs = intern_dict({ + name: urllib.unquote(value).decode("UTF-8") if value else value + for name, value in m.groupdict().items() + }) - callback_return = yield callback(request, **kwargs) - if callback_return is not None: - code, response = callback_return - self._send_response(request, code, response) + callback_return = yield callback(request, **kwargs) + if callback_return is not None: + code, response = callback_return + self._send_response(request, code, response) - try: - request_metrics.stop(self.clock, request, servlet_classname) - except: - pass + try: + request_metrics.stop(self.clock, request, servlet_classname) + except: + pass - return + return # Huh. No one wanted to handle that? Fiiiiiine. Send 400. raise UnrecognizedRequestError() -- cgit 1.4.1 From 6d1a94d218cca7a039e77318951833c9e45dc043 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 19 Aug 2016 18:40:31 +0100 Subject: Remove redundant measure --- synapse/http/server.py | 69 +++++++++++++++++++++++++------------------------- 1 file changed, 34 insertions(+), 35 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index f3357d2ff7..74840de55c 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -235,42 +235,41 @@ class JsonResource(HttpServer, resource.Resource): request_metrics = RequestMetrics() request_metrics.start(self.clock) - with Measure(self.clock, "http.render"): - # Loop through all the registered callbacks to check if the method - # and path regex match - for path_entry in self.path_regexs.get(request.method, []): - m = path_entry.pattern.match(request.path) - if not m: - continue - - # We found a match! Trigger callback and then return the - # returned response. We pass both the request and any - # matched groups from the regex to the callback. - - callback = path_entry.callback - - servlet_instance = getattr(callback, "__self__", None) - if servlet_instance is not None: - servlet_classname = servlet_instance.__class__.__name__ - else: - servlet_classname = "%r" % callback - - kwargs = intern_dict({ - name: urllib.unquote(value).decode("UTF-8") if value else value - for name, value in m.groupdict().items() - }) - - callback_return = yield callback(request, **kwargs) - if callback_return is not None: - code, response = callback_return - self._send_response(request, code, response) + # Loop through all the registered callbacks to check if the method + # and path regex match + for path_entry in self.path_regexs.get(request.method, []): + m = path_entry.pattern.match(request.path) + if not m: + continue + + # We found a match! Trigger callback and then return the + # returned response. We pass both the request and any + # matched groups from the regex to the callback. + + callback = path_entry.callback + + servlet_instance = getattr(callback, "__self__", None) + if servlet_instance is not None: + servlet_classname = servlet_instance.__class__.__name__ + else: + servlet_classname = "%r" % callback + + kwargs = intern_dict({ + name: urllib.unquote(value).decode("UTF-8") if value else value + for name, value in m.groupdict().items() + }) + + callback_return = yield callback(request, **kwargs) + if callback_return is not None: + code, response = callback_return + self._send_response(request, code, response) + + try: + request_metrics.stop(self.clock, request, servlet_classname) + except: + pass - try: - request_metrics.stop(self.clock, request, servlet_classname) - except: - pass - - return + return # Huh. No one wanted to handle that? Fiiiiiine. Send 400. raise UnrecognizedRequestError() -- cgit 1.4.1 From 27e0178da9e5c61c5221faf4a7ad1b5be5684531 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 19 Aug 2016 18:49:37 +0100 Subject: Add a top level measure --- synapse/http/server.py | 91 +++++++++++++++++++++++++------------------------- 1 file changed, 46 insertions(+), 45 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index 74840de55c..2cba13e69f 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -104,54 +104,55 @@ def wrap_request_handler(request_handler, report_metrics): _next_request_id += 1 with LoggingContext(request_id) as request_context: - if report_metrics: - request_metrics = RequestMetrics() - request_metrics.start(self.clock) - - request_context.request = request_id - with request.processing(): - try: - with PreserveLoggingContext(request_context): - yield request_handler(self, request) - except CodeMessageException as e: - code = e.code - if isinstance(e, SynapseError): - logger.info( - "%s SynapseError: %s - %s", request, code, e.msg - ) - else: - logger.exception(e) - outgoing_responses_counter.inc(request.method, str(code)) - respond_with_json( - request, code, cs_exception(e), send_cors=True, - pretty_print=_request_user_agent_is_curl(request), - version_string=self.version_string, - ) - except: - logger.exception( - "Failed handle request %s.%s on %r: %r", - request_handler.__module__, - request_handler.__name__, - self, - request - ) - respond_with_json( - request, - 500, - { - "error": "Internal server error", - "errcode": Codes.UNKNOWN, - }, - send_cors=True - ) - finally: + with Measure(self.clock, "wrapped_request_handler"): + if report_metrics: + request_metrics = RequestMetrics() + request_metrics.start(self.clock) + + request_context.request = request_id + with request.processing(): try: - if report_metrics: - request_metrics.stop( - self.clock, request, self.__class__.__name__ + with PreserveLoggingContext(request_context): + yield request_handler(self, request) + except CodeMessageException as e: + code = e.code + if isinstance(e, SynapseError): + logger.info( + "%s SynapseError: %s - %s", request, code, e.msg ) + else: + logger.exception(e) + outgoing_responses_counter.inc(request.method, str(code)) + respond_with_json( + request, code, cs_exception(e), send_cors=True, + pretty_print=_request_user_agent_is_curl(request), + version_string=self.version_string, + ) except: - pass + logger.exception( + "Failed handle request %s.%s on %r: %r", + request_handler.__module__, + request_handler.__name__, + self, + request + ) + respond_with_json( + request, + 500, + { + "error": "Internal server error", + "errcode": Codes.UNKNOWN, + }, + send_cors=True + ) + finally: + try: + if report_metrics: + request_metrics.stop( + self.clock, request, self.__class__.__name__ + ) + except: + pass return wrapped_request_handler -- cgit 1.4.1 From a093fab253ca0e67d9ae861e5b8cf393ea7783f9 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 22 Aug 2016 10:18:12 +0100 Subject: Use top level measure --- synapse/http/server.py | 16 +--------------- 1 file changed, 1 insertion(+), 15 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index 2cba13e69f..d2efd9f3e4 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -222,7 +222,7 @@ class JsonResource(HttpServer, resource.Resource): # 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) + @request_handler() @defer.inlineCallbacks def _async_render(self, request): """ This gets called from render() every time someone sends us a request. @@ -233,9 +233,6 @@ class JsonResource(HttpServer, resource.Resource): self._send_response(request, 200, {}) return - request_metrics = RequestMetrics() - request_metrics.start(self.clock) - # Loop through all the registered callbacks to check if the method # and path regex match for path_entry in self.path_regexs.get(request.method, []): @@ -249,12 +246,6 @@ class JsonResource(HttpServer, resource.Resource): callback = path_entry.callback - servlet_instance = getattr(callback, "__self__", None) - if servlet_instance is not None: - servlet_classname = servlet_instance.__class__.__name__ - else: - servlet_classname = "%r" % callback - kwargs = intern_dict({ name: urllib.unquote(value).decode("UTF-8") if value else value for name, value in m.groupdict().items() @@ -265,11 +256,6 @@ class JsonResource(HttpServer, resource.Resource): code, response = callback_return 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. -- cgit 1.4.1 From 8c52160b07968ed1070452d902e758b01e276bbd Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 22 Aug 2016 10:44:45 +0100 Subject: Allow request handlers to override metric name --- synapse/http/server.py | 52 ++++++++++++++++++++++++++++++-------------------- 1 file changed, 31 insertions(+), 21 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index d2efd9f3e4..db2127cf8f 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -75,12 +75,12 @@ response_db_txn_duration = metrics.register_distribution( _next_request_id = 0 -def request_handler(report_metrics=True): +def request_handler(include_metrics=False): """Decorator for ``wrap_request_handler``""" - return lambda request_handler: wrap_request_handler(request_handler, report_metrics) + return lambda request_handler: wrap_request_handler(request_handler, include_metrics) -def wrap_request_handler(request_handler, report_metrics): +def wrap_request_handler(request_handler, include_metrics=False): """Wraps a method that acts as a request handler with the necessary logging and exception handling. @@ -105,15 +105,17 @@ def wrap_request_handler(request_handler, report_metrics): with LoggingContext(request_id) as request_context: with Measure(self.clock, "wrapped_request_handler"): - if report_metrics: - request_metrics = RequestMetrics() - request_metrics.start(self.clock) + request_metrics = RequestMetrics() + request_metrics.start(self.clock, name=self.__class__.__name__) request_context.request = request_id with request.processing(): try: with PreserveLoggingContext(request_context): - yield request_handler(self, request) + if include_metrics: + yield request_handler(self, request, request_metrics) + else: + yield request_handler(self, request) except CodeMessageException as e: code = e.code if isinstance(e, SynapseError): @@ -147,10 +149,9 @@ def wrap_request_handler(request_handler, report_metrics): ) finally: try: - if report_metrics: - request_metrics.stop( - self.clock, request, self.__class__.__name__ - ) + request_metrics.stop( + self.clock, request, self.__class__.__name__ + ) except: pass return wrapped_request_handler @@ -222,9 +223,9 @@ class JsonResource(HttpServer, resource.Resource): # 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() + @request_handler(include_metrics=True) @defer.inlineCallbacks - def _async_render(self, request): + def _async_render(self, request, request_metrics): """ 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. @@ -256,6 +257,14 @@ class JsonResource(HttpServer, resource.Resource): code, response = callback_return self._send_response(request, code, response) + servlet_instance = getattr(callback, "__self__", None) + if servlet_instance is not None: + servlet_classname = servlet_instance.__class__.__name__ + else: + servlet_classname = "%r" % callback + + request_metrics.name = servlet_classname + return # Huh. No one wanted to handle that? Fiiiiiine. Send 400. @@ -286,11 +295,12 @@ class JsonResource(HttpServer, resource.Resource): class RequestMetrics(object): - def start(self, clock): + def start(self, clock, name): self.start = clock.time_msec() self.start_context = LoggingContext.current_context() + self.name = name - def stop(self, clock, request, servlet_classname): + def stop(self, clock, request): context = LoggingContext.current_context() tag = "" @@ -304,26 +314,26 @@ class RequestMetrics(object): ) return - incoming_requests_counter.inc(request.method, servlet_classname, tag) + incoming_requests_counter.inc(request.method, self.name, tag) response_timer.inc_by( clock.time_msec() - self.start, request.method, - servlet_classname, tag + self.name, tag ) ru_utime, ru_stime = context.get_resource_usage() response_ru_utime.inc_by( - ru_utime, request.method, servlet_classname, tag + ru_utime, request.method, self.name, tag ) response_ru_stime.inc_by( - ru_stime, request.method, servlet_classname, tag + ru_stime, request.method, self.name, tag ) response_db_txn_count.inc_by( - context.db_txn_count, request.method, servlet_classname, tag + context.db_txn_count, request.method, self.name, tag ) response_db_txn_duration.inc_by( - context.db_txn_duration, request.method, servlet_classname, tag + context.db_txn_duration, request.method, self.name, tag ) -- cgit 1.4.1 From 33f3624ff76dc71e73c997ffef0059b1d004a5e1 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 22 Aug 2016 10:49:31 +0100 Subject: Add exception logging. Fix typo --- synapse/http/server.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'synapse/http/server.py') diff --git a/synapse/http/server.py b/synapse/http/server.py index db2127cf8f..168e53ce0c 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -150,10 +150,10 @@ def wrap_request_handler(request_handler, include_metrics=False): finally: try: request_metrics.stop( - self.clock, request, self.__class__.__name__ + self.clock, request ) - except: - pass + except Exception as e: + logger.warn("Failed to stop metrics: %r", e) return wrapped_request_handler -- cgit 1.4.1