Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Server-Timing response header #2771

Closed
steve-chavez opened this issue Apr 27, 2023 · 11 comments · Fixed by #2983
Closed

Server-Timing response header #2771

steve-chavez opened this issue Apr 27, 2023 · 11 comments · Fixed by #2983
Labels
enhancement a feature, ready for implementation

Comments

@steve-chavez
Copy link
Member

steve-chavez commented Apr 27, 2023

Problem

Currently there's no way to debug the time we take to parse the request and the time we take to receive the query response. The EXPLAIN execution plan, only obtains the query time, but not the aforementioned two.

Solution

Add the standard Server-Timing header. This can communicate all types of metrics for a given request-response cycle.

An example response would be like:

GET /projects?id=eq.3

Server-Timing: jwt;dur=34, app;dur=47.2, db;dur=53, render;dur=15

Which would mean the jwt ("jwt") decoding time was 34 ms, the parsing + planning("app") took 47.2ms, the database ("db") query time was 53 ms, and we took 15 ms to obtain the query response("render", this is relevant to #2770).

To avoid doing this work for all the requests:

  • We can add Server-Timing whenever the Prefer: server-timing=include header is specified.
  • Or enable it whenever db-plan-enabled is turned on.

References:

@steve-chavez steve-chavez added the idea Needs of discussion to become an enhancement, not ready for implementation label Apr 27, 2023
@steve-chavez
Copy link
Member Author

Seems this might be simple with the timeit package: https://hackage.haskell.org/package/timeit-1.0.0.0/docs/System-TimeIt.html. Since the functions are so small we could also vendor the functionality.

Got that from this blog post: https://chrisdone.com/posts/measuring-duration-in-haskell/

@steve-chavez
Copy link
Member Author

steve-chavez commented May 1, 2023

If parsing(parsec) time is high, we can look into switching to https://github.com/AndrasKovacs/flatparse

edit: maybe unfeasible as flatparse looks low-level and lacking some of the combinators we use.

@steve-chavez steve-chavez added enhancement a feature, ready for implementation and removed idea Needs of discussion to become an enhancement, not ready for implementation labels Aug 28, 2023
@steve-chavez
Copy link
Member Author

steve-chavez commented Aug 29, 2023

Doing this for app, db, render in the current codebase would be repetitive:

     (ActionRead headersOnly, TargetIdent identifier) -> do 
       wrPlan <- liftEither $ Plan.wrappedReadPlan identifier conf sCache apiReq 
       -- timeit
       resultSet <- runQuery roleIsoLvl (Plan.wrTxMode wrPlan) $ Query.readQuery wrPlan conf apiReq 
      -- timeit
       return $ Response.readResponse headersOnly identifier apiReq resultSet 
  
     (ActionMutate MutationCreate, TargetIdent identifier) -> do 
       mrPlan <- liftEither $ Plan.mutateReadPlan MutationCreate apiReq identifier conf sCache
       -- timeit 
       resultSet <- runQuery roleIsoLvl (Plan.mrTxMode mrPlan) $ Query.createQuery mrPlan apiReq conf 
       -- timeit
       return $ Response.createResponse identifier mrPlan apiReq resultSet 

(ref)

We would need refactoring for these. Basically have a single function exposed on the Plan, Query and Response modules and have App use those.

For now I'm thinking of the following steps, the main idea is to make the Response and Query modules pure; this will also enable those to be "doctested":


For jwt, it might be possible already, we need to timeit here somehow:

\req respond -> case fromJust $ Auth.getResult req of

Or somewhere in the Auth module, maybe by storing it on the Vault and then retrieving it on App.

@taimoorzaeem
Copy link
Collaborator

@steve-chavez @laurenceisla I have sort of implemented the Server-Timing but I am not sure how to test it. FYI, to test this feature I need to enable configurations like db-plan-enabled and jwt-caching. Would the test belong to spec-tests or io-tests? I am confused because matching headers seems to belong to spec tests but setting up configurations seem to belong to io-tests.

@steve-chavez
Copy link
Member Author

@taimoorzaeem I think it should be fine as a spec test, there are some examples here where we use different configs for each spec:

let withApp = app testCfg
maxRowsApp = app testMaxRowsCfg
disabledOpenApi = app testDisabledOpenApiCfg
securityOpenApi = app testSecurityOpenApiCfg
proxyApp = app testProxyCfg
noAnonApp = app testCfgNoAnon
noJwtApp = app testCfgNoJWT
binaryJwtApp = app testCfgBinaryJWT
audJwtApp = app testCfgAudienceJWT
asymJwkApp = app testCfgAsymJWK
asymJwkSetApp = app testCfgAsymJWKSet
rootSpecApp = app testCfgRootSpec
htmlRawOutputApp = app testCfgHtmlRawOutput
responseHeadersApp = app testCfgResponseHeaders
disallowRollbackApp = app testCfgDisallowRollback
forceRollbackApp = app testCfgForceRollback
testCfgLegacyGucsApp = app testCfgLegacyGucs
planEnabledApp = app testPlanEnabledCfg
pgSafeUpdateApp = app testPgSafeUpdateEnabledCfg
obsApp = app testObservabilityCfg
extraSearchPathApp = appDbs testCfgExtraSearchPath
unicodeApp = appDbs testUnicodeCfg
nonexistentSchemaApp = appDbs testNonexistentSchemaCfg
multipleSchemaApp = appDbs testMultipleSchemaCfg
ignorePrivOpenApi = appDbs testIgnorePrivOpenApiCfg
let analyze :: IO ()
analyze = do
analyzeTable "items"
analyzeTable "child_entities"
specs = uncurry describe <$> [
("Feature.Query.AndOrParamsSpec" , Feature.Query.AndOrParamsSpec.spec actualPgVersion)
, ("Feature.Auth.AuthSpec" , Feature.Auth.AuthSpec.spec actualPgVersion)
, ("Feature.ConcurrentSpec" , Feature.ConcurrentSpec.spec)
, ("Feature.CorsSpec" , Feature.CorsSpec.spec)
, ("Feature.Query.DeleteSpec" , Feature.Query.DeleteSpec.spec)
, ("Feature.Query.EmbedDisambiguationSpec" , Feature.Query.EmbedDisambiguationSpec.spec)
, ("Feature.Query.EmbedInnerJoinSpec" , Feature.Query.EmbedInnerJoinSpec.spec)
, ("Feature.Query.InsertSpec" , Feature.Query.InsertSpec.spec actualPgVersion)
, ("Feature.Query.JsonOperatorSpec" , Feature.Query.JsonOperatorSpec.spec actualPgVersion)
, ("Feature.OpenApi.OpenApiSpec" , Feature.OpenApi.OpenApiSpec.spec actualPgVersion)
, ("Feature.OptionsSpec" , Feature.OptionsSpec.spec actualPgVersion)
, ("Feature.Query.PgSafeUpdateSpec.disabledSpec" , Feature.Query.PgSafeUpdateSpec.disabledSpec)
, ("Feature.Query.PlanSpec.disabledSpec" , Feature.Query.PlanSpec.disabledSpec)
, ("Feature.Query.QuerySpec" , Feature.Query.QuerySpec.spec actualPgVersion)
, ("Feature.Query.RawOutputTypesSpec" , Feature.Query.RawOutputTypesSpec.spec)
, ("Feature.Query.RpcSpec" , Feature.Query.RpcSpec.spec actualPgVersion)
, ("Feature.Query.SingularSpec" , Feature.Query.SingularSpec.spec)
, ("Feature.Query.NullsStrip" , Feature.Query.NullsStrip.spec)
, ("Feature.Query.UpdateSpec" , Feature.Query.UpdateSpec.spec actualPgVersion)
, ("Feature.Query.UpsertSpec" , Feature.Query.UpsertSpec.spec actualPgVersion)
, ("Feature.Query.ComputedRelsSpec" , Feature.Query.ComputedRelsSpec.spec)
, ("Feature.Query.RelatedQueriesSpec" , Feature.Query.RelatedQueriesSpec.spec)
, ("Feature.Query.SpreadQueriesSpec" , Feature.Query.SpreadQueriesSpec.spec)
, ("Feature.NoSuperuserSpec" , Feature.NoSuperuserSpec.spec)
]
hspec $ do
mapM_ (parallel . before withApp) specs
-- we analyze to get accurate results from EXPLAIN
parallel $ beforeAll_ analyze . before withApp $
describe "Feature.Query.RangeSpec" Feature.Query.RangeSpec.spec
-- this test runs with a raw-output-media-types set to text/html
parallel $ before htmlRawOutputApp $
describe "Feature.Query.HtmlRawOutputSpec" Feature.Query.HtmlRawOutputSpec.spec
-- this test runs with a different server flag
parallel $ before maxRowsApp $
describe "Feature.Query.QueryLimitedSpec" Feature.Query.QueryLimitedSpec.spec
-- this test runs with a different schema
parallel $ before unicodeApp $
describe "Feature.Query.UnicodeSpec" Feature.Query.UnicodeSpec.spec
-- this test runs with openapi-mode set to disabled
parallel $ before disabledOpenApi $
describe "Feature.DisabledOpenApiSpec" Feature.OpenApi.DisabledOpenApiSpec.spec
-- this test runs with openapi-mode set to ignore-acl
parallel $ before ignorePrivOpenApi $
describe "Feature.OpenApi.IgnorePrivOpenApiSpec" Feature.OpenApi.IgnorePrivOpenApiSpec.spec
-- this test runs with a proxy
parallel $ before proxyApp $
describe "Feature.OpenApi.ProxySpec" Feature.OpenApi.ProxySpec.spec
-- this test runs with openapi-security-active set to true
parallel $ before securityOpenApi $
describe "Feature.OpenApi.SecurityOpenApiSpec" Feature.OpenApi.SecurityOpenApiSpec.spec
-- this test runs without an anonymous role
parallel $ before noAnonApp $
describe "Feature.Auth.NoAnonSpec" Feature.Auth.NoAnonSpec.spec
-- this test runs without a JWT secret
parallel $ before noJwtApp $
describe "Feature.Auth.NoJwtSpec" Feature.Auth.NoJwtSpec.spec
-- this test runs with a binary JWT secret
parallel $ before binaryJwtApp $
describe "Feature.Auth.BinaryJwtSecretSpec" Feature.Auth.BinaryJwtSecretSpec.spec
-- this test runs with a binary JWT secret and an audience claim
parallel $ before audJwtApp $
describe "Feature.Auth.AudienceJwtSecretSpec" Feature.Auth.AudienceJwtSecretSpec.spec
-- this test runs with asymmetric JWK
parallel $ before asymJwkApp $
describe "Feature.Auth.AsymmetricJwtSpec" Feature.Auth.AsymmetricJwtSpec.spec
-- this test runs with asymmetric JWKSet
parallel $ before asymJwkSetApp $
describe "Feature.Auth.AsymmetricJwtSpec" Feature.Auth.AsymmetricJwtSpec.spec
-- this test runs with a nonexistent db-schema
parallel $ before nonexistentSchemaApp $
describe "Feature.Query.ErrorSpec" Feature.Query.ErrorSpec.spec
-- this test runs with an extra search path
parallel $ before extraSearchPathApp $ do
describe "Feature.ExtraSearchPathSpec" Feature.ExtraSearchPathSpec.spec
describe "Feature.Query.PostGISSpec" $ Feature.Query.PostGISSpec.spec actualPgVersion
-- this test runs with a root spec function override
parallel $ before rootSpecApp $
describe "Feature.OpenApi.RootSpec" Feature.OpenApi.RootSpec.spec
-- this test runs with a pre request function override
parallel $ before responseHeadersApp $
describe "Feature.RpcPreRequestGucsSpec" Feature.RpcPreRequestGucsSpec.spec
-- this test runs with multiple schemas
parallel $ before multipleSchemaApp $
describe "Feature.Query.MultipleSchemaSpec" Feature.Query.MultipleSchemaSpec.spec
-- this test runs with db-uses-legacy-gucs = false
parallel $ before testCfgLegacyGucsApp $
describe "Feature.LegacyGucsSpec" Feature.LegacyGucsSpec.spec
-- this test runs with db-plan-enabled = true
parallel $ before planEnabledApp $
describe "Feature.Query.PlanSpec.spec" $ Feature.Query.PlanSpec.spec actualPgVersion
-- this test runs with a pre request to enable the pg-safeupdate library per-session
parallel $ before pgSafeUpdateApp $
describe "Feature.Query.PgSafeUpdateSpec.spec" Feature.Query.PgSafeUpdateSpec.spec
-- this test runs with server-trace-header set
parallel $ before obsApp $
describe "Feature.ObservabilitySpec.spec" Feature.ObservabilitySpec.spec
-- Note: the rollback tests can not run in parallel, because they test persistance and
-- this results in race conditions
-- this test runs with tx-rollback-all = true and tx-allow-override = true
before withApp $
describe"Feature.RollbackAllowedSpec" Feature.RollbackSpec.allowed
-- this test runs with tx-rollback-all = false and tx-allow-override = false
before disallowRollbackApp $
describe "Feature.RollbackDisallowedSpec" Feature.RollbackSpec.disallowed
-- this test runs with tx-rollback-all = true and tx-allow-override = false
before forceRollbackApp $
describe "Feature.RollbackForcedSpec" Feature.RollbackSpec.forced
where
loadSchemaCache pool conf =
either (panic.show) id <$> P.use pool (HT.transaction HT.ReadCommitted HT.Read $ querySchemaCache conf)

@taimoorzaeem
Copy link
Collaborator

taimoorzaeem commented Sep 8, 2023

the database ("db") query time was 53 ms, and we took 15 ms to obtain the query response("render", this is relevant to #2770.

@steve-chavez What exactly is the difference between db and render. If I understand correctly, db time refers to time it took to run the query and render refers to the time it took hasql decoders to represent the query result into appropriate representation?

@steve-chavez
Copy link
Member Author

@taimoorzaeem Yes, that was the idea. To be clear maybe we can name that duration decode instead of render.

Btw, since you need this for the jwt caching feat, adding only the jwt duration to server-timing would be fine. We can add other durations later.

@steve-chavez
Copy link
Member Author

According to the following blog post, there is a nice browser integration for server timing.

https://www.smashingmagazine.com/2018/10/performance-server-timing/

A couple of things caught my attention.

Server Timing itself adds very minimal overhead to the HTTP response sent back over the wire. The header is very minimal and is generally safe to be sending without worrying about targeting to only internal users
https://www.smashingmagazine.com/2018/10/performance-server-timing/#considerations

TBD We could enable server timing without db-plan-enabled but only for authenticated users.

The only property that is required is name. Both dur and desc are optional, and can be used optionally where required. For example, if you needed to debug a timing problem that was happening on one server or data center and not another, it might be useful to add that information into the response without an associated timing.
Server-Timing: datacenter;desc="East coast data center", db;dur=123;desc="Database", tmpl;dur=56;desc="Template processing”

TBD We could have an initial description like server;desc="PostgREST'. This in case our durations conflict with another server that also exposes Server-Timing. I'm assuming this desc allows us to namespace the durations, haven't tried it.


There's also a JS integration: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceServerTiming

Also note:

The Server-Timing header may expose potentially sensitive application and infrastructure information. Consider to control which metrics are returned when and to whom on the server side. For example, you could only show metrics to authenticated users and nothing to the public.
https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing

@develop7
Copy link
Collaborator

develop7 commented Oct 2, 2023

TBD We could have an initial description like server;desc="PostgREST'. This in case our durations conflict with another server that also exposes Server-Timing. I'm assuming this desc allows us to namespace the durations, haven't tried it.

Doesn't look that way — the desc seems to be consumed by client verbatim (per W3 TR). Moreover, it seems like we could have as many equally-named timings as we please, hence it's likely our job to make them stand out.

@develop7
Copy link
Collaborator

develop7 commented Oct 2, 2023

Doing this for app, db, render in the current codebase would be repetitive:

[…skip…]

Right now, after #2971 got merged, the code looks bit better:

case (iAction, iTarget) of
(ActionRead headersOnly, TargetIdent identifier) -> do
wrPlan <- liftEither $ Plan.wrappedReadPlan identifier conf sCache apiReq
resultSet <- runQuery roleIsoLvl (Plan.wrTxMode wrPlan) $ Query.readQuery wrPlan conf apiReq
pgrst <- liftEither $ Response.readResponse wrPlan headersOnly identifier apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionMutate MutationCreate, TargetIdent identifier) -> do
mrPlan <- liftEither $ Plan.mutateReadPlan MutationCreate apiReq identifier conf sCache
resultSet <- runQuery roleIsoLvl (Plan.mrTxMode mrPlan) $ Query.createQuery mrPlan apiReq conf
pgrst <- liftEither $ Response.createResponse identifier mrPlan apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionMutate MutationUpdate, TargetIdent identifier) -> do
mrPlan <- liftEither $ Plan.mutateReadPlan MutationUpdate apiReq identifier conf sCache
resultSet <- runQuery roleIsoLvl (Plan.mrTxMode mrPlan) $ Query.updateQuery mrPlan apiReq conf
pgrst <- liftEither $ Response.updateResponse mrPlan apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionMutate MutationSingleUpsert, TargetIdent identifier) -> do
mrPlan <- liftEither $ Plan.mutateReadPlan MutationSingleUpsert apiReq identifier conf sCache
resultSet <- runQuery roleIsoLvl (Plan.mrTxMode mrPlan) $ Query.singleUpsertQuery mrPlan apiReq conf
pgrst <- liftEither $ Response.singleUpsertResponse mrPlan apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionMutate MutationDelete, TargetIdent identifier) -> do
mrPlan <- liftEither $ Plan.mutateReadPlan MutationDelete apiReq identifier conf sCache
resultSet <- runQuery roleIsoLvl (Plan.mrTxMode mrPlan) $ Query.deleteQuery mrPlan apiReq conf
pgrst <- liftEither $ Response.deleteResponse mrPlan apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionInvoke invMethod, TargetProc identifier _) -> do
cPlan <- liftEither $ Plan.callReadPlan identifier conf sCache apiReq invMethod
resultSet <- runQuery (fromMaybe roleIsoLvl $ pdIsoLvl (Plan.crProc cPlan))(Plan.crTxMode cPlan) $ Query.invokeQuery (Plan.crProc cPlan) cPlan apiReq conf pgVer
pgrst <- liftEither $ Response.invokeResponse cPlan invMethod (Plan.crProc cPlan) apiReq resultSet serverTimingParams
return $ pgrstResponse pgrst
(ActionInspect headersOnly, TargetDefaultSpec tSchema) -> do
iPlan <- liftEither $ Plan.inspectPlan conf apiReq
oaiResult <- runQuery roleIsoLvl (Plan.ipTxmode iPlan) $ Query.openApiQuery sCache pgVer conf tSchema
pgrst <- liftEither $ Response.openApiResponse (T.decodeUtf8 prettyVersion, docsVersion) headersOnly oaiResult conf sCache iSchema iNegotiatedByProfile
return $ pgrstResponse pgrst
(ActionInfo, TargetIdent identifier) -> do
pgrst <- liftEither $ Response.infoIdentResponse identifier sCache
return $ pgrstResponse pgrst
(ActionInfo, TargetProc identifier _) -> do
cPlan <- liftEither $ Plan.callReadPlan identifier conf sCache apiReq ApiRequest.InvHead
pgrst <- liftEither $ Response.infoProcResponse (Plan.crProc cPlan)
return $ pgrstResponse pgrst
(ActionInfo, TargetDefaultSpec _) -> do
pgrst <- liftEither Response.infoRootResponse
return $ pgrstResponse pgrst

Still repetitive, but, uh, more uniform. All I can think of factoring out without introducing extra indirection is return $ pgrstResponse pgrst, which isn't making it awful lot better.

On the other hand, actually delivering metrics for plan, query, render and jwt right now seems to be the matter of wrapping respective calls with timeItT, like this:

-- ...skip...
handleRequest AuthResult{..} conf appState authenticated prepared pgVer apiReq@ApiRequest{..} sCache serverTimingParams =
  case (iAction, iTarget) of
    (ActionRead headersOnly, TargetIdent identifier) -> do
      (planTime, wrPlan) <- timeItT $ liftEither $ Plan.wrappedReadPlan identifier conf sCache apiReq
      (rsTime, resultSet) <- timeItT $ runQuery roleIsoLvl (Plan.wrTxMode wrPlan) $ Query.readQuery wrPlan conf apiReq
      (renderTime, pgrst) <- timeItT $ liftEither $ Response.readResponse wrPlan headersOnly identifier apiReq resultSet serverTimingParams
     -- ...skip...

Well, there's rendering the header too, but the goal at hand is still close.

@steve-chavez
Copy link
Member Author

Still repetitive, but, uh, more uniform.

On a previous discussion we had the idea to have App do the IO and make the other modules pure, then have a single entrypoint for each module instead of having handleRequest in App.

Note: previous discussion was here and is part of this big issue.

On the other hand, actually delivering metrics for plan, query, render and jwt right now seems to be the matter of wrapping respective calls with timeItT, like this:

Yeah, so it can be done with some duplication but it'd be cleaner with the refactor. That being said, implementing without being DRY should be fine. We can refactor it later.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement a feature, ready for implementation
Development

Successfully merging a pull request may close this issue.

3 participants