feat(web): Provide Server-Timing Header

Allows users to debug/see for themselves where/why requests are
(potentially) slow.

Closes #37.

ancv/timing.py

@@ -0,0 +1,48 @@
+from dataclasses import dataclass, field
+from datetime import timedelta
+from time import perf_counter
+from typing import Optional
+
+
+@dataclass
+class Stopwatch:
+ """A simple stopwatch for timing execution.
+
+ Call it with a segment name, and it will start timing that segment, stopping when it
+ is called again with the next segment or explicitly with `stop()`.
+
+ The results are available in the `timings` attribute.
+ """
+
+ timings: dict[str, timedelta] = field(default_factory=dict)
+ _start: Optional[float] = field(repr=False, default=None)
+ _current_segment: Optional[str] = field(repr=False, default=None)
+ _finished: bool = field(repr=False, default=False)
+
+ def __getitem__(self, key: str) -> timedelta:
+ return self.timings[key]
+
+ def __call__(self, segment: str) -> None:
+ stop = perf_counter()
+
+ if segment in self.timings or segment == self._current_segment:
+ raise ValueError(f"Segment '{segment}' already exists.")
+
+ if self._current_segment is not None and self._start is not None:
+ self.timings[self._current_segment] = timedelta(seconds=stop - self._start)
+
+ if self._finished:
+ self._start = None
+ self._current_segment = None
+ self._finished = False
+ else:
+ self._start = perf_counter()
+ self._current_segment = segment
+
+ def stop(self) -> None:
+ """Stops the current segment and adds it to the timings.
+
+ Calling the stopwatch again with a new segment will restart it.
+ """
+ self._finished = True
+ self(segment="__final_segment__")

ancv/web/client.py

@@ -12,15 +12,17 @@
 from ancv.data.models.github import Gist
 from ancv.data.models.resume import ResumeSchema
 from ancv.exceptions import ResumeLookupError
+from ancv.timing import Stopwatch
 
 LOGGER = get_logger()
 
 
 async def get_resume(
- user: str, session: aiohttp.ClientSession, github: GitHubAPI
+ user: str, session: aiohttp.ClientSession, github: GitHubAPI, stopwatch: Stopwatch
 ) -> ResumeSchema:
  log = LOGGER.bind(user=user, session=session)
 
+ stopwatch("Fetching user")
  try:
  # This generates an additional request, counting towards our limit. However,
  # it seems the cleanest way to check for user existence before iterating over
@@ -35,6 +37,7 @@ async def get_resume(
  raise ResumeLookupError(f"User {user} not found.")
  raise e
 
+ stopwatch("Fetching gists")
  gists = github.getiter(f"/users/{user}/gists")
  async for raw_gist in gists:
  log.info("Got raw gist of user.")
@@ -61,6 +64,7 @@ async def get_resume(
  raw_resume: str = await github.getitem(str(file.raw_url))
  log.info("Got raw resume of user.")
 
+ stopwatch("Validation")
  try:
  resume = ResumeSchema(**json.loads(raw_resume))
  except json.decoder.JSONDecodeError:

ancv/web/server.py

@@ -1,5 +1,6 @@
 from abc import ABC, abstractmethod
 from dataclasses import dataclass
+from datetime import timedelta
 from pathlib import Path
 from typing import AsyncGenerator, Optional
 
@@ -9,6 +10,7 @@
 from structlog import get_logger
 
 from ancv.exceptions import ResumeConfigError, ResumeLookupError
+from ancv.timing import Stopwatch
 from ancv.visualization.templates import Template
 from ancv.web import is_terminal_client
 from ancv.web.client import get_resume
@@ -112,6 +114,9 @@ async def root(self, request: web.Request) -> web.Response:
  raise web.HTTPFound(self.landing_page) # Redirect
 
  async def username(self, request: web.Request) -> web.Response:
+ stopwatch = Stopwatch()
+ stopwatch(segment="Initialize Request")
+
  log = LOGGER.bind(request=request)
  log.info(request.message.headers)
 
@@ -125,19 +130,31 @@ async def username(self, request: web.Request) -> web.Response:
 
  log = log.bind(user=user)
 
+ stopwatch.stop()
  try:
- resume = await get_resume(user=user, session=session, github=github)
+ resume = await get_resume(
+ user=user, session=session, github=github, stopwatch=stopwatch
+ )
  except ResumeLookupError as e:
+ stopwatch.stop()
  log.warning(str(e))
  return web.Response(text=str(e))
  else:
+ stopwatch(segment="Templating")
  try:
  template = Template.from_model_config(resume)
  except ResumeConfigError as e:
  log.warning(str(e))
  return web.Response(text=str(e))
+
+ stopwatch(segment="Rendering")
+ resp = web.Response(text=template.render())
+ stopwatch.stop()
+
+ resp.headers["Server-Timing"] = server_timing_header(stopwatch.timings)
+
  log.debug("Serving rendered template.")
- return web.Response(text=template.render())
+ return resp
 
 
 class FileHandler(Runnable):
@@ -158,3 +175,12 @@ def run(self, context: ServerContext) -> None:
  async def root(self, request: web.Request) -> web.Response:
  LOGGER.debug("Serving rendered template.", request=request)
  return web.Response(text=self.rendered)
+
+
+def server_timing_header(timings: dict[str, timedelta]) -> str:
+ """https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing"""
+
+ return ", ".join(
+ f"{name.replace(' ', '-')};dur={duration.microseconds / 1e3}"
+ for name, duration in timings.items()
+ )

tests/test_timing.py

@@ -0,0 +1,57 @@
+import time
+from datetime import timedelta
+
+import pytest
+
+from ancv.timing import Stopwatch
+
+
+def test_stopwatch_disallows_same_segments():
+ stopwatch = Stopwatch()
+ with pytest.raises(ValueError):
+ stopwatch("segment1")
+ stopwatch("segment1")
+
+
+def sleep(seconds: float) -> None:
+ """Sleep for the given number of seconds.
+
+ This is a replacement for the built-in `time.sleep()` function which will send
+ control back to the OS, introducing an uncertainty depending on the OS.
+ To keep our tests fast, we want to sleep for brief periods, but that will yield a
+ large relative error from the approx. constant OS thread sleep uncertainties.
+ """
+ now = time.time()
+ while time.time() <= (now + seconds):
+ time.sleep(0.001)
+
+
+def test_stopwatch_basics():
+ stopwatch = Stopwatch()
+ stopwatch("segment1")
+ sleep(0.1)
+ stopwatch("segment2")
+ sleep(0.1)
+ stopwatch("segment3")
+ sleep(0.2)
+ stopwatch.stop()
+ sleep(0.1)
+ stopwatch("segment4")
+ sleep(0.5)
+ stopwatch.stop()
+
+ expected = {
+ "segment1": timedelta(seconds=0.1),
+ "segment2": timedelta(seconds=0.1),
+ "segment3": timedelta(seconds=0.2),
+ "segment4": timedelta(seconds=0.5),
+ }
+ for real, expected in zip(stopwatch.timings.values(), expected.values()):
+ # https://stackoverflow.com/a/1133888/11477374 :
+ os_thread_sleep_uncertainty_microseconds = 20_000
+ assert (
+ pytest.approx(
+ real.microseconds, abs=os_thread_sleep_uncertainty_microseconds
+ )
+ == expected.microseconds
+ )