Logs and server timing not showing the correct elapsed time

[laurenceisla]

Environment

• PostgreSQL version: v17
• PostgREST version: 14.1
• Operating system: MacOS 15

Description of issue

The logs are printing incorrect timings as shown here #4462 (comment). It seems the library has some kind of problem when calculating or getting the system time. The timeItT function should return the time in seconds but it doesn't seem to be that way, it needs to be multiplied by 100 to have the correct value.

This also happens when returning the server timing, e.g. this is what's currently showing:

curl localhost:3000/rpc/sleep?seconds=4 -i
...
Server-Timing: jwt;dur=0.1, parse;dur=0.3, plan;dur=0.3, transaction;dur=47.1, response;dur=0.6

But after I multiply it by 100 it returns a reasonable value (the transaction at least):

Server-Timing: jwt;dur=7.0, parse;dur=32.2, plan;dur=31.4, transaction;dur=4697.8, response;dur=54.4

However once the elapsed time is big enough the values are not accurate:

time curl localhost:3000/rpc/sleep?seconds=100 -i
...
Server-Timing: jwt;dur=8.3, parse;dur=38.7, plan;dur=35.8, transaction;dur=112025.0, response;dur=55.7
________________________________________________________
Executed in  100.03 secs      fish           external
   usr time    6.84 millis    0.38 millis    6.45 millis
   sys time   10.06 millis    1.62 millis    8.44 millis

The transaction shows 112 seconds vs the 100.03 it actually took. In contrast, replacing the process with a function that uses the Date.Time library logs the correct time:

    timeItT' p = do
      s <- liftIO getCurrentTime
      x <- p
      e <- liftIO getCurrentTime
      let time = realToFrac $ diffUTCTime e s
      return (time, x)

Server-Timing: jwt;dur=0.1, parse;dur=0.3, plan;dur=0.3, transaction;dur=100003.1, response;dur=0.6


________________________________________________________
Executed in  100.02 secs      fish           external

Solution

Fixing upstream would be one solution, but the Date.Time library mentioned above could be an alternative (I'm not aware of the drawbacks yet).

[steve-chavez]

but the Date.Time library mentioned above could be an alternative (I'm not aware of the drawbacks yet).

Yes please let's do that and reduce dependencies, we're already using that lib right?

postgrest/postgrest.cabal

Line 141 in 655fe7b

, time >= 1.6 && < 1.13

[steve-chavez]

curl localhost:3000/rpc/sleep?seconds=4 -i
Server-Timing: jwt;dur=0.1, parse;dur=0.3, plan;dur=0.3, transaction;dur=47.1, response;dur=0.6

We should have a test that validates the transaction;dur makes sense according to the sleep value.

[steve-chavez]

Can confirm the above, current tx duration:

$ curl localhost:3000/rpc/sleep?seconds=5 -i
HTTP/1.1 204 No Content
Date: Fri, 12 Dec 2025 22:22:45 GMT
Server: postgrest/15 (pre-release)
Content-Range: 0-0/*
Server-Timing: jwt;dur=0.0, parse;dur=0.1, plan;dur=0.1, transaction;dur=46.1, response;dur=0.0

With the fix using Date.Time:

$ curl localhost:3000/rpc/sleep?seconds=5 -i
HTTP/1.1 204 No Content
Date: Fri, 12 Dec 2025 22:26:49 GMT
Server: postgrest/15 (pre-release)
Content-Range: 0-0/*
Server-Timing: jwt;dur=0.0, parse;dur=0.1, plan;dur=0.1, transaction;dur=5007.3, response;dur=0.0