fix: inaccurate Server-Timing durations

The transaction duration was notably off, doing:

```
curl localhost:3000/rpc/sleep?seconds=5 -i
```

Shows `46.1` for the `transaction;dur`, with this fix we obtain
`5007.3`.

Fixes https://github.com/PostgREST/postgrest/issues/4522

This also fixes inaccurate "schema cache queried" logs,
see https://github.com/PostgREST/postgrest/issues/4551.

(cherry picked from commit 013f078bc4)

CHANGELOG.md

@@ -12,6 +12,8 @@ All notable changes to this project will be documented in this file. From versio
 - Fix regression where the `PGRST103` error response was truncated by @laurenceisla in #4455
   + Happened when an `offset` was greater than the rows requested and `Prefer: count=exact` was sent.
 - Fix not returning `Content-Length` on empty HTTP `201` responses by @laurenceisla in #4518
+- Fix inaccurate Server-Timing header durations by @steve-chavez in #4522
+- Fix inaccurate "Schema cache queried" logs by @steve-chavez in #4522
 
 ## [14.1] - 2025-11-05
 

postgrest.cabal

@@ -94,6 +94,7 @@ library
                       PostgREST.Response.OpenAPI
                       PostgREST.Response.GucHeader
                       PostgREST.Response.Performance
+                      PostgREST.TimeIt
                       PostgREST.Version
   build-depends:      base                      >= 4.9 && < 4.20
                     , HTTP                      >= 4000.3.7 && < 4000.5
@@ -139,7 +140,6 @@ library
                     , swagger2                  >= 2.4 && < 2.9
                     , text                      >= 1.2.2 && < 2.2
                     , time                      >= 1.6 && < 1.13
-                    , timeit                    >= 2.0 && < 2.1
                     , unordered-containers      >= 0.2.8 && < 0.3
                     , unix-compat               >= 0.5.4 && < 0.8
                     , vault                     >= 0.3.1.5 && < 0.4

src/PostgREST/App.hs

@@ -51,13 +51,13 @@ import PostgREST.Observation          (Observation (..))
 import PostgREST.Response.Performance (ServerTiming (..),
                                        serverTimingHeader)
 import PostgREST.SchemaCache          (SchemaCache (..))
+import PostgREST.TimeIt               (timeItT)
 import PostgREST.Version              (docsVersion, prettyVersion)
 
 import qualified Data.ByteString.Char8 as BS
 import qualified Data.List             as L
 import qualified Network.HTTP.Types    as HTTP
 import           Protolude             hiding (Handler)
-import           System.TimeIt         (timeItT)
 
 type Handler = ExceptT Error
 

src/PostgREST/AppState.hs

@@ -44,8 +44,8 @@ import qualified PostgREST.Error            as Error
 import qualified PostgREST.Logger           as Logger
 import qualified PostgREST.Metrics          as Metrics
 import           PostgREST.Observation
+import           PostgREST.TimeIt           (timeItT)
 import           PostgREST.Version          (prettyVersion)
-import           System.TimeIt              (timeItT)
 
 import Control.AutoUpdate (defaultUpdateSettings, mkAutoUpdate,
                            updateAction)

src/PostgREST/Auth.hs

@@ -25,8 +25,8 @@ import qualified Network.Wai                     as Wai
 import qualified Network.Wai.Middleware.HttpAuth as Wai
 
 import Data.List        (lookup)
+import PostgREST.TimeIt (timeItT)
 import System.IO.Unsafe (unsafePerformIO)
-import System.TimeIt    (timeItT)
 
 import PostgREST.AppState      (AppState, getConfig, getJwtCacheState,
                                 getTime)

src/PostgREST/Observation.hs

@@ -156,7 +156,7 @@ observationMessage = \case
     "Evicted entry from JWT cache"
   where
     showMillis :: Double -> Text
-    showMillis x = toS $ showFFloat (Just 1) (x * 1000) ""
+    showMillis x = toS $ showFFloat (Just 1) x ""
 
     jsonMessage err = T.decodeUtf8 . LBS.toStrict . Error.errorPayload $ Error.PgError False err
 

src/PostgREST/Response/Performance.hs

