Log handler execution duration on the "Finished processing" message (closes #3063)#3067
Merged
Merged
Conversation
…H-3063) When browsing production logs it is hard to tell how long an individual handler took. The execution-finished log now includes the handler's execution time in milliseconds, both in the rendered message ("...executed in {Duration} ms") and as a structured "Duration" property so slow handlers can be found with structured log filters over a time window. The duration comes from Envelope.ExecutionTime, which is populated by Envelope.StopTiming() inside IMessageTracker.ExecutionFinished. Both Executor and TracingExecutor log _executionFinished after that tracker call (in the finally / post-tracking paths), so the timing is always available at the log site. Applied to every _executionFinished call site, including TracingExecutor's inline-invoke and streaming paths. Adds execution_finished_logs_duration_3063, which routes a (deliberately slow) message through the worker so it exercises Executor.ExecuteAsync, then asserts the rendered message carries "executed in ... ms" and that the structured "Duration" property is present and greater than zero. Closes #3063 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This was referenced Jun 10, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #3063. Adds the handler's execution time to the execution-finished log so it's possible to pinpoint slow handlers in production logs (and filter for them in structured logging).
Change
The
_executionFinishedlog message now reads:{Duration}is also a structured property (Duration), so you can filter for all handlers over some threshold across a time window — which was the actual ask in the issue (metrics are too coarse-grained; per-operation log math can't separate transport time from handler time).The value comes from
Envelope.ExecutionTime, which is set byEnvelope.StopTiming()insideIMessageTracker.ExecutionFinished(...). Both executors log_executionFinishedafter that tracker call (in thefinally/ post-tracking paths), so the timing is always populated at the log site.Applied to:
Executor.ExecuteAsync— the transport-received path_executionFinishedcall site inTracingExecutor(theInvokeTracing.Fullpath), including the inline-invoke and streaming branches, so the message is consistent wherever "Finished processing" is emittedTest
execution_finished_logs_duration_3063routes a deliberately-slow message (Task.Delay(25)) through the worker viaSendMessageAndWaitAsyncso it exercisesExecutor.ExecuteAsync(not the inline-invoke path), then asserts both that the rendered message containsexecuted in … msand that the structuredDurationproperty is present and> 0.All 6 related CoreTests pass (the new test + the 5 existing
invoke_tracing_modetests).wolverine.slnx -c Releasebuilds clean (0 warnings, 0 errors).Note on log level
_executionFinishedis emitted atHandlerChain.ProcessingLogLevel, which defaults toDebug— so the duration rides the existing "Finished processing" line rather than the Information-level "Successfully processed" line the issue author mentioned. This keeps the change to a single, already-existing log statement; if we'd rather surface the duration at Information level, that's a follow-up decision.🤖 Generated with Claude Code