Trace invalidation from start to finish #710
Conversation
|
View Vercel preview at instant-www-js-e2e-tracer-jsv.vercel.app. |
| (when (instance? Throwable ret) | ||
| (throw ret))))) | ||
| p (promise)] | ||
| (tracer/with-span! {:name "ws/send-json!" |
There was a problem hiding this comment.
Tracing the full time it takes to send the json to the client. Looking at honeycomb, the send lock is almost never locked when we get here.
There was a problem hiding this comment.
Ah, perhaps it's because with grouped-queue, many of our messages are serialized per session. I wonder if we get something like set-presence and transact at the same time, if the lock will start to come in effect
There was a problem hiding this comment.
I think the reason we rarely wait on the lock is that calling Websockets/sendText is very quick--undertow is probably just putting a message onto a queue. All of the waiting happens between when we call sendText and when the complete callback is called.
Right now we don't have a great way of seeing the full lifecycle of a transaction, from when the user calls
db.transactto the point where the clients subscribed to that query re-render with new data. Our best metric right now is manually visiting the examples page and checking/unchecking tasks.This PR introduces end-to-end tracing that will allow us to track from when
transact!finishes to when we finish delivering the final websocket :refresh message for the transaction. It's not quite the full latency that the user sees, but it's close.We use the transaction id to tie all of the spans to a single trace. It's one thing that we can track across multiple machines and know it will be the same on all machines. We generate our own parent trace-id and span-id from the tx-id and then create parent spans with that trace-id. That allows us to have spans from different machines all share the same parent.
It produces a trace diagram that looks like this:
All of the spans are just single points because the parent spans have no way of knowing when the child spans complete.
We only log one out of every 10,000 transactions (configurable via instant-config) and we add an extra
:entropyattr that will encourage refinery to forward our spans.