-
Notifications
You must be signed in to change notification settings - Fork 2.8k
add query execution time and response size to ws-server logs in websocket transport #3584
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
Conversation
|
Deploy preview for hasura-docs ready! Built with commit 702e809 |
|
Review app for commit c77f54d deployed to Heroku: https://hge-ci-pull-3584.herokuapp.com |
|
New log json structure is. {
"type":"ws-server",
"timestamp":"2019-12-17T11:46:29.190+0700",
"level":"debug",
"detail": {
"metadata": {
"response_size":21,
"query_execution_time": 8.54369e-4
},
"event": {
...
},
"websocket_id":"4c9dffd6-aa14-4539-b935-f40dd5647b2b"
}
}
|
ecthiender
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Overall looks good. Added some minor comments regarding readability of code. Let me know if that makes sense.
|
Would be great if @lexi-lambda can also take a brief look at it (to check if it makes sense to calculate the exec time and put it in the queue). |
|
Review app for commit 3041d1d deployed to Heroku: https://hge-ci-pull-3584.herokuapp.com |
|
Review app for commit 4e32bbc deployed to Heroku: https://hge-ci-pull-3584.herokuapp.com |
ecthiender
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
lexi-lambda
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Left a few minor comments.
|
Review app for commit b94eb84 deployed to Heroku: https://hge-ci-pull-3584.herokuapp.com |
| -- ^ extra metadata that we use for other actions, such as print log | ||
| -- we don't want to inlcude them into websocket message payload |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please use Haddock comment syntax for comments like there where it makes sense. (I’ve made the change here myself, since it’s a small thing, but just so you know in the future.)
|
Review app for commit 702e809 deployed to Heroku: https://hge-ci-pull-3584.herokuapp.com |
|
Review app https://hge-ci-pull-3584.herokuapp.com is deleted |
| _ -> "for the following reasons:\n" <> T.unlines | ||
| (map ((" • " <>) . showError) errors) | ||
|
|
||
| withElapsedTime :: MonadIO m => m a -> m (NominalDiffTime, a) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
FWIW I wrote a similar utility function in https://github.com/hasura/graphql-engine/pull/3622/files#diff-b4adc70671eae2d8ba4ad21bd16ede86R104 I considered NominalDiffTime but ultimately went a different route since having a duration type tagged with a unit is less error-prone when using literals and when serializing. But there are tradeoffs for both approaches...
I also use the monotonic clock, which is a more strictly correct way to get timing, but again this probably doesn't matter (unless some other part of the code blows up or loops on unexpected negative duration etc...)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@lexi-lambda @hgiasac actually I think I need an opinion here. I'm rebasing my PR again on this and now there's a block of code we time twice ) in two different ways which doesn't make much sense.
I'm okay refactoring to use NominalDiffTime (or maybe even better, a newtype called Seconds) as a standard duration type
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@jberryman I wrote a library for doing type-safe unit conversion stuff in Data.Time.Clock.Units. It’s all based on DiffTime, though, not NominalDiffTime, since as you mention it’s the Right Thing here.
That said, I’ve never actually been 100% clear on how you’re supposed to actually get a DiffTime with the usual Data.Time.Clock API. As far as I can tell, it doesn’t expose a monotonic clock. There’s Data.Time.Clock.TAI, but there’s no guaranteed way to access a clock that produces an AbsoluteTime.
My preference would be to wrap GHC.Clock so that it produces a DiffTime and use that, along with the Data.Time.Clock.Units module mentioned above. Does that seem reasonable to you?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh cool, I looked but totally missed that module. It looks good!
Types help a lot but time is crazy; my understanding, which is probably not entirely correct:
AbsoluteTimewas defined to be an epoch time, to support the possibility of a correct difference operation (DiffTime); no ecosystem really developed out of these (or maybe there are some good libraries out there! I've only usedtimezone-olsenwhich uses completely separate types IIRC)NominalDiffTime(nominal in the sense of "it doesn't really work"?) was defined separately with much self-loathing to support the useful but formally nonsensical diffing ofUTCTime(which as they note is only correct (or legally binding?) if theUTCTimes are earlier than a horizon of 6 months from when you perform the calculation...)- I think there fundamentally is not a way to get
AbsoluteTimeas they define it from your machine without a table of leap seconds;POSIXTimeis what we usually think of when we think of an epoch time but is, I think, approximate wrt leap seconds (...very unclear about this) - the monotonic clock is orthogonal to all of this; it's just an API that gives you a ticking counter that only increases (the regular system clock can jump forward or backwards). afaiu a reading of the monotonic clock has no meaning; it's only good for measuring durations.
Sooooo ... (what were we talking about?)
My preference would be to wrap GHC.Clock so that it produces a DiffTime and use that, along with the Data.Time.Clock.Units module mentioned above. Does that seem reasonable to you?
I think either DiffTime or NominalDiffTime are equally valid to use as a duration type in that module, but NominalDiffTime is the one you can actually use in calculations with time moments (for better or worse). So we might want to consider using NominalDiffTime in your module, but I have no real opinion there and yes that sounds good!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@lexi-lambda also re. an algebra for time etc., I couldn't remember the name of this structure and had to email a colleague: https://ro-che.info/articles/2013-01-08-torsors
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh I see you can get an AbsoluteTime with http://hackage.haskell.org/package/time-1.9.3/docs/Data-Time-Clock-System.html#v:systemToTAITime , but now I'm a more lost...
See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
…3552 We upload a set of accumulating timers and counters to track service time for different types of operations, across several dimensions (e.g. did we hit the plan cache, was a remote involved, etc.) Also... Standardize on DiffTime as a standard duration type, and try to use it consistently. See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
…3552 We upload a set of accumulating timers and counters to track service time for different types of operations, across several dimensions (e.g. did we hit the plan cache, was a remote involved, etc.) Also... Standardize on DiffTime as a standard duration type, and try to use it consistently. See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
…3552 We upload a set of accumulating timers and counters to track service time for different types of operations, across several dimensions (e.g. did we hit the plan cache, was a remote involved, etc.) Also... Standardize on DiffTime as a standard duration type, and try to use it consistently. See discussion here: hasura#3584 (review) It should be possible to overwrite that module so the new threadDelay sticks per the pattern in hasura#3705 blocked on hasura#3558 Rename the Control.Concurrent.Extended.threadDelay to `sleep` since a naive use with a literal argument would be very bad! We catch a bug in 'computeTimeDiff'. Add convenient 'Read' instances to the time unit utility types. Make 'Second' a newtype to support this.
…cket transport (hasura#3584) - cherry-picked the above commit (2aba7ed) from master into ratelimit-changes-v1stable
Description
Affected components
Related Issues
Solution and Design
Add more two fields
query_execution_timeandresponse_sizeintows-serverevent detail.They are computed on
message_sentdata event only.{ "type":"ws-server", "timestamp":"2019-12-17T11:46:29.190+0700", "level":"debug", "detail": { "metadata": { "response_size":21, "query_execution_time": 8.54369e-4 }, "event": { "type":"message_sent", "detail": "{ "type":"data", "id":"1", "payload": { ... } } }" }, "websocket_id":"4c9dffd6-aa14-4539-b935-f40dd5647b2b" } }Live query
TQueuecontent are changed fromBL.ByteStringtoWSQueueResponseADT:Add
LiveQueryMetadataADT as additional parameter in live queryOnChangecallback:Server checklist
Catalog upgrade
Does this PR change Hasura Catalog version?
Metadata
Does this PR add a new Metadata feature?
run_sqlauto manages the new metadata through schema diffing?run_sqlauto manages the definitions of metadata on renaming?export_metadata/replace_metadatasupports the new metadata added?GraphQL
Breaking changes
No Breaking changes
There are breaking changes:
Metadata API
Existing
querytypes:argspayload which is not backward compatibleJSONschemaGraphQL API
Schema Generation:
NamedTypeSchema Resolve:-
nullvalue for any input fieldsLogging
JSONschema has changedtypenames have changedAdd more two fields
query_execution_timeandresponse_sizeintows-serverevent detail. However, normal user won't see any difference because those logs are only sent ondebuglevelSteps to test and verify
Run graphql engine with
--log-level=debugRequest a subcription query
View stdout logs
Limitations, known bugs & workarounds