Proper event tracing for ICSharpCode.Decompiler and ICSharpCode.ILSpyX#3904
Conversation
…ting The events introduced in #2519 timed only the five per-entity DoDecompile overloads, allocated a Stopwatch and the member's FullName even when no trace session was attached, and reported whole milliseconds, which rounds almost every member to zero. Flat one-shot events also gave PerfView and dotnet-trace no way to show durations or nesting, and the actually expensive stages (type system initialization, assembly resolution probing, the IL/AST transform pipelines, whole-project decompilation) were not instrumented at all. Start/Stop event pairs let trace viewers derive duration and nesting from event timestamps, keywords let a session enable only the areas of interest, and every call site is gated on IsEnabled() so tracing costs a branch when disabled. Per-transform events are Verbose because of their volume; unlike the STEP/Stepper mechanism they work in Release builds. EventSource is in-box for netstandard2.0 and flows over both ETW and EventPipe, so this stays cross-platform with no new dependency. Assisted-by: Claude:claude-fable-5:Claude Code
… tracing ILSpyX had no instrumentation, yet most UI-visible latency bottoms out here: lazy assembly loads, the first-resolve cascade that metadata-loads every assembly in a list snapshot, per-module search strategy runs, analyzer scope scans over all assemblies and their references, bundle/zip entry extraction, and PDB loading. The provider mirrors the ICSharpCode.Decompiler design: Start/Stop pairs, keyword gating, and IsEnabled() guards at every call site; per-entry package extraction is Verbose because of its volume. AbstractSearchStrategy.Search is now a non-virtual template method that wraps the span around a new protected SearchCore, so derived strategies cannot bypass the instrumentation. Assisted-by: Claude:claude-fable-5:Claude Code
|
Triggering the enhancement of tracing was this blog article: https://devblogs.microsoft.com/performance-diagnostics/etw-mcp-intro/ |
There was a problem hiding this comment.
Pull request overview
This PR redesigns and expands performance event tracing across the ILSpy stack by introducing proper cross-platform EventSource-based instrumentation for both ICSharpCode.Decompiler (core decompilation pipeline) and ICSharpCode.ILSpyX (frontend-support operations), plus documentation and test coverage to validate event schemas and call-site behavior.
Changes:
- Reworks
ICSharpCode.Decompilertracing into keyword-gated Start/Stop spans for decompilation stages, type system init, assembly resolution, whole-project decompilation, and Verbose per-transform timings. - Adds a new
ICSharpCode.ILSpyXprovider for assembly loading/resolution, snapshot lookup builds, search, analyzer scope enumeration, package open/extraction, and debug-info loading. - Adds strict manifest/schema validation tests for both providers and documentation for collecting traces via EventPipe/ETW.
Reviewed changes
Copilot reviewed 15 out of 15 changed files in this pull request and generated 3 comments.
Show a summary per file
| File | Description |
|---|---|
| ILSpy/Search/RunningSearch.cs | Adds per-module search Start/Stop tracing via the ILSpyX provider. |
| ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs | Adds provider manifest/schema validation and behavioral tests for ILSpyX events. |
| ICSharpCode.ILSpyX/LoadedPackage.cs | Emits package open/extraction events (with Verbose gating for per-entry timing). |
| ICSharpCode.ILSpyX/LoadedAssembly.cs | Instruments assembly load, debug-info load, and reference resolution with outcome reporting. |
| ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs | Introduces the ICSharpCode.ILSpyX EventSource provider, keywords, and NonEvent helpers. |
| ICSharpCode.ILSpyX/AssemblyListSnapshot.cs | Adds snapshot lookup build Start/Stop spans around lookup construction. |
| ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs | Wraps lazy scope enumeration in an analyzer span when tracing is enabled. |
| ICSharpCode.Decompiler/TypeSystem/DecompilerTypeSystem.cs | Adds type system init Start/Stop span including a resolved-reference count payload. |
| ICSharpCode.Decompiler/Metadata/UniversalAssemblyResolver.cs | Instruments assembly probing in FindAssemblyFile with Start/Stop events (non-VSADDIN). |
| ICSharpCode.Decompiler/Instrumentation/DecompilerEventSource.cs | Major redesign of the decompiler provider: keywords, spans, and per-transform events + NonEvent guards. |
| ICSharpCode.Decompiler/IL/Instructions/ILFunction.cs | Adds Verbose per-IL-transform timing with cached tracing gate. |
| ICSharpCode.Decompiler/CSharp/ProjectDecompiler/WholeProjectDecompiler.cs | Adds whole-project and per-file Start/Stop spans and counts. |
| ICSharpCode.Decompiler/CSharp/CSharpDecompiler.cs | Adds per-type/per-member spans and Verbose per-AST-transform timing. |
| ICSharpCode.Decompiler.Tests/Instrumentation/DecompilerEventSourceTests.cs | Adds provider manifest/schema validation and behavioral tests for decompiler events. |
| docs/CollectingEventTraces.md | Documents provider keywords/levels and how to collect traces with dotnet-trace/PerfView. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| Init(mainModuleWithOptions, referencedAssembliesWithOptions); | ||
| } | ||
| this.mainModule = (MetadataModule)base.MainModule; | ||
| return referencedAssemblies.Count; |
There was a problem hiding this comment.
Fixed in 28606d8. InitializeCoreAsync now returns referencedAssembliesWithOptions.Count, i.e. the final reference set passed to Init() (distinct assemblies after the same-name/version dedup, plus resolved non-assembly modules), and the XML doc was updated to match. The raw resolve fan-out is still observable per reference via the AssemblyResolveStart/Stop events, so no information is lost.
| [Test] | ||
| public void FiringEveryEventProducesNoEventSourceErrors() | ||
| { |
There was a problem hiding this comment.
Fixed in 28606d8. Rather than serializing the test (which would not help against the non-test ILSpy components emitting events), every string payload the test fires now carries a unique "SchemaSmokeTest." marker and the count assertions filter on it, so concurrent decompilations in parallel fixtures cannot affect the counts. The behavioral tests already filtered by identifiable payloads.
| [Test] | ||
| public void FiringEveryEventProducesNoEventSourceErrors() | ||
| { |
There was a problem hiding this comment.
Fixed in 28606d8, same approach as the decompiler-side test: string payloads carry a unique "SchemaSmokeTest." marker that the count assertions filter on. SnapshotLookupBuildStart/Stop have no string payload, so those two use a sentinel assemblyCount (987654) as the filter instead.
|
Good context - the keyword/level split in both providers is designed exactly for that kind of workflow: an ETW/EventPipe session can enable just the area under investigation (e.g. |
Collecting from the two EventSource providers differs by tooling, not by platform: dotnet-trace/EventPipe works the same everywhere, with ETW/PerfView as the Windows-only alternative. The doc lists the keyword masks and levels so sessions can enable only the areas of interest. Assisted-by: Claude:claude-fable-5:Claude Code
TypeSystemInitStop now reports the size of the final reference set passed to Init() instead of the raw resolve count, which included same-name duplicates that the version dedup later drops. The schema smoke tests asserted exact global event counts, but the providers are process-wide and the decompiler fixtures run in parallel, so unrelated decompilations could inflate the counts; every string payload now carries a unique marker (and the string-less snapshot events a sentinel count) that the assertions filter on. Assisted-by: Claude:claude-fable-5:Claude Code
28606d8 to
79342c4
Compare
Reworks the event tracing that #2519 started into proper, cross-platform performance instrumentation for both
ICSharpCode.DecompilerandICSharpCode.ILSpyX.Accepted plan
ICSharpCode.Decompilerprovider freely (the five flat events from Add ETW for Performance Measuring #2519 are replaced; back-compat was explicitly waived): Start/Stop event pairs instead of one-shot "took N ms" events, keyword gating, and coverage of the stages that actually cost time - type system initialization, assembly resolution probing, whole-project decompilation, and per-transform timing of the IL/AST pipelines (Verbose, since PR Add ETW for Performance Measuring #2519's[Conditional("STEP")]Stepper only exists in Debug builds).ICSharpCode.ILSpyXprovider for the frontend-support costs: assembly loading (whichIFileLoaderwon), reference resolution (with outcome), snapshot lookup builds, per-module search, analyzer scope scans, bundle/zip extraction, and PDB loading.EventSourceis in-box for netstandard2.0 and flows over both ETW (PerfView) and EventPipe (dotnet-trace), so the same instrumentation works on Windows, Linux and macOS.ActivitySourcewas considered and rejected because it would add theSystem.Diagnostics.DiagnosticSourcepackage to the dependency-free core library.Start/Stop pairs mean trace viewers derive durations and nesting from event timestamps - call sites do not time themselves, except for the high-volume single-shot events (per-transform, per-extracted-entry) which carry an explicit
elapsedMs.High-level overview
ICSharpCode.Decompiler(keywordsDecompilation,TypeSystem,AssemblyResolver,ProjectDecompiler,Transforms):DecompileTypeStart/Stop,DecompileMemberStart/Stop(token, member kind, IL body size)DoDecompileoverloads inCSharpDecompilerTypeSystemInitStart/Stop(resolved reference count)DecompilerTypeSystem.InitializeAsyncAssemblyResolveStart/Stop(resolved path, success)UniversalAssemblyResolver.FindAssemblyFileProjectDecompilationStart/Stop,ProjectFileStart/StopWholeProjectDecompiler(incl. the parallel per-file loop)ILTransformExecuted,AstTransformExecuted(Verbose)ILFunction.RunTransforms/CSharpDecompiler.RunTransformsICSharpCode.ILSpyX(keywordsAssemblyLoad,Resolver,Search,Analyzers,Packages,DebugInfo):AssemblyLoadStart/Stop(winning loader, success)LoadedAssembly.LoadAsyncAssemblyResolveStart/Stop(outcome: found-in-list / loaded-from-disk / similar-match / not-found)MyAssemblyResolver.ResolveAsyncSnapshotLookupBuildStart/StopAssemblyListSnapshotlookup construction (the first-resolve cascade)SearchModuleStart/StopRunningSearch.RunSearch(the app-side per-assembly loop)AnalyzerScopeStart/Stop(modules in scope)AnalyzerScope.GetModulesInScope(span wraps the lazy enumeration)PackageOpened,PackageEntryExtracted(Verbose)LoadedPackagebundle/zip open and per-entry decompressionDebugInfoLoadStart/Stop(provider kind)LoadedAssembly.LoadDebugInfoAre the
IsEnabledguards necessary?Short answer: a check must exist somewhere, but not at the call sites -
WriteEventalready no-ops internally when the provider is disabled, so the branch itself buys nothing. What a naive "just write the event" pattern would actually pay for with tracing off:FullNamebuilds a new string per call - tens of thousands of allocations on a whole-module decompilation.params object[]marshaling: events with 4+ mixed args have no exactWriteEventoverload, so C# allocates the args array and boxes the ints before the internal enabled-check can skip them. This is the classic EventSource trap, and the same category of always-on overhead Add ETW for Performance Measuring #2519 had (it allocated aStopwatchplusFullNameper member unconditionally).Stopwatch.GetTimestamp()(QPC) calls per transform, ~40 transforms x every method - millions of calls on a large assembly, for Verbose data that is almost never collected.Because readability matters more than guard micro-plumbing, the guards were refactored into the providers using the dotnet/runtime pattern: strongly-typed
[NonEvent]overloads (e.g.DecompileMemberStart(IEntity, DecompiledMemberKind)) checkIsEnabled()before extracting any payload. Call sites read like plain logging - nobool tracelocals, no wrapper/Coremethod splits kept purely for tracing. The only surviving call-site guards are the cachedboolin the twoRunTransformsloops and the package-entry extraction paths (case 3 above), each one variable in one method. Along the way theSearch/SearchCoretemplate split was reverted (the span moved to the single call site inRunningSearch) and the bundle/zip Start/Stop span collapsed to a singlePackageOpenedcompletion event.Net effect: disabled tracing costs one branch and zero allocations everywhere, and the instrumentation noise is concentrated in the two
*EventSource.csfiles.Validating traces
doc/CollectingEventTraces.md (added in this PR) has the per-platform instructions -
dotnet-traceattach/launch on all platforms, PerfView/ETW as the Windows alternative, plus the keyword/level reference for enabling subsets. Verified end-to-end by collecting adotnet-traceEventPipe session ofilspycmdwhole-project-decompiling an assembly: all Decompiler event types (including the Verbose per-transform ones) appear in the resulting.nettrace.Testing
EventSource.GenerateManifest(..., Strict)) plus a fire-every-event test per provider that asserts noEventSourceMessageschema errors - all 28 events covered.DecompilerTypeSystem(type system + resolver events), whole-project-decompiling a Roslyn-compiled throwaway assembly (project events), loading/resolving throughAssemblyList(load/resolve/snapshot events), PDB loading,AnalyzerScopeenumeration, zip open/extraction, and a headless-UI search run (SearchModuleevents viaSearchPaneModel).🤖 Generated with Claude Code