PostgREST / postgrest

REST API for any Postgres database
https://postgrest.org
MIT License
23.08k stars 1.02k forks source link

Add pool checkout to `Server-Timing` #3442

Open steve-chavez opened 4 months ago

steve-chavez commented 4 months ago

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 commented 4 months ago

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

https://github.com/PostgREST/postgrest/blob/85a4e35a2de869ddf9b6c5f6893a3154767cbc76/src/PostgREST/App.hs#L146-L149

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

(https://github.com/nikita-volkov/hasql-pool/pull/40#issuecomment-1947360163)

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.