fix: inaccurate Server-Timing durations #4544

steve-chavez · 2025-12-12T23:10:46Z

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 #4522, fixes #4551

src/PostgREST/TimeIt.hs

test/io/test_io.py

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 PostgREST#4522

steve-chavez · 2025-12-13T20:32:17Z

There seems to be a slight loss of performance on the JWT loadtests and I'm very puzzled by it, do we use the timeItT function at all on those tests?

Specially the jwt-hs-cache-worst test which never failed before and now shows 401 Unauthorized plus degraded perf: https://github.com/PostgREST/postgrest/actions/runs/20197230049?pr=4544#summary-57982981100

Note: don'get confused by jwt-rsa-cache-worst, which is flaky and fails with 401 Unauthorized sometimes.

steve-chavez · 2025-12-13T20:39:11Z

There seems to be a slight loss of performance on the JWT loadtests and I'm very puzzled by it, do we use the timeItT function at all on those tests?

Makes no sense since PGRST_SERVER_TIMING_ENABLED=true is not done on those.

steve-chavez · 2025-12-13T20:46:48Z

Ah, I see it now, we use timeItT at startup time here:

postgrest/src/PostgREST/AppState.hs

Lines 419 to 421 in b2029af

    
           observer $ SchemaCacheQueriedObs resultTime 
        
           (t, _) <- timeItT $ observer $ SchemaCacheSummaryObs $ showSummary sCache 
        
           observer $ SchemaCacheLoadedObs t

This is when we show:

13/Dec/2025:15:46:31 -0500: Schema cache queried in 140.8 milliseconds
13/Dec/2025:15:46:31 -0500: Schema cache loaded 271 Relations, 232 Relationships, 149 Functions, 15 Domain Representations, 45 Media Type Handlers, 1196 Timezones
13/Dec/2025:15:46:31 -0500: Schema cache loaded in 5.4 milliseconds

The jwt loadtests consider this startup time for an estimate:

postgrest/nix/tools/generate_targets.py

Lines 134 to 135 in b2029af

    
           # estimated time takes to build and run postgrest itself 
        
           build_run_postgrest_time = 2

steve-chavez · 2025-12-13T20:48:50Z

This likely means that the perf loss when enabling server-timing is higher now: #3410 (comment) (used to be ~6.5%)

steve-chavez · 2025-12-14T01:08:25Z

Btw, with this change the initial load is modified/corrected too:

old

13/Dec/2025:20:04:06 -0500: Schema cache queried in 16.9 milliseconds
13/Dec/2025:20:04:06 -0500: Schema cache loaded 271 Relations, 232 Relationships, 149 Functions, 15 Domain Representations, 45 Media Type Handlers, 1196 Timezones
13/Dec/2025:20:04:06 -0500: Schema cache loaded in 7.5 milliseconds


13/Dec/2025:20:04:10 -0500: Schema cache queried in 15.2 milliseconds
13/Dec/2025:20:04:10 -0500: Schema cache loaded 271 Relations, 232 Relationships, 149 Functions, 15 Domain Representations, 45 Media Type Handlers, 1196 Timezones
13/Dec/2025:20:04:10 -0500: Schema cache loaded in 6.0 milliseconds

new

13/Dec/2025:20:04:27 -0500: Schema cache queried in 193.1 milliseconds
13/Dec/2025:20:04:27 -0500: Schema cache loaded 271 Relations, 232 Relationships, 149 Functions, 15 Domain Representations, 45 Media Type Handlers, 1196 Timezones
13/Dec/2025:20:04:27 -0500: Schema cache loaded in 7.9 milliseconds

13/Dec/2025:20:04:32 -0500: Schema cache queried in 188.4 milliseconds
13/Dec/2025:20:04:32 -0500: Schema cache loaded 271 Relations, 232 Relationships, 149 Functions, 15 Domain Representations, 45 Media Type Handlers, 1196 Timezones
13/Dec/2025:20:04:32 -0500: Schema cache loaded in 6.4 milliseconds

Edit: will add a test for this. I can also confirm the recent gains on #4396 (comment) are maintained (the Schema cache loaded logs are the same, only the Schema cache queried .. logs were wrong).

steve-chavez · 2025-12-14T03:34:16Z

The jwt loadtests consider this startup time for an estimate:

I've tried fiddling with that but no dice 😕 .. I'm going to have to rework those loadtests before merging here.

Also print last unauthorized body

steve-chavez · 2025-12-15T22:44:36Z

The jwt loadtests consider this startup time for an estimate:
build_run_postgrest_time = 2

Looks like on the jwt-hs-cache-worst loadtest the responses are indeed slower. I've added some extra logs to debug, see:

loadtest failed: found 71824 401 Unauthorized responses
Last 401 response body:
{"code":"PGRST303","details":null,"hint":null,"message":"JWT expired"}
https://github.com/PostgREST/postgrest/actions/runs/20248536993/job/58134780051

By increasing the build_run_postgrest_time by 50s (74b8941) the expire time, we get fewer errors

loadtest failed: found 15277 401 Unauthorized responses
Last 401 response body:
{"code":"PGRST303","details":null,"hint":null,"message":"JWT expired"}
https://github.com/PostgREST/postgrest/actions/runs/20249251648/job/58137218950

By increasing to 100s (2bb7ab0), we don't get errors (https://github.com/PostgREST/postgrest/actions/runs/20248902699/job/58136016682)

But clearly this is no longer about the startup time, the increase is too much and doesn't make sense (manually testing it it cannot be more than 1s).

The new timeItT has to be affecting the JWT validation speed somehow, but it's not clear at all how.

steve-chavez · 2025-12-15T23:32:29Z

I compared the loadtest on both branches with a profiled build, we can do this now (after the work on #4219):

PGRST_CMD=postgrest-profiled-run postgrest-loadtest -k jwt-hs-cache-worst

And there's no meaningful difference:

main

Mon Dec 15 18:12 2025 Time and Allocation Profiling Report (Final)

   postgrest +RTS -N -I0 -qg -p -h -RTS /nix/store/029dn97slxdcvhq01bwaw81dwnbjzq2i-legacy.conf

total time  =       11.51 secs   (35848 ticks @ 1000 us, 16 processors)
total alloc = 10,075,656,784 bytes  (excludes profiling overheads)

COST CENTRE MODULE SRC %time %alloc

parse PostgREST.ApiRequest.QueryParams src/PostgREST/ApiRequest/QueryParams.hs:(116,1)-(182,85) 10.1 19.0
withFdSocket Network.Socket.Types dist/build/Network/Socket/Types.hs:(180,1)-(188,10) 6.1 0.9
cached PostgREST.Cache.Sieve src/PostgREST/Cache/Sieve.hs:(84,1)-(218,60) 3.3 3.8
fromBase64URLUnpadded Data.Memory.Encoding.Base64 Data/Memory/Encoding/Base64.hs:140:1-74 3.2 16.5
MAIN MAIN 3.1 1.1
parseClaims PostgREST.Auth.Jwt src/PostgREST/Auth/Jwt.hs:(121,1)-(151,59) 3.1 1.5
throwSocketErrorWaitWrite Network.Socket.Internal Network/Socket/Internal.hs:(249,1)-(251,44) 2.9 0.1
onBranchElement StmHamt.Focuses library/StmHamt/Focuses.hs:(14,1)-(36,23) 2.7 3.2
copyAndFreeze Data.ByteArray.Methods Data/ByteArray/Methods.hs:(237,1)-(240,21) 2.5 2.7
parseJwt Jose.Internal.Parser Jose/Internal/Parser.hs:57:1-58 2.2 1.8
convertFromBase Data.ByteArray.Encoding Data/ByteArray/Encoding.hs:(114,1)-(161,114) 2.2 3.0
postgrest PostgREST.App src/PostgREST/App.hs:(93,1)-(123,20) 2.2 1.5
userApiRequest PostgREST.ApiRequest src/PostgREST/ApiRequest.hs:(80,1)-(111,89) 2.1 0.7
sendResponse Network.Wai.Handler.Warp.Response Network/Wai/Handler/Warp/Response.hs:(123,1)-(173,30) 2.0 1.1
bsToTokens Data.Aeson.Decoding.ByteString src/Data/Aeson/Decoding/ByteString.hs:(33,1)-(101,47) 2.0 4.2
decode Jose.Jwt Jose/Jwt.hs:(90,1)-(127,28) 1.8 1.7
parseAndDecodeClaims PostgREST.Auth.Jwt src/PostgREST/Auth/Jwt.hs:49:1-76 1.7 1.8
whileM Control.Monad.Extra src/Control/Monad/Extra.hs:(168,1)-(170,23) 1.7 0.9
traverse Data.Aeson.KeyMap src/Data/Aeson/KeyMap.hs:226:1-50 1.7 2.4
recvRequest Network.Wai.Handler.Warp.Request Network/Wai/Handler/Warp/Request.hs:(81,1)-(120,50) 1.6 1.1
parseHeaderLines Network.Wai.Handler.Warp.RequestHeader Network/Wai/Handler/Warp/RequestHeader.hs:(36,1)-(41,57) 1.6 3.2
withObject Data.Aeson.Types.FromJSON src/Data/Aeson/Types/FromJSON.hs:(720,1)-(721,78) 1.4 2.0
toResultValue Data.Aeson.Decoding.Conversion src/Data/Aeson/Decoding/Conversion.hs:51:1-38 1.3 1.4
http1 Network.Wai.Handler.Warp.HTTP1 Network/Wai/Handler/Warp/HTTP1.hs:(41,1)-(103,50) 1.2 0.5
fromList Data.Aeson.KeyMap src/Data/Aeson/KeyMap.hs:247:1-30 1.1 1.1
initialize Crypto.MAC.HMAC Crypto/MAC/HMAC.hs:(75,1)-(112,34) 1.1 1.2
withPtr Basement.Block.Base Basement/Block/Base.hs:(401,1)-(410,31) 1.1 0.8
ifromJSON Data.Aeson.Types.FromJSON src/Data/Aeson/Types/FromJSON.hs:839:1-28 1.1 0.3
withText Data.Aeson.Types.FromJSON src/Data/Aeson/Types/FromJSON.hs:(731,1)-(732,76) 1.1 1.1
headerLines Network.Wai.Handler.Warp.Request Network/Wai/Handler/Warp/Request.hs:(125,1)-(136,66) 1.1 0.9
middleware PostgREST.Auth src/PostgREST/Auth.hs:(44,1)-(60,18) 1.1 0.3
onHamtElement StmHamt.Focuses library/StmHamt/Focuses.hs:(39,1)-(57,34) 1.1 1.2
composeHeader Network.Wai.Handler.Warp.ResponseHeader Network/Wai/Handler/Warp/ResponseHeader.hs:(21,1)-(28,45) 1.0 1.1
atomicModifyIORefCAS_ Data.Atomics Data/Atomics.hs:(443,1)-(454,29) 1.0 0.2

head

Mon Dec 15 17:58 2025 Time and Allocation Profiling Report (Final)

   postgrest +RTS -N -I0 -qg -p -h -RTS /nix/store/029dn97slxdcvhq01bwaw81dwnbjzq2i-legacy.conf

total time  =       11.77 secs   (36665 ticks @ 1000 us, 16 processors)
total alloc = 8,140,671,648 bytes  (excludes profiling overheads)

COST CENTRE MODULE SRC %time %alloc

parse PostgREST.ApiRequest.QueryParams src/PostgREST/ApiRequest/QueryParams.hs:(116,1)-(182,85) 9.6 19.0
withFdSocket Network.Socket.Types dist/build/Network/Socket/Types.hs:(180,1)-(188,10) 6.2 0.9
cached PostgREST.Cache.Sieve src/PostgREST/Cache/Sieve.hs:(84,1)-(218,60) 3.6 3.8
fromBase64URLUnpadded Data.Memory.Encoding.Base64 Data/Memory/Encoding/Base64.hs:140:1-74 3.2 16.5
parseClaims PostgREST.Auth.Jwt src/PostgREST/Auth/Jwt.hs:(121,1)-(151,59) 3.1 1.5
MAIN MAIN 3.1 1.1
throwSocketErrorWaitWrite Network.Socket.Internal Network/Socket/Internal.hs:(249,1)-(251,44) 2.9 0.1
onBranchElement StmHamt.Focuses library/StmHamt/Focuses.hs:(14,1)-(36,23) 2.7 3.2
copyAndFreeze Data.ByteArray.Methods Data/ByteArray/Methods.hs:(237,1)-(240,21) 2.4 2.7
convertFromBase Data.ByteArray.Encoding Data/ByteArray/Encoding.hs:(114,1)-(161,114) 2.3 3.0
postgrest PostgREST.App src/PostgREST/App.hs:(93,1)-(123,20) 2.2 1.5
parseJwt Jose.Internal.Parser Jose/Internal/Parser.hs:57:1-58 2.1 1.8
bsToTokens Data.Aeson.Decoding.ByteString src/Data/Aeson/Decoding/ByteString.hs:(33,1)-(101,47) 2.0 4.2
sendResponse Network.Wai.Handler.Warp.Response Network/Wai/Handler/Warp/Response.hs:(123,1)-(173,30) 1.9 1.1
userApiRequest PostgREST.ApiRequest src/PostgREST/ApiRequest.hs:(80,1)-(111,89) 1.9 0.7
decode Jose.Jwt Jose/Jwt.hs:(90,1)-(127,28) 1.8 1.7
parseHeaderLines Network.Wai.Handler.Warp.RequestHeader Network/Wai/Handler/Warp/RequestHeader.hs:(36,1)-(41,57) 1.7 3.2
whileM Control.Monad.Extra src/Control/Monad/Extra.hs:(168,1)-(170,23) 1.7 0.9
recvRequest Network.Wai.Handler.Warp.Request Network/Wai/Handler/Warp/Request.hs:(81,1)-(120,50) 1.7 1.1
parseAndDecodeClaims PostgREST.Auth.Jwt src/PostgREST/Auth/Jwt.hs:49:1-76 1.7 1.8
traverse Data.Aeson.KeyMap src/Data/Aeson/KeyMap.hs:226:1-50 1.6 2.4
withObject Data.Aeson.Types.FromJSON src/Data/Aeson/Types/FromJSON.hs:(720,1)-(721,78) 1.4 2.0
toResultValue Data.Aeson.Decoding.Conversion src/Data/Aeson/Decoding/Conversion.hs:51:1-38 1.3 1.4
onHamtElement StmHamt.Focuses library/StmHamt/Focuses.hs:(39,1)-(57,34) 1.2 1.2
composeHeader Network.Wai.Handler.Warp.ResponseHeader Network/Wai/Handler/Warp/ResponseHeader.hs:(21,1)-(28,45) 1.2 1.1
middleware PostgREST.Auth src/PostgREST/Auth.hs:(44,1)-(60,18) 1.1 0.3
initialize Crypto.MAC.HMAC Crypto/MAC/HMAC.hs:(75,1)-(112,34) 1.1 1.2
fromList Data.Aeson.KeyMap src/Data/Aeson/KeyMap.hs:247:1-30 1.1 1.1
headerLines Network.Wai.Handler.Warp.Request Network/Wai/Handler/Warp/Request.hs:(125,1)-(136,66) 1.1 0.9
withPtr Basement.Block.Base Basement/Block/Base.hs:(401,1)-(410,31) 1.1 0.8
withText Data.Aeson.Types.FromJSON src/Data/Aeson/Types/FromJSON.hs:(731,1)-(732,76) 1.1 1.1
http1 Network.Wai.Handler.Warp.HTTP1 Network/Wai/Handler/Warp/HTTP1.hs:(41,1)-(103,50) 1.0 0.5
atomicModifyIORefCAS_ Data.Atomics Data/Atomics.hs:(443,1)-(454,29) 1.0 0.2
traverseHeader Network.Wai.Handler.Warp.Header Network/Wai/Handler/Warp/Header.hs:(113,1)-(122,26) 1.0 0.5

steve-chavez · 2025-12-16T02:30:11Z

The jwt loadtests consider this startup time for an estimate:
build_run_postgrest_time = 2

Turns out the above didn't really consider the build time when the cache is invalidated (happens here because postgrest.cabal is modified). The cached builds take 2 or 3 seconds but when building HEAD, it takes 90 seconds as seen below:

Running "jwt-hs-cache-worst" loadtest on "main"...

Preparing worktree (new branch 'main')
Generating 200000 targets...
Created 200000 targets in /home/runner/work/postgrest/postgrest/test/load/gen_targets.http (3.21s)
postgrest-with-pg-17: You can connect with: psql 'postgres:///postgres?host=/tmp/postgrest-with-pg-17-95s/socket' -U postgres
postgrest-with-pg-17: You can tail the logs with: tail -f /tmp/postgrest-with-pg-17-95s/db.log
Building postgrest (nix)... done in 3s.

Running "jwt-hs-cache-worst" loadtest on "v14.1"...

Preparing worktree (detached HEAD b3b4e5ff)
Generating 200000 targets...
Created 200000 targets in /home/runner/work/postgrest/postgrest/test/load/gen_targets.http (3.16s)
postgrest-with-pg-17: You can connect with: psql 'postgres:///postgres?host=/tmp/postgrest-with-pg-17-US7/socket' -U postgres
postgrest-with-pg-17: You can tail the logs with: tail -f /tmp/postgrest-with-pg-17-US7/db.log
Building postgrest (nix)... done in 2s.

Running "jwt-hs-cache-worst" loadtest on HEAD...

Generating 200000 targets...
Created 200000 targets in /home/runner/work/postgrest/postgrest/test/load/gen_targets.http (3.30s)
postgrest-with-pg-17: You can connect with: psql 'postgres:///postgres?host=/tmp/postgrest-with-pg-17-TcA/socket' -U postgres
postgrest-with-pg-17: You can tail the logs with: tail -f /tmp/postgrest-with-pg-17-TcA/db.log
Building postgrest (nix)... done in 90s.

(From https://github.com/PostgREST/postgrest/actions/runs/20254022788/job/58152032057?pr=4544)

Will correct that separate from this PR.

steve-chavez force-pushed the fix-server-timing branch from 789777d to 3a6efed Compare December 12, 2025 23:13

steve-chavez marked this pull request as ready for review December 12, 2025 23:13

steve-chavez requested a review from laurenceisla December 12, 2025 23:25

laurenceisla reviewed Dec 13, 2025

View reviewed changes

src/PostgREST/TimeIt.hs Show resolved Hide resolved

taimoorzaeem reviewed Dec 13, 2025

View reviewed changes

test/io/test_io.py Outdated Show resolved Hide resolved

steve-chavez force-pushed the fix-server-timing branch 2 times, most recently from c546d39 to b5d164b Compare December 13, 2025 19:42

fix: inaccurate Server-Timing durations

b2029af

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 PostgREST#4522

steve-chavez force-pushed the fix-server-timing branch from b5d164b to b2029af Compare December 13, 2025 20:09

laurenceisla approved these changes Dec 13, 2025

View reviewed changes

steve-chavez force-pushed the fix-server-timing branch 3 times, most recently from 321ef10 to 68e5d78 Compare December 14, 2025 03:17

steve-chavez marked this pull request as draft December 14, 2025 03:32

steve-chavez force-pushed the fix-server-timing branch 4 times, most recently from 871f4f4 to d1cb8dd Compare December 15, 2025 21:11

nix: fail jwt loadtest in case of 401

095ea0a

Also print last unauthorized body

steve-chavez force-pushed the fix-server-timing branch 2 times, most recently from 9c82e24 to 095ea0a Compare December 15, 2025 21:47

steve-chavez added 2 commits December 15, 2025 17:01

try fixing loadtest

2bb7ab0

try reducing loadtest build_run_postgrest_time

74b8941

steve-chavez force-pushed the fix-server-timing branch 3 times, most recently from c434832 to 2998b97 Compare December 16, 2025 00:15

nix: print the build time

d0c6944

steve-chavez force-pushed the fix-server-timing branch from 2998b97 to d0c6944 Compare December 16, 2025 02:05

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

fix: inaccurate Server-Timing durations #4544

fix: inaccurate Server-Timing durations #4544

steve-chavez commented Dec 12, 2025 •

edited

Loading

Uh oh!

Uh oh!

Uh oh!

steve-chavez commented Dec 13, 2025 •

edited

Loading

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 14, 2025 •

edited

Loading

Uh oh!

steve-chavez commented Dec 14, 2025

Uh oh!

steve-chavez commented Dec 15, 2025

Uh oh!

steve-chavez commented Dec 15, 2025

Uh oh!

steve-chavez commented Dec 16, 2025

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

3 participants

Uh oh!

fix: inaccurate Server-Timing durations #4544

Are you sure you want to change the base?

fix: inaccurate Server-Timing durations #4544

Conversation

steve-chavez commented Dec 12, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

steve-chavez commented Dec 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 13, 2025

Uh oh!

steve-chavez commented Dec 14, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

old

new

Uh oh!

steve-chavez commented Dec 14, 2025

Uh oh!

steve-chavez commented Dec 15, 2025

Uh oh!

steve-chavez commented Dec 15, 2025

Uh oh!

steve-chavez commented Dec 16, 2025

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

3 participants

steve-chavez commented Dec 12, 2025 •

edited

Loading

steve-chavez commented Dec 13, 2025 •

edited

Loading

steve-chavez commented Dec 14, 2025 •

edited

Loading