Skip to content

Perf: avoid repeated orchestration-history scans for tracing - #788

Open
Bernd Verst (berndverst) wants to merge 10 commits into
mainfrom
berndverst-fix-trace-history-scan-perf
Open

Bernd Verst (berndverst) wants to merge 10 commits into
mainfrom
berndverst-fix-trace-history-scan-perf

Conversation

@berndverst

@berndverst Bernd Verst (berndverst) commented Jul 24, 2026 •

Copy link
Copy Markdown
Member

Summary

What changed?

  • Gate tracing-only execution-start lookup and completion-event correlation behind TraceHelper.HasListeners.
  • Replace per-completion linear history scans with TraceHistoryEventLookup: register only scheduling IDs referenced by this work item's new completion/failure events, then resolve both scheduling-event types in one lazy scan. Expected correlation work is O(past events + new events), with O(requested IDs) temporary storage.
  • Preserve the reviewer-directed one-to-one scheduling-ID invariant: looking up duplicate IDs for the same scheduling-event type throws a diagnostic exception and abandons the invalid work item.
  • Merge main at 936325b2 and resolve processor conflicts against its rewind/streamed-history implementation. Use the actual materialized past history for both start-event discovery and correlation; keep required rewind validation even without listeners and retain the fresh rewind trace context.
  • Fix a reproduced failure-path bug: if correlation throws after an orchestration Activity starts, dispose it before rethrowing to the existing abandonment/logging path.
  • Extend streamed-history coverage across two chunks and both scheduling-event types; strengthen real-sidecar integration coverage to assert the exact scheduled/executed parent-span relationships and distinct scheduled spans, not just span names.

Why is this change needed?

  • For fan-in batches on large histories, the prior tracing correlation scans grew as O(new completion events × past events), including when tracing was disabled.
  • Value assessment: highest priority of the three performance PRs. It removes avoidable work from ordinary no-listener execution and addresses an algorithmic scaling issue when tracing is enabled. The index is work-item-local and bounded by requested IDs, not all historical scheduling events.
  • No numeric throughput claim is made: the asymptotic improvement and one-pass enumeration are supported by code/tests; production workload speedups still need measurement.

Issues / work items


Project checklist

  • Release notes are not required for the next release
    • Otherwise: Notes added to release_notes.md
  • Backport is not required
    • Otherwise: Backport tracked by issue/PR #issue_or_pr
  • All required tests have been added/updated (unit tests, E2E tests)
  • Breaking change?
    • If yes:
      • Impact: Intentional behavioral change for malformed duplicate scheduling-ID history, explicitly requested in Sophia's existing review. Listener-enabled processing abandons an ambiguous work item rather than selecting the old first/last match. Valid history, public signatures, wire fields, and replay output remain unchanged.
      • Migration guidance: No change for valid orchestrations. Diagnose/repair invalid duplicate scheduling history rather than relying on ambiguous first/last-match behavior.

AI-assisted code disclosure (required)

Was an AI tool used? (select one)

  • No
  • Yes, AI helped write parts of this PR (e.g., GitHub Copilot)
  • Yes, an AI agent generated most of this PR

If AI was used:

  • Tool(s): GitHub Copilot; this refresh used GPT-6.1 Sol.
  • AI-assisted areas/files: Shared tracing helpers/index, worker processor, lookup/processor unit tests, and tracing integration tests.
  • What you changed after AI output: Preserved prior human-review decisions rather than restoring obsolete duplicate-ID first/last-wins semantics; integrated main's rewind/streamed-history paths; added stronger correlation assertions; reproduced and fixed the unclosed Activity on abandonment.

AI verification (required if AI was used):

  • I understand the code and can explain it
  • I verified referenced APIs/types exist and are correct
  • I reviewed edge cases/failure paths (timeouts, retries, cancellation, exceptions)
  • I reviewed concurrency/async behavior
  • I checked for unintended breaking or behavior changes

Testing

Automated tests

  • Result: Passed locally on the refreshed branch (Windows, .NET SDK 10.0.403).
  • dotnet restore Microsoft.DurableTask.sln --configfile nuget.config --verbosity quiet — passed when refreshing shared solution assets after merging main.
  • dotnet test test\Worker\Grpc.Tests\Worker.Grpc.Tests.csproj --configuration Release --no-restore --filter "FullyQualifiedName~WithActivityListener_DuplicateEventIds" --verbosity minimal -p:WarningLevel=0 — failed before the cleanup fix with a timeout waiting for ActivityStopped, reproducing the defect.
  • dotnet test test\Worker\Grpc.Tests\Worker.Grpc.Tests.csproj --configuration Release --no-restore --verbosity quiet -p:WarningLevel=0 — passed after the fix, 218/218, including the abandonment regression, streamed-history correlation, no-listener behavior, and rewind tests.
  • dotnet test test\Grpc.IntegrationTests\Grpc.IntegrationTests.csproj --configuration Release --no-restore --filter "FullyQualifiedName~TracingIntegrationTests|FullyQualifiedName~OrchestrationPatterns" --verbosity quiet -p:WarningLevel=0 — passed, 55/55, including all 8 tracing tests.
  • dotnet build src\Worker\Grpc\Worker.Grpc.csproj --configuration Release --no-restore --verbosity quiet -p:WarningLevel=0 — passed across all configured target frameworks.
  • Full solution test execution, live DTS rewind integration, and end-to-end performance benchmarks were not run locally. Current GitHub checks are authoritative for CI.

Manual validation (only if runtime/behavior changed)

  • Environment (OS, .NET version, components): Windows; .NET SDK 10.0.403/runtime 10.0.14; mocked history stream/completion transport and real in-process sidecar.
  • Steps + observed results:
    1. Reproduced abandoned duplicate-ID work leaving its Activity unclosed; the new regression failed before the fix and passed in the final suite.
    2. Correlated activity and sub-orchestration completions using scheduling events from streamed history; passed and the stream was fetched exactly once.
    3. Asserted that each real activity/sub-orchestration server span belongs to its corresponding distinct scheduled client span; passed. No separate live-service/manual workload was run.
  • Evidence (optional): Exact local commands/results above; refreshed merge/fix commit 81d05c10.

Notes for reviewers

  • Recommended first priority: largest and broadest benefit, with bounded per-work-item memory and no shared index synchronization.
  • The no-listener optimization skips tracing-specific scans, not history retrieval/reconstruction needed for execution or rewind validation.
  • HasListeners is not a sampling-decision check: a registered listener that ultimately samples nothing can still cause indexing work. No sampling-level fast path is claimed.
  • Do not reapply obsolete comments requesting duplicate-ID first/last-wins behavior: Sophia explicitly requested fail-fast one-to-one mapping, and the author's replies documented that decision.

Breaking Change

Type: behavioral (invalid duplicate scheduling-ID histories only)
Impact: With tracing listeners enabled, ambiguous scheduling correlation now abandons the work item with a diagnostic exception instead of choosing a first/last matching event. This was explicitly requested in the existing human review. No binary, source, wire, serialization, or valid-history replay change.
Migration: Valid histories require no action or orchestration version change. Invalid duplicate scheduling histories require diagnosis/repair; callers must not rely on ambiguous trace correlation.

OnRunOrchestratorAsync previously scanned orchestration history to
correlate tracing events unconditionally, and for every qualifying
new event it rescanned the full past-events list to find the
originating TaskScheduled/SubOrchestrationInstanceCreated event -
O(new events x past events) work, even when no tracing listener was
registered.

- Add TraceHelper.HasListeners, a cheap check backed by
  ActivitySource.HasListeners(), and gate all tracing-correlation
  work in OnRunOrchestratorAsync behind it so nothing is scanned when
  no listener is registered.
- Replace the LINQ Concat-based scan for the ExecutionStarted event
  with a single-pass local function.
- Add TraceHistoryEventLookup, which builds one dictionary index per
  work item (built lazily, once) for O(1) repeated lookups instead of
  rescanning PastEvents per new event, while preserving the exact
  original first-wins (SubOrchestrationInstanceCreated) and last-wins
  (TaskScheduled) semantics for duplicate event IDs.

No public API changes; trace output, error handling, and replay
determinism are unaffected.

Adds regression tests for the no-listener fast path, first/last-wins
correlation semantics end-to-end, and direct unit tests for
TraceHistoryEventLookup.

Fixes #769

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot-Session: 9c538f3e-308d-48a3-af7f-b3baf90e97b2
Copilot AI lite review requested due to automatic review settings July 24, 2026 22:16

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Improves the gRPC worker’s tracing correlation performance by avoiding unnecessary orchestration-history scans when tracing is disabled and by indexing past history events for O(1) correlation lookups when tracing is enabled. This aligns with the SDK’s goal of keeping worker-side orchestration processing efficient, especially for long-running instances with large histories.

Changes:

  • Added a cheap listener check (TraceHelper.HasListeners) and gated trace-correlation work in OnRunOrchestratorAsync behind it.
  • Replaced repeated past-history scans with a per-work-item indexed lookup (TraceHistoryEventLookup) that preserves prior first/last-wins semantics for duplicate event IDs.
  • Added unit and worker-level tests covering listener/no-listener behavior and duplicate-ID correlation semantics.

Reviewed changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated no comments.

Show a summary per file
File Description
test/Worker/Grpc.Tests/TraceHistoryEventLookupTests.cs Adds focused unit tests for the new indexed lookup, including duplicate-ID first/last-wins semantics and filtering by event type.
test/Worker/Grpc.Tests/GrpcDurableTaskWorkerTests.cs Adds end-to-end worker tests for the no-listener fast path and for correlation semantics under a real ActivityListener.
src/Worker/Grpc/GrpcDurableTaskWorker.Processor.cs Gates tracing correlation behind HasListeners, replaces LINQ concat scan with a single-pass helper, and uses the indexed lookup for repeated correlation.
src/Shared/Grpc/Tracing/TraceHistoryEventLookup.cs Introduces a lazily-built, cached dictionary index for past events to avoid O(N×M) repeated scans.
src/Shared/Grpc/Tracing/TraceHelper.cs Exposes HasListeners backed by ActivitySource.HasListeners() to allow callers to skip trace-correlation work when tracing is disabled.

Copilot AI review requested due to automatic review settings July 27, 2026 18:37

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 5 out of 5 changed files in this pull request and generated no new comments.

@berndverst

Copy link
Copy Markdown
Member Author

Quantitative performance impact

I compared live head d223fc2 with its merge base in a focused Release/.NET 10 harness on Windows x64 (AMD EPYC 7763). It used the actual TraceHistoryEventLookup/TraceHelper.HasListeners code and the exact old lookup algorithm. Activity creation, the rest of worker execution, and gRPC were excluded, so these are correlation-stage measurements rather than fleet-wide orchestration averages.

Let H be past-event count and N_t/N_s qualifying task/sub-orchestration completion counts.

Path Old past-event inspections New work
No tracing listener execution-start search + up to N_t*H + sum(sub match positions) one HasListeners() check; zero history enumeration
Listener, task completions N_t*H one H-event task index + N_t dictionary lookups
Listener, sub-orchestration completions sum(sub match positions) one H-event sub index + N_s dictionary lookups

Representative, best, and adverse cases

“Representative” below means a selected ordinary shape, not production telemetry.

Case Listener / shape Correlation latency, old -> new Allocation/work item Interpretation
Average-style representative Off; H=100, 5 task completions 4.40 us -> ~6 ns 1,056 -> 0 B The history work is eliminated; the new value is near harness overhead, so the ratio is not meaningful
Listener-on ordinary task case H=100, 5 task completions 4.38 -> 2.00 us (-54.3%) 1,056 -> 4,704 B (+3,648 B) Faster CPU path, higher temporary allocation
Listener-on ordinary mixed case H=100, 3 task + 3 early sub matches 2.55 -> 3.43 us (~+34.5%) 1,024 -> 4,280 B (+3,256 B) Small/early-match histories can regress
Best measured large replay Off; H=10,000, 1,000 task completions 79.8 ms -> near harness overhead 160,256 -> 0 B Removes the entire quadratic correlation scan
Listener-on large fan-out H=10,000, 1,000 task completions 80.46 ms -> 333.5 us (-99.585%, ~241x) 160,256 -> 451,592 B (+291,336 B) Large CPU/latency gain traded for a temporary index
Listener-on mixed fan-out H=10,000, 500 task + 500 sub completions 36.98 ms -> 490.7 us (-98.673%, ~75x) 128,256 -> 431,438 B (+303,182 B) Same tradeoff with two lazy indexes
Constructed adverse case Listener on; one sub match at position 2 of H=10,000 166 ns -> 95.7 us (~576x as long) 352 -> 296 B Old FirstOrDefault stops at event 2; new code builds the full lazy index

The no-listener ~6 ns figures are close to benchmark-harness cost and should be read as “the scan was removed,” not as a credible millions-of-operations throughput claim.

Memory and GC

The lazy indexes reference existing events; they do not copy protobuf messages. On this x64 runtime, estimated incremental dictionary storage while live is approximately 28-56 B per unique indexed ID, including capacity slack/array headers but excluding the existing event objects.

  • 50 task entries: about 2.7 KiB retained, 4.7 KiB cumulatively allocated
  • 5,000 task entries: about 236 KiB retained, 452 KiB allocated
  • Two 3,333-entry indexes: about 227 KiB retained, 431 KiB allocated

Thus:

  • No listener: both scan CPU and correlation allocations fall to zero.
  • Listener + repeated lookups: CPU falls from O(N*H) to O(H+N), but temporary memory becomes O(unique history IDs).
  • Listener + one early sub lookup: CPU can regress from O(1) expected early exit to O(H) index construction.
  • A listener that samples every activity out still makes HasListeners() true and pays indexing costs.

Whole-worker throughput interpretation

Correlation-stage speedup does not translate directly to orchestration throughput. Using Amdahl's law:

  • If the old correlation work is 10% of turn CPU and the new path removes it, modeled turn throughput improves by about 11.1%.
  • If a large fan-out replay spends 50% of turn CPU in old correlation scans and that work becomes negligible, the modeled ceiling is about 2x turn throughput.

Those are sensitivity examples. Actual gains require telemetry for listener prevalence and the distributions of H, qualifying new events, event mix, and match positions.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot-Session: 01dc5b7c-c742-45b7-ae8c-5cda9bcfbd2c
Copilot AI review requested due to automatic review settings August 4, 2026 19:50

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 5 out of 5 changed files in this pull request and generated no new comments.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Copilot-Session: 01dc5b7c-c742-45b7-ae8c-5cda9bcfbd2c
Copilot AI review requested due to automatic review settings August 13, 2026 01:58

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated 1 comment.

Suppressed comments (3)

test/Worker/Grpc.Tests/TraceHistoryEventLookupTests.cs:47

  • This test currently asserts that duplicate SubOrchestrationInstanceCreated event IDs throw, but the prior linear scan behavior (and the PR description) expects first-wins semantics for duplicate IDs to preserve correlation behavior.
        act.Should().Throw<InvalidOperationException>()
            .WithMessage("*'SubOrchestrationInstanceCreated'*event ID '2'*");
    }

test/Worker/Grpc.Tests/TraceHistoryEventLookupTests.cs:28

  • These tests currently assert that duplicate event IDs throw. Per the original implementation (TaskScheduled = last-wins, SubOrchestrationInstanceCreated = first-wins) and the PR description, duplicates should be tolerated with defined first/last-wins behavior rather than causing failures during tracing correlation.

This issue also appears on line 45 of the same file.

        act.Should().Throw<InvalidOperationException>()
            .WithMessage("*'TaskScheduled'*event ID '1'*");
    }

test/Worker/Grpc.Tests/GrpcDurableTaskWorkerTests.cs:377

  • These two tests rely on TraceHistoryEventLookup throwing on duplicate event IDs (and assert the work item is abandoned when a listener is registered). That behavior conflicts with the stated goal of preserving the original duplicate-ID correlation semantics (TaskScheduled last-wins, SubOrchestrationInstanceCreated first-wins). If duplicate IDs are expected to be tolerated, these tests should be reworked to validate the no-listener fast path without depending on duplicate-ID exceptions, and the listener-enabled path should validate the preserved first/last-wins correlation rather than abandonment.
        // Arrange: duplicate event IDs cause TraceHistoryEventLookup to throw when it builds an index. If this
        // invalid history still completes, the no-listener fast path did not invoke either lookup method.
        TraceHelper.HasListeners.Should().BeFalse();

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Copilot-Session: 01dc5b7c-c742-45b7-ae8c-5cda9bcfbd2c
Copilot AI review requested due to automatic review settings August 13, 2026 02:24

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated no new comments.

Suppressed comments (1)

test/Grpc.IntegrationTests/TracingIntegrationTests.cs:97

  • This new test is named/positioned as validating span correlation, but the assertions only check that client Activities with specific OperationName values exist. That doesn’t actually validate the correlation behavior the PR is changing (i.e., that the server activity/sub-orchestration spans are parented to the correct client scheduled spans, and that the two scheduled operations remain distinct). Strengthen the assertions to check ParentSpanId relationships (similar to the other tests in this file) so the test fails if the history lookup mis-correlates events.
        // Assert
        metadata.RuntimeStatus.Should().Be(OrchestrationRuntimeStatus.Completed);
        activities.Should().ContainSingle(
            activity => activity.Kind == ActivityKind.Client
                && activity.Source.Name == CoreActivitySourceName

Bernd Verst added 2 commits August 12, 2026 19:33
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Copilot-Session: 01dc5b7c-c742-45b7-ae8c-5cda9bcfbd2c
Copilot AI review requested due to automatic review settings August 13, 2026 03:05
@berndverst

Copy link
Copy Markdown
Member Author

Updated quantitative impact after demand-shaped indexing

This supersedes the listener-on index measurements in my earlier comment. Head 3830a05 now pre-registers only correlation IDs referenced by the current work item's NewEvents, scans PastEvents once for both scheduling-event types, and retains only those requested IDs.

I measured the old repeated-scan algorithm, the prior full-history index, and the current demand-shaped index in a focused Release/.NET 10 harness on Windows x64 (AMD EPYC 7763), using real protobuf HistoryEvent objects. These numbers isolate correlation work; they are not whole-worker throughput measurements.

Scenario Shape Old repeated scan Prior full index Current demand-shaped index Current vs old
Average-style task case H=100, 50 scheduled tasks, 5 completions 3.160 us / 832 B 1.377 us / 4,736 B 0.793 us / 616 B -74.9% latency, -26.0% allocation, ~4.0x correlation throughput
Average-style mixed case H=100, 33 task + 33 sub events, 3 lookups each 2.516 us / 1,024 B 1.845 us / 4,344 B 0.888 us / 648 B -64.7% latency, -36.7% allocation, ~2.8x throughput
Best listener-on fan-in H=10,000, 5,000 scheduled tasks, 1,000 completions 54.33 ms / 160,034 B 147.1 us / 451,641 B 80.1 us / 102,368 B -99.853% latency, -36.0% allocation, ~678x throughput
Large mixed fan-in H=10,000, 3,333 task + 3,333 sub events, 500 lookups each 35.57 ms / 160,066 B 210.4 us / 431,611 B 91.1 us / 96,408 B -99.744% latency, -39.8% allocation, ~390x throughput
Constructed worst case listener on; one sub match at position 2 of H=10,000 89.8 ns / 184 B 35.67 us / 320 B 39.00 us / 352 B ~434x latency, +168 B

Compared with the prior full index, the current large task case reduces index latency another 45.5% and allocation 77.3%; the large mixed case reduces latency 56.7% and allocation 77.7%. Storage is now O(unique correlation IDs in NewEvents) rather than O(all scheduling IDs in PastEvents).

The no-listener path is unchanged from the earlier measurement: it performs one HasListeners() check and zero tracing-history enumeration or correlation allocation. The earlier representative no-listener case (H=100, 5 task completions) fell from 4.40 us and 1,056 B to approximately harness overhead and 0 B; the large no-listener replay (H=10,000, 1,000 completions) removes roughly 79.8 ms of correlation work.

The constructed single-early-sub case remains the adverse boundary. The old FirstOrDefault could return at position 2, while the reviewer-requested one-to-one invariant requires scanning the applicable history to detect a later duplicate and fail rather than silently selecting one. That O(H) validation cost cannot retain the old early-exit complexity while also guaranteeing duplicate detection. The current design removes the avoidable all-history storage and keeps that cost confined to listener-enabled tracing.

Reciprocal latency is used only as a correlation-stage throughput proxy. Whole-worker gains depend on the fraction of turn CPU previously spent in tracing correlation, listener prevalence, history sizes, and completion-batch distributions.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated no new comments.

Copilot AI review requested due to automatic review settings August 13, 2026 03:09

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated no new comments.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Copilot-Session: 01dc5b7c-c742-45b7-ae8c-5cda9bcfbd2c
Copilot AI review requested due to automatic review settings August 13, 2026 03:18

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 6 out of 6 changed files in this pull request and generated no new comments.

Preserve rewind and streamed-history behavior, verify parent-span correlation, and close abandoned work-item traces on lookup failure.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟢 Approval recommended

No active review issues are identified in the supplied evidence.

No open issues 🎉

Review effort: Lite

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Performance: avoid repeated orchestration-history scans for tracing

3 participants