Add pool checkout to Server-Timing

[steve-chavez]

Problem

Server-Timing currently conflates the pool checkout time with the transaction time. Meaning we cannot differentiate if a query took a lot of time or if acquiring the connection from the pool did.

Solution

Add a pool-checkout duration:

HTTP/1.1 200 OK

Server-Timing: jwt;dur=14.9, parse;dur=71.1, plan;dur=109.0, pool-checkout;dur=10.3, transaction;dur=353.2, response;dur=4.4

Notes

Measuring check-in time (time to return the connection to the pool) doesn't make much sense in our case IMO, since we always return the connection right after finishing the transaction. This probably makes more sense in traditional three-tier apps where some business logic is done in the application layer while a pool connection is being used.

[steve-chavez]

There's a problem doing this, so currently we get the timings with:

postgrest/src/PostgREST/App.hs

Lines 146 to 149 in 85a4e35

	(parseTime, apiReq@ApiRequest{..}) <- withTiming $ liftEither . mapLeft Error.ApiRequestError $ ApiRequest.userApiRequest conf req body sCache
	(planTime, plan) <- withTiming $ liftEither $ Plan.actionPlan iAction conf apiReq sCache
	(queryTime, queryResult) <- withTiming $ Query.runQuery appState conf authResult apiReq plan sCache pgVer (Just authRole /= configDbAnonRole)
	(respTime, resp) <- withTiming $ liftEither $ Response.actionResponse queryResult apiReq (T.decodeUtf8 prettyVersion, docsVersion) conf sCache iSchema iNegotiatedByProfile

But it's not possible to use the same pattern for the pool checkout time, we have to compute the time inside the pool.

According to Nikita, we have to measure the checkout time (or wait time) like:

executeObservedSession :: Pool -> Monitor -> Session -> IO ()
executeObservedSession pool monitor session = do
  Monitor.incGauge monitor "db.client.connections.pending_requests"
  startTime <- getCurrentTime
  Pool.use pool do
    liftIO $ do
      endTime <- getCurrentTime
      Monitor.observeHistogram monitor "db.client.connections.wait_time" (diffUTCTime endTime startTime)
      Monitor.decGauge monitor "db.client.connections.pending_requests"
    session

(nikita-volkov/hasql-pool#40 (comment))

So while we could have a Metric (o new Observation) inside the pool, is not straightforward to get it out. Maybe we could use an IORef there, but it's kind of messy.