diff options
Diffstat (limited to 'synapse/http')
| -rw-r--r-- | synapse/http/request_metrics.py | 137 | ||||
| -rw-r--r-- | synapse/http/server.py | 76 | ||||
| -rw-r--r-- | synapse/http/site.py | 4 |
3 files changed, 213 insertions, 4 deletions
diff --git a/synapse/http/request_metrics.py b/synapse/http/request_metrics.py index 34a730d5bc..0984870e7e 100644 --- a/synapse/http/request_metrics.py +++ b/synapse/http/request_metrics.py @@ -17,6 +17,7 @@ import logging from prometheus_client.core import Counter, Histogram +from synapse.metrics import LaterGauge from synapse.util.logcontext import LoggingContext @@ -50,14 +51,75 @@ response_db_sched_duration = Counter("synapse_http_request_response_db_sched_dur response_size = Counter("synapse_http_request_response_size", "", ["method", "servlet", "tag"] ) +# In flight metrics are incremented while the requests are in flight, rather +# than when the response was written. + +in_flight_requests_ru_utime = Counter("synapse_http_request_in_flight_requests_ru_utime_seconds", "", ["method", "servlet"]) + +in_flight_requests_ru_stime = Counter("synapse_http_request_in_flight_requests_ru_stime_seconds", "", ["method", "servlet"]) + +in_flight_requests_db_txn_count = Counter("synapse_http_request_in_flight_requests_db_txn_count", "", ["method", "servlet"]) + +# seconds spent waiting for db txns, excluding scheduling time, when processing +# this request +in_flight_requests_db_txn_duration = Counter("synapse_http_request_in_flight_requests_db_txn_duration_seconds", "", ["method", "servlet"]) + +# seconds spent waiting for a db connection, when processing this request +in_flight_requests_db_sched_duration = Counter("synapse_http_request_in_flight_requests_db_sched_duration_seconds", "", ["method", "servlet"]) + +# The set of all in flight requests, set[RequestMetrics] +_in_flight_requests = set() + + +def _collect_in_flight(): + """Called just before metrics are collected, so we use it to update all + the in flight request metrics + """ + + for rm in _in_flight_requests: + rm.update_metrics() + + +metrics.register_collector(_collect_in_flight) + + +def _get_in_flight_counts(): + """Returns a count of all in flight requests by (method, server_name) + + Returns: + dict[tuple[str, str], int] + """ + + # Map from (method, name) -> int, the number of in flight requests of that + # type + counts = {} + for rm in _in_flight_requests: + key = (rm.method, rm.name,) + counts[key] = counts.get(key, 0) + 1 + + return counts + +LaterGauge( + "synapse_http_request_metrics_in_flight_requests_count", "", + ["method", "servlet"], + _get_in_flight_counts +) + class RequestMetrics(object): - def start(self, time_msec, name): + def start(self, time_msec, name, method): self.start = time_msec self.start_context = LoggingContext.current_context() self.name = name + self.method = method + + self._request_stats = _RequestStats.from_context(self.start_context) + + _in_flight_requests.add(self) def stop(self, time_msec, request): + _in_flight_requests.discard(self) + context = LoggingContext.current_context() tag = "" @@ -87,3 +149,76 @@ class RequestMetrics(object): context.db_sched_duration_ms / 1000.) response_size.labels(request.method, self.name, tag).inc(request.sentLength) + + # We always call this at the end to ensure that we update the metrics + # regardless of whether a call to /metrics while the request was in + # flight. + self.update_metrics() + + def update_metrics(self): + """Updates the in flight metrics with values from this request. + """ + diff = self._request_stats.update(self.start_context) + + in_flight_requests_ru_utime.labels(self.method, self.name).inc(diff.ru_utime) + in_flight_requests_ru_stime.labels(self.method, self.name).inc(diff.ru_stime) + + in_flight_requests_db_txn_count.labels(self.method, self.name).inc(diff.db_txn_count) + + in_flight_requests_db_txn_duration.labels(self.method, self.name).inc(diff.db_txn_duration_ms / 1000.) + + in_flight_requests_db_sched_duration.labels(self.method, self.name).inc(diff.db_sched_duration_ms / 1000.) + + +class _RequestStats(object): + """Keeps tracks of various metrics for an in flight request. + """ + + __slots__ = [ + "ru_utime", "ru_stime", + "db_txn_count", "db_txn_duration_ms", "db_sched_duration_ms", + ] + + def __init__(self, ru_utime, ru_stime, db_txn_count, + db_txn_duration_ms, db_sched_duration_ms): + self.ru_utime = ru_utime + self.ru_stime = ru_stime + self.db_txn_count = db_txn_count + self.db_txn_duration_ms = db_txn_duration_ms + self.db_sched_duration_ms = db_sched_duration_ms + + @staticmethod + def from_context(context): + ru_utime, ru_stime = context.get_resource_usage() + + return _RequestStats( + ru_utime, ru_stime, + context.db_txn_count, + context.db_txn_duration_ms, + context.db_sched_duration_ms, + ) + + def update(self, context): + """Updates the current values and returns the difference between the + old and new values. + + Returns: + _RequestStats: The difference between the old and new values + """ + new = _RequestStats.from_context(context) + + diff = _RequestStats( + new.ru_utime - self.ru_utime, + new.ru_stime - self.ru_stime, + new.db_txn_count - self.db_txn_count, + new.db_txn_duration_ms - self.db_txn_duration_ms, + new.db_sched_duration_ms - self.db_sched_duration_ms, + ) + + self.ru_utime = new.ru_utime + self.ru_stime = new.ru_stime + self.db_txn_count = new.db_txn_count + self.db_txn_duration_ms = new.db_txn_duration_ms + self.db_sched_duration_ms = new.db_sched_duration_ms + + return diff diff --git a/synapse/http/server.py b/synapse/http/server.py index f72d986288..bc09b8b2be 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -13,7 +13,8 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. - +import cgi +from six.moves import http_client from synapse.api.errors import ( cs_exception, SynapseError, CodeMessageException, UnrecognizedRequestError, Codes @@ -44,6 +45,18 @@ import simplejson logger = logging.getLogger(__name__) +HTML_ERROR_TEMPLATE = """<!DOCTYPE html> +<html lang=en> + <head> + <meta charset="utf-8"> + <title>Error {code}</title> + </head> + <body> + <p>{msg}</p> + </body> +</html> +""" + def wrap_json_request_handler(h): """Wraps a request handler method with exception handling. @@ -102,6 +115,65 @@ def wrap_json_request_handler(h): return wrap_request_handler_with_logging(wrapped_request_handler) +def wrap_html_request_handler(h): + """Wraps a request handler method with exception handling. + + Also adds logging as per wrap_request_handler_with_logging. + + The handler method must have a signature of "handle_foo(self, request)", + where "self" must have a "clock" attribute (and "request" must be a + SynapseRequest). + """ + def wrapped_request_handler(self, request): + d = defer.maybeDeferred(h, self, request) + d.addErrback(_return_html_error, request) + return d + + return wrap_request_handler_with_logging(wrapped_request_handler) + + +def _return_html_error(f, request): + """Sends an HTML error page corresponding to the given failure + + Args: + f (twisted.python.failure.Failure): + request (twisted.web.iweb.IRequest): + """ + if f.check(CodeMessageException): + cme = f.value + code = cme.code + msg = cme.msg + + if isinstance(cme, SynapseError): + logger.info( + "%s SynapseError: %s - %s", request, code, msg + ) + else: + logger.error( + "Failed handle request %r: %s", + request, + f.getTraceback().rstrip(), + ) + else: + code = http_client.INTERNAL_SERVER_ERROR + msg = "Internal server error" + + logger.error( + "Failed handle request %r: %s", + request, + f.getTraceback().rstrip(), + ) + + body = HTML_ERROR_TEMPLATE.format( + code=code, msg=cgi.escape(msg), + ).encode("utf-8") + request.setResponseCode(code) + request.setHeader(b"Content-Type", b"text/html; charset=utf-8") + request.setHeader(b"Content-Length", b"%i" % (len(body),)) + request.write(body) + finish_request(request) + + def wrap_request_handler_with_logging(h): """Wraps a request handler to provide logging and metrics @@ -132,7 +204,7 @@ def wrap_request_handler_with_logging(h): servlet_name = self.__class__.__name__ with request.processing(servlet_name): with PreserveLoggingContext(request_context): - d = h(self, request) + d = defer.maybeDeferred(h, self, request) # record the arrival of the request *after* # dispatching to the handler, so that the handler diff --git a/synapse/http/site.py b/synapse/http/site.py index 202a990508..b608504225 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -85,7 +85,9 @@ class SynapseRequest(Request): def _started_processing(self, servlet_name): self.start_time = int(time.time() * 1000) self.request_metrics = RequestMetrics() - self.request_metrics.start(self.start_time, name=servlet_name) + self.request_metrics.start( + self.start_time, name=servlet_name, method=self.method, + ) self.site.access_logger.info( "%s - %s - Received request: %s %s", |