feat: add more perf counters to Server-Timing (#2983)

test/io/test_io.py

@@ -1119,15 +1119,15 @@ def test_server_timing_jwt_should_decrease_on_subsequent_requests(defaultenv):
     )
 
     with run(stdin=SECRET.encode(), env=env) as postgrest:
-        first_dur_text = postgrest.session.get(
-            "/authors_only", headers=headers
-        ).headers["Server-Timing"]
-        second_dur_text = postgrest.session.get(
+        first_timings = postgrest.session.get("/authors_only", headers=headers).headers[
+            "Server-Timing"
+        ]
+        second_timings = postgrest.session.get(
             "/authors_only", headers=headers
         ).headers["Server-Timing"]
 
-        first_dur = float(first_dur_text[8:])  # skip "jwt;dur="
-        second_dur = float(second_dur_text[8:])
+        first_dur = parse_server_timings_header(first_timings)["jwt"]
+        second_dur = parse_server_timings_header(second_timings)["jwt"]
 
         # their difference should be atleast 300, implying
         # that JWT Caching is working as expected
@@ -1172,15 +1172,15 @@ def test_server_timing_jwt_should_not_decrease_when_caching_disabled(defaultenv)
 
     with run(stdin=SECRET.encode(), env=env) as postgrest:
         warmup_req = postgrest.session.get("/authors_only", headers=headers)
-        first_dur_text = postgrest.session.get(
-            "/authors_only", headers=headers
-        ).headers["Server-Timing"]
-        second_dur_text = postgrest.session.get(
+        first_timings = postgrest.session.get("/authors_only", headers=headers).headers[
+            "Server-Timing"
+        ]
+        second_timings = postgrest.session.get(
             "/authors_only", headers=headers
         ).headers["Server-Timing"]
 
-        first_dur = float(first_dur_text[8:])  # skip "jwt;dur="
-        second_dur = float(second_dur_text[8:])
+        first_dur = parse_server_timings_header(first_timings)["jwt"]
+        second_dur = parse_server_timings_header(second_timings)["jwt"]
 
         # their difference should be less than 150
         # implying that token is not cached
@@ -1201,15 +1201,15 @@ def test_jwt_cache_with_no_exp_claim(defaultenv):
     headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET)  # no exp
 
     with run(stdin=SECRET.encode(), env=env) as postgrest:
-        first_dur_text = postgrest.session.get(
-            "/authors_only", headers=headers
-        ).headers["Server-Timing"]
-        second_dur_text = postgrest.session.get(
+        first_timings = postgrest.session.get("/authors_only", headers=headers).headers[
+            "Server-Timing"
+        ]
+        second_timings = postgrest.session.get(
             "/authors_only", headers=headers
         ).headers["Server-Timing"]
 
-        first_dur = float(first_dur_text[8:])  # skip "jwt;dur="
-        second_dur = float(second_dur_text[8:])
+        first_dur = parse_server_timings_header(first_timings)["jwt"]
+        second_dur = parse_server_timings_header(second_timings)["jwt"]
 
         # their difference should be atleast 300, implying
         # that JWT Caching is working as expected

test/io/util.py

@@ -40,3 +40,20 @@ def authheader(token):
 def jwtauthheader(claim, secret):
     "Authorization header with signed JWT."
     return authheader(jwt.encode(claim, secret))
+
+
+def parse_server_timings_header(header):
+    """Parse the Server-Timing header into a dict of metric names to values.
+
+    The header is a comma-separated list of metrics, each of which has a name
+    and a duration. The duration may be followed by a semicolon and a list of
+    parameters, but we ignore those.
+
+    See https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing
+    """
+    timings = {}
+    for timing in header.split(","):
+        name, duration_text, *_ = timing.split(";")
+        _, duration = duration_text.split("=")
+        timings[name] = float(duration)
+    return timings

test/spec/Feature/Query/ServerTimingSpec.hs

@@ -22,8 +22,7 @@ spec =
           `shouldRespondWith`
           [json|[{"id":6,"name":"Oscorp","referee":3,"auditor":4,"manager_id":6}]|]
           { matchStatus  = 200
-          , matchHeaders = [ matchContentTypeJson
-                           , matchHeaderPresent "Server-Timing"]
+          , matchHeaders = matchContentTypeJson : map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
           }
 
       it "works with post request" $
@@ -33,8 +32,7 @@ spec =
           `shouldRespondWith`
           [json|[{"id":7,"name":"John","referee":null,"auditor":null,"manager_id":6}]|]
           { matchStatus  = 201
-          , matchHeaders = [ matchContentTypeJson
-                           , matchHeaderPresent "Server-Timing"]
+          , matchHeaders = matchContentTypeJson : map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
           }
 
       it "works with patch request" $
@@ -43,8 +41,7 @@ spec =
           `shouldRespondWith`
             ""
             { matchStatus  = 204
-            , matchHeaders = [ matchHeaderAbsent hContentType
-                             , matchHeaderPresent "Server-Timing" ]
+            , matchHeaders = matchHeaderAbsent hContentType : map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
             }
 
       it "works with put request" $
@@ -54,7 +51,7 @@ spec =
           `shouldRespondWith`
             [json| [ { "name": "Go", "rank": 19 } ]|]
             { matchStatus  = 200
-            , matchHeaders = [ matchHeaderPresent "Server-Timing" ]
+            , matchHeaders = map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
             }
 
       it "works with delete request" $
@@ -64,8 +61,7 @@ spec =
           `shouldRespondWith`
             ""
             { matchStatus  = 204
-            , matchHeaders = [ matchHeaderAbsent hContentType
-                             , matchHeaderPresent "Server-Timing" ]
+            , matchHeaders = matchHeaderAbsent hContentType : map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
             }
 
       it "works with rpc call" $
@@ -75,5 +71,5 @@ spec =
           `shouldRespondWith`
           [json|{"x": 1, "y": 2}|]
           { matchStatus  = 200
-          , matchHeaders = [ matchHeaderPresent "Server-Timing" ]
+          , matchHeaders = map matchServerTimingHasTiming ["jwt", "plan", "query", "render"]
           }

test/spec/SpecHelper.hs

@@ -24,6 +24,7 @@ import Test.Hspec.Wai
 import Test.Hspec.Wai.JSON
 import Text.Heredoc
 
+import Data.String                       (String)
 import PostgREST.Config                  (AppConfig (..),
                                           JSPathExp (..),
                                           LogLevel (..),
@@ -58,11 +59,14 @@ matchHeaderAbsent name = MatchHeader $ \headers _body ->
     Just _  -> Just $ "unexpected header: " <> toS (original name) <> "\n"
     Nothing -> Nothing
 
-matchHeaderPresent :: HeaderName -> MatchHeader
-matchHeaderPresent name = MatchHeader $ \headers _body ->
-  case lookup name headers of
-    Just _  -> Nothing
-    Nothing -> Just $ "missing header: " <> toS (original name) <> "\n"
+-- | Matches Server-Timing header has a well-formed metric with the given name
+matchServerTimingHasTiming :: String -> MatchHeader
+matchServerTimingHasTiming metric = MatchHeader $ \headers _body ->
+  case lookup "Server-Timing" headers of
+    Just hdr -> if hdr =~ (metric <> ";dur=[[:digit:]]+.[[:digit:]]+")
+                  then Nothing
+                  else Just $ "missing metric: " <> metric <> "\n"
+    Nothing  -> Just "missing Server-Timing header\n"
 
 validateOpenApiResponse :: [Header] -> WaiSession () ()
 validateOpenApiResponse headers = do