@@ -1,4 +1,3 @@
-{-# LANGUAGE NumericUnderscores #-}
 module PostgREST.Response.Performance
   ( ServerTiming (..)
   , serverTimingHeader
@@ -24,12 +23,12 @@ data ServerTiming =
 -- The duration precision is milliseconds, per the docs
 --
 -- >>> serverTimingHeader ServerTiming { plan=Just 0.1, transaction=Just 0.2, response=Just 0.3, jwt=Just 0.4, parse=Just 0.5}
--- ("Server-Timing","jwt;dur=400.0, parse;dur=500.0, plan;dur=100.0, transaction;dur=200.0, response;dur=300.0")
+-- ("Server-Timing","jwt;dur=0.4, parse;dur=0.5, plan;dur=0.1, transaction;dur=0.2, response;dur=0.3")
 serverTimingHeader :: ServerTiming -> HTTP.Header
 serverTimingHeader timing =
   ("Server-Timing", renderTiming)
   where
-    renderMetric metric = maybe "" (\dur -> BS.concat [metric, BS.pack $ ";dur=" <> showFFloat (Just 1) (dur * 1_000) ""])
+    renderMetric metric = maybe "" (\dur -> BS.concat [metric, BS.pack $ ";dur=" <> showFFloat (Just 1) dur ""])
     renderTiming = BS.intercalate ", " $ (\(k, v) -> renderMetric k (v timing)) <$>
       [ ("jwt", jwt)
       , ("parse", parse)

src/PostgREST/TimeIt.hs

@@ -0,0 +1,20 @@
+module PostgREST.TimeIt
+  ( timeItT
+  ) where
+
+import GHC.Clock
+import Protolude
+
+{-
+ - The signature is the same as https://hackage.haskell.org/package/timeit-2.0/docs/src/System-TimeIt.html#timeIt,
+ - we vendor this functionality because it gave errors as shown on https://github.com/PostgREST/postgrest/issues/4522 plus
+ - the function is small enough. This vendored function is different in that the result is in milliseconds.
+ -}
+timeItT :: MonadIO m => m a -> m (Double, a)
+timeItT p = do
+  s <- liftIO getMonotonicTime
+  x <- p
+  e <- liftIO getMonotonicTime
+  let time = (e - s) * 1000
+  return (time, x)
+

test/io/test_io.py

@@ -7,7 +7,7 @@ import time
 import pytest
 
 from config import CONFIGSDIR, FIXTURES, SECRET
-from util import Thread, jwtauthheader
+from util import Thread, jwtauthheader, parse_server_timings_header
 from postgrest import (
     freeport,
     is_ipv6,
@@ -1058,6 +1058,56 @@ def test_schema_cache_concurrent_notifications(slow_schema_cache_env):
         assert response.status_code == 200
 
 
+def test_schema_cache_query_sleep_logs(defaultenv):
+    """Schema cache sleep should be reflected in the logged query duration."""
+
+    env = {
+        **defaultenv,
+        "PGRST_INTERNAL_SCHEMA_CACHE_QUERY_SLEEP": "1000",
+    }
+    log_pattern = re.compile(r"Schema cache queried in ([\d.]+) milliseconds")
+
+    with run(env=env, wait_max_seconds=3, no_startup_stdout=False) as postgrest:
+        observed_ms = None
+        collected = []
+
+        lines = postgrest.read_stdout(nlines=10)
+        collected.extend(lines)
+        for line in lines:
+            match = log_pattern.search(line)
+            if match:
+                observed_ms = float(match.group(1))
+                break
+
+        assert observed_ms is not None
+        assert 1000 < observed_ms < 2000
+
+
+def test_schema_cache_load_sleep_logs(defaultenv):
+    """Schema cache load sleep should be reflected in the logged load duration."""
+
+    env = {
+        **defaultenv,
+        "PGRST_INTERNAL_SCHEMA_CACHE_LOAD_SLEEP": "1000",
+    }
+    log_pattern = re.compile(r"Schema cache loaded in ([\d.]+) milliseconds")
+
+    with run(env=env, wait_max_seconds=3, no_startup_stdout=False) as postgrest:
+        observed_ms = None
+        collected = []
+
+        lines = postgrest.read_stdout(nlines=10)
+        collected.extend(lines)
+        for line in lines:
+            match = log_pattern.search(line)
+            if match:
+                observed_ms = float(match.group(1))
+                break
+
+        assert observed_ms is not None
+        assert 1000 < observed_ms < 2000
+
+
 @pytest.mark.parametrize("dburi_type", ["no_params", "no_params_qmark", "with_params"])
 def test_get_pgrst_version_with_uri_connection_string(dburi_type, dburi, defaultenv):
     "The fallback_application_name should be added to the db-uri if it has a URI format"
@@ -1662,3 +1712,29 @@ def test_requests_without_resource_embedding_wait_for_schema_cache_reload(defaul
             response.elapsed.total_seconds() > 1
             and response.elapsed.total_seconds() < 5
         )
+
+
+def test_server_timing_transaction_duration(defaultenv, metapostgrest):
+    "server-timing transaction duration should be accurate"
+
+    # just to ensure we don't timeout
+    role = "timeout_authenticator"
+    set_statement_timeout(metapostgrest, role, 3000)  # 3 seconds
+
+    env = {
+        **defaultenv,
+        "PGUSER": role,
+        "PGRST_DB_ANON_ROLE": role,
+        "PGRST_SERVER_TIMING_ENABLED": "true",
+    }
+
+    with run(env=env) as postgrest:
+        response = postgrest.session.get("/rpc/sleep?seconds=2")
+
+        assert response.status_code == 204
+
+        response_dur = parse_server_timings_header(response.headers["Server-Timing"])[
+            "transaction"
+        ]
+
+        assert 2000 <= response_dur < 3000