fix: instrument timing for slow requests

backend/common/server/config.py

@@ -92,6 +92,7 @@ def after_request(response: Response):
                     status_code=response.status_code,
                     content_length=response.content_length,
                     response_time=time.time() - g.start,
+                    request=dict(url=request.path, method=request.method),
                 ),
             )
         )

backend/common/utils/timer.py

@@ -1,16 +1,89 @@
 import logging
 import time
 from contextlib import contextmanager
+from typing import Any, Optional
+
+import numpy as np
 
 logging.basicConfig(level=logging.INFO)
 
+Accumulators: dict[str, Any] = dict()
+
 
 @contextmanager
-def log_time_taken(description: str = "Code block"):
+def log_time_taken(
+    description: str,
+):
     start_time = time.time()
     try:
         yield
     finally:
         end_time = time.time()
         elapsed_time = end_time - start_time
         logging.info(dict(type="METRIC", details=dict(description=description, time=elapsed_time, unit="seconds")))
+
+
+class TimeAccumulator:
+    def __init__(self, group: str):
+        self.group = group
+        self.records = []
+
+    @contextmanager
+    def time(
+        self,
+        description: Optional[str] = None,
+    ):
+        start_time = time.time()
+        try:
+            yield
+        finally:
+            end_time = time.time()
+            logging.info(
+                dict(
+                    type="METRIC",
+                    details=dict(description=description, time=end_time - start_time, unit="seconds", group=self.group),
+                )
+            )
+            self.records.append(dict(description=description, elapsed=end_time - start_time))
+
+    def todict(self):
+        records = self.records
+        if not records:
+            return dict(
+                group=self.group,
+                records=0,
+                total_time=0,
+                max_time=0,
+                min_time=0,
+                median_time=0,
+                _95th_percentile=0,
+                _99th_percentile=0,
+                unit="seconds",
+            )
+        records.sort(key=lambda x: x["elapsed"])
+        times = [record["elapsed"] for record in records]
+        self.total_time = sum(times)
+        self.max_time = max(times)
+        self.min_time = min(times)
+        self.median_time = np.median(times)
+        self._95th_percentile, self._99th_percentile = np.percentile(times, [95, 99])
+        return dict(
+            group=self.group,
+            records=len(records),
+            total_time=self.total_time,
+            max_time=self.max_time,
+            min_time=self.min_time,
+            median_time=self.median_time,
+            _95th_percentile=self._95th_percentile,
+            _99th_percentile=self._99th_percentile,
+            unit="seconds",
+        )
+
+
+@contextmanager
+def log_accumulative_time_taken(group: str) -> TimeAccumulator:
+    accumulator = TimeAccumulator(group)
+    try:
+        yield accumulator
+    finally:
+        logging.info(dict(type="METRIC", details=accumulator.todict()))

backend/curation/api/v1/curation/collections/actions.py

@@ -4,6 +4,7 @@
 
 import backend.common.doi as doi
 from backend.common.utils.http_exceptions import ForbiddenHTTPException, InvalidParametersHTTPException
+from backend.common.utils.timer import log_accumulative_time_taken
 from backend.curation.api.v1.curation.collections.common import reshape_for_curation_api
 from backend.layers.auth.user_info import UserInfo
 from backend.layers.business.entities import CollectionQueryFilter
@@ -42,9 +43,11 @@ def get(visibility: str, token_info: dict, curator: str = None):
     logging.info(filters)
 
     resp_collections = []
-    for collection_version in get_business_logic().get_collections(CollectionQueryFilter(**filters)):
-        resp_collection = reshape_for_curation_api(collection_version, user_info, preview=True)
-        resp_collections.append(resp_collection)
+    with log_accumulative_time_taken("reshape_for_curation_api") as time_accumulator:
+        for collection_version in get_business_logic().get_collections(CollectionQueryFilter(**filters)):
+            with time_accumulator.time(f"{collection_version.collection_id.id}"):
+                resp_collection = reshape_for_curation_api(collection_version, user_info, preview=True)
+                resp_collections.append(resp_collection)
     return jsonify(resp_collections)