Record how long a client-terminated request had been in flight - #3287
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## master #3287 +/- ##
=============================================
- Coverage 64.24% 38.13% -26.11%
+ Complexity 10398 6487 -3911
=============================================
Files 840 938 +98
Lines 71755 80572 +8817
Branches 8611 9700 +1089
=============================================
- Hits 46099 30730 -15369
- Misses 23004 47371 +24367
+ Partials 2652 2471 -181 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
2bd059b to
37b931c
Compare
When a client aborts an in-flight request, NettyMessageProcessor logs that the channel became inactive but not how long the request had been running, so a client giving up at a fixed deadline is indistinguishable from one that died early. clientEarlyTerminationCount already counts these aborts, and their duration reaches nioRoundTripTimeInMs, but that histogram is bucketed per request type and mixes aborts with successes, so it cannot show the abort-only distribution. Add a ClientTerminatedRequestTimeInMs histogram, fed from the two client termination paths: channelInactive() and the idle timeout in userEventTriggered(). Which of the two finds the request still open depends on the transport -- a real event loop defers fireChannelInactive to a later task, by which point the request has been closed, whereas EmbeddedChannel runs it inline -- so recording goes through a one shot helper, reset in resetState() alongside the request it belongs to. That keeps the count at one per request on either transport instead of encoding the transport's behaviour. Instrumenting only channelInactive() missed every idle timeout abort in production, which is the longest lived group and the tail this metric exists to show. Read the elapsed time through a new RestRequestMetricsTracker accessor. No new timestamp is introduced: NettyRequest's constructor already marks the request received, and the value simply had no reader. The accessor returns 0 rather than throwing when the request was never marked, unlike its siblings, because its caller is a diagnostic on an error path. Both abort log lines gain the elapsed time. On channelInactive() it is appended, so prefix based log matching keeps working; the idle path previously logged no per-request line at all. testIdleChannelAbortOnRealEventLoopRecordsTimeInFlight drives a LocalChannel on a real event loop, because the EmbeddedChannel tests structurally cannot fail on this defect. The server side and protocol abort paths were verified not to feed the histogram on real TCP sockets, so the metric measures what its name says. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
37b931c to
98aa744
Compare
Do we actually need the logging, given the metric?The new Splitting the two log paths:
Dedup covers the metric, not the logs. The metric makes the per-request forensic value marginal, and where per-request detail does matter we usually already have it upstream. For example, on the PUT blob path an HTTP connection timeout already logs the blob name — so request identity for the interesting case isn't lost if this line goes away. I'd suggest one of these two, rather than shipping a separate
Either keeps the signal without adding a routine-path |
…te log line Review feedback on the idle path: the change was emitting a second, error level line for an event the handler already logs at info, so a single idle disconnect could produce two lines describing it. Fold the request URI and time in flight into the existing info line instead, and delete the added error line. The channelInactive error line is unchanged. Recording idle terminations into ClientTerminatedRequestTimeInMs was also wrong, for a reason the log nit exposed. netty.server.idle.time.seconds is a fixed config value, so every idle termination lands at approximately the same elapsed time. Mixed into the client abort distribution they form a sharp spike at a deadline our own timeout config chose, which is indistinguishable from the real finding the histogram exists to surface. They now record into a separate IdleTerminatedRequestTimeInMs. One flag still guards both call sites, so a request is recorded exactly once, into whichever histogram observed the termination first, and can never appear in both. The tests assert that mutual exclusion in both directions. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
…m split rationale testIdleChannelAbortOnRealEventLoopRecordsTimeInFlight opened its timing window after awaiting serverChannelInitialized, which counts down in initChannel, i.e. at channel registration rather than at request receipt. LocalChannel.doWrite completes the client's write promise in in.remove() before finishPeerRead delivers the read, so the server had not yet constructed the NettyRequest or called markRequestReceived() when the window opened. Instrumenting the latch showed the request was still unreceived at that point in 12 of 12 runs, so the test was only passing because the server usually caught up inside the 2 ms budget; when it did not, the recorded time came out as 1 ms and the lower-bound assertion failed. The repo sets failOnPassedAfterRetry = false, so those failures were retried away and did not fail the build. A RequestReceivedProbe handler now sits immediately before the processor and counts down after fireChannelRead returns, which is after the processor has constructed the request and marked it received, so the window can no longer open early. 30 consecutive whole-class runs are clean. Also corrects the stated reason for keeping the two histograms apart. The claim that every idle termination lands at approximately the configured timeout is wrong: IdleStateHandler's ALL_IDLE fires relative to the last read or write, not to request arrival, so a request that streams for ten minutes and then stalls records ten minutes plus the timeout. The accurate property is that request arrival is itself a read, so an idle abort cannot be observed sooner than the timeout - the population has a hard floor there and no upper bound. Pooling the two would inject a server-chosen floor into a distribution whose signal is at the low end. The recordTermination javadoc now leads with its contract and states that the guard prevents a double count rather than assigning the bucket. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
|
Thanks @beijxu — proceeding with option 2: the idle details are folded into the existing |
|
|
5 participants
Motivation
Record how long a request had been in flight when a client disconnect or server idle timeout closes it.
What changed
getTimeSinceRequestReceivedInMs()using the request timestamp already recorded byNettyRequest.ClientTerminatedRequestTimeInMsandIdleTerminatedRequestTimeInMshistograms, recorded at most once per request.Known gap
A disconnect first observed through a failed response write is not recorded because the request closes before
channelInactive()runs. This affects disconnects during response writes and remains follow-up work, soClientTerminatedRequestTimeInMsis a lower bound rather than a count.Risk Assessment
Metrics and logging only. No storage, request-completion, callback, or resource-lifecycle behavior changes. Idle-path log volume remains unchanged.
Testing Done
./gradlew :ambry-rest:test— 97 passed./gradlew :ambry-api:test— 233 passed, 6 skippedNettyMessageProcessorTestclass runs passed after fixing test synchronization