From f5199fae24028b7dcd720622b8a227805471002f Mon Sep 17 00:00:00 2001 From: Christoph Wille Date: Wed, 22 Jul 2026 15:50:45 +0200 Subject: [PATCH] Add ILSpyXEventSource for assembly load, resolve, search and analyzer 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 --- ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs | 33 +++ ICSharpCode.ILSpyX/AssemblyListSnapshot.cs | 113 ++++--- .../Instrumentation/ILSpyXEventSource.cs | 222 ++++++++++++++ ICSharpCode.ILSpyX/LoadedAssembly.cs | 70 ++++- ICSharpCode.ILSpyX/LoadedPackage.cs | 19 +- .../Instrumentation/ILSpyXEventSourceTests.cs | 280 ++++++++++++++++++ ILSpy/Search/RunningSearch.cs | 6 + 7 files changed, 687 insertions(+), 56 deletions(-) create mode 100644 ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs create mode 100644 ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs diff --git a/ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs b/ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs index 662994761..011540124 100644 --- a/ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs +++ b/ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs @@ -24,6 +24,7 @@ using System.Threading; using ICSharpCode.Decompiler; using ICSharpCode.Decompiler.Metadata; using ICSharpCode.Decompiler.Util; +using ICSharpCode.ILSpyX.Instrumentation; namespace ICSharpCode.ILSpyX.Analyzers { @@ -55,6 +56,14 @@ namespace ICSharpCode.ILSpyX.Analyzers } public IEnumerable GetModulesInScope(CancellationToken ct) + { + var modules = GetModulesInScopeCore(ct); + if (!ILSpyXEventSource.Log.IsAnalyzerTracingEnabled()) + return modules; + return TraceModulesInScope(modules); + } + + IEnumerable GetModulesInScopeCore(CancellationToken ct) { if (IsLocal) return new[] { TypeScope.ParentModule!.MetadataFile! }; @@ -65,6 +74,30 @@ namespace ICSharpCode.ILSpyX.Analyzers return GetReferencingModules(TypeScope.ParentModule!.MetadataFile!, ct); } + /// + /// Wraps the lazily-evaluated scope enumeration in an AnalyzerScope trace span, so the + /// span covers the actual scan work (which happens during enumeration, not when + /// GetModulesInScope returns). + /// + IEnumerable TraceModulesInScope(IEnumerable modules) + { + string entityName = typeScope.FullName; + ILSpyXEventSource.Log.AnalyzerScopeStart(entityName); + int count = 0; + try + { + foreach (var module in modules) + { + count++; + yield return module; + } + } + finally + { + ILSpyXEventSource.Log.AnalyzerScopeStop(entityName, count); + } + } + public IEnumerable GetAllModules() { return assemblyListSnapshot.GetAllAssembliesAsync().GetAwaiter().GetResult() diff --git a/ICSharpCode.ILSpyX/AssemblyListSnapshot.cs b/ICSharpCode.ILSpyX/AssemblyListSnapshot.cs index 69b79d16a..5a1b6edcf 100644 --- a/ICSharpCode.ILSpyX/AssemblyListSnapshot.cs +++ b/ICSharpCode.ILSpyX/AssemblyListSnapshot.cs @@ -28,6 +28,7 @@ using ICSharpCode.Decompiler.Metadata; using ICSharpCode.Decompiler.Util; using ICSharpCode.ILSpyX.Extensions; using ICSharpCode.ILSpyX.FileLoaders; +using ICSharpCode.ILSpyX.Instrumentation; namespace ICSharpCode.ILSpyX { @@ -79,73 +80,89 @@ namespace ICSharpCode.ILSpyX private async Task> CreateLoadedAssemblyLookupAsync(bool shortNames) { - var result = new Dictionary(StringComparer.OrdinalIgnoreCase); - foreach (LoadedAssembly loaded in assemblies) + ILSpyXEventSource.Log.SnapshotLookupBuildStart(assemblies.Length); + try { - try + var result = new Dictionary(StringComparer.OrdinalIgnoreCase); + foreach (LoadedAssembly loaded in assemblies) { - var module = await loaded.GetMetadataFileOrNullAsync().ConfigureAwait(false); - if (module == null) - continue; - var reader = module.Metadata; - if (reader == null || !reader.IsAssembly) - continue; - string tfm = await loaded.GetTargetFrameworkIdAsync().ConfigureAwait(false); - if (tfm.StartsWith(".NETFramework,Version=v4.", StringComparison.Ordinal)) + try { - tfm = ".NETFramework,Version=v4"; + var module = await loaded.GetMetadataFileOrNullAsync().ConfigureAwait(false); + if (module == null) + continue; + var reader = module.Metadata; + if (reader == null || !reader.IsAssembly) + continue; + string tfm = await loaded.GetTargetFrameworkIdAsync().ConfigureAwait(false); + if (tfm.StartsWith(".NETFramework,Version=v4.", StringComparison.Ordinal)) + { + tfm = ".NETFramework,Version=v4"; + } + string key = tfm + ";" + + (shortNames ? module.Name : module.FullName); + if (!result.ContainsKey(key)) + { + result.Add(key, module); + } } - string key = tfm + ";" - + (shortNames ? module.Name : module.FullName); - if (!result.ContainsKey(key)) + catch (BadImageFormatException) { - result.Add(key, module); + continue; } } - catch (BadImageFormatException) - { - continue; - } + return result; + } + finally + { + ILSpyXEventSource.Log.SnapshotLookupBuildStop(assemblies.Length); } - return result; } private async Task>> CreateLoadedAssemblyShortNameGroupLookupAsync() { - var result = new Dictionary>(StringComparer.OrdinalIgnoreCase); - - foreach (LoadedAssembly loaded in assemblies) + ILSpyXEventSource.Log.SnapshotLookupBuildStart(assemblies.Length); + try { - try - { - var module = await loaded.GetMetadataFileOrNullAsync().ConfigureAwait(false); - var reader = module?.Metadata; - if (reader == null || !reader.IsAssembly) - continue; - var asmDef = reader.GetAssemblyDefinition(); - var asmDefName = reader.GetString(asmDef.Name); + var result = new Dictionary>(StringComparer.OrdinalIgnoreCase); - var line = (module!, version: asmDef.Version); - - if (!result.TryGetValue(asmDefName, out var existing)) + foreach (LoadedAssembly loaded in assemblies) + { + try + { + var module = await loaded.GetMetadataFileOrNullAsync().ConfigureAwait(false); + var reader = module?.Metadata; + if (reader == null || !reader.IsAssembly) + continue; + var asmDef = reader.GetAssemblyDefinition(); + var asmDefName = reader.GetString(asmDef.Name); + + var line = (module!, version: asmDef.Version); + + if (!result.TryGetValue(asmDefName, out var existing)) + { + existing = new List<(MetadataFile module, Version version)>(); + result.Add(asmDefName, existing); + existing.Add(line); + continue; + } + + int index = existing.BinarySearch(line.version, l => l.version); + index = index < 0 ? ~index : index + 1; + existing.Insert(index, line); + } + catch (BadImageFormatException) { - existing = new List<(MetadataFile module, Version version)>(); - result.Add(asmDefName, existing); - existing.Add(line); continue; } - - int index = existing.BinarySearch(line.version, l => l.version); - index = index < 0 ? ~index : index + 1; - existing.Insert(index, line); - } - catch (BadImageFormatException) - { - continue; } - } - return result; + return result; + } + finally + { + ILSpyXEventSource.Log.SnapshotLookupBuildStop(assemblies.Length); + } } /// diff --git a/ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs b/ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs new file mode 100644 index 000000000..3eccd86bd --- /dev/null +++ b/ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs @@ -0,0 +1,222 @@ +// Copyright (c) 2026 Christoph Wille +// +// Permission is hereby granted, free of charge, to any person obtaining a copy of this +// software and associated documentation files (the "Software"), to deal in the Software +// without restriction, including without limitation the rights to use, copy, modify, merge, +// publish, distribute, sublicense, and/or sell copies of the Software, and to permit persons +// to whom the Software is furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in all copies or +// substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, +// INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR +// PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE +// FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR +// OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +// DEALINGS IN THE SOFTWARE. + +using System.Diagnostics; +using System.Diagnostics.Tracing; + +using ICSharpCode.Decompiler.Metadata; +using ICSharpCode.ILSpyX.Search; + +namespace ICSharpCode.ILSpyX.Instrumentation +{ + /// + /// Outcome reported in the AssemblyResolveStop event. + /// + public enum AssemblyResolveOutcome + { + NotFound = 0, + FoundInList = 1, + LoadedFromDisk = 2, + SimilarNameMatch = 3, + ProvidedByParentResolver = 4, + } + + /// + /// Performance tracing for assembly loading, reference resolution, search, analyzers and + /// package extraction. + /// + /// The provider is consumable via ETW (PerfView) on Windows and via EventPipe + /// (dotnet-trace) on all platforms. Start/Stop event pairs let trace viewers compute + /// durations and nesting from the event timestamps; call sites therefore do not measure + /// elapsed time themselves except for the high-volume single-shot events (per-entry + /// extraction), which carry an explicit elapsedMs payload. + /// + /// Where payload extraction would allocate on a hot path, call sites use the + /// strongly-typed [NonEvent] overloads below, which check IsEnabled() before computing + /// anything. The remaining [Event] methods are cheap enough to call unconditionally: + /// WriteEvent no-ops internally when the provider is disabled. + /// + [EventSource(Name = "ICSharpCode.ILSpyX")] + public sealed class ILSpyXEventSource : EventSource + { + public static class Keywords + { + /// Loading assembly files from disk (file loaders, PE parsing). + public const EventKeywords AssemblyLoad = (EventKeywords)0x1; + /// Assembly reference resolution and assembly-list lookup construction. + public const EventKeywords Resolver = (EventKeywords)0x2; + /// Per-module search strategy execution. + public const EventKeywords Search = (EventKeywords)0x4; + /// Analyzer scope determination (referencing-modules scans). + public const EventKeywords Analyzers = (EventKeywords)0x8; + /// Bundle/zip package opening and per-entry extraction (extraction is Verbose). + public const EventKeywords Packages = (EventKeywords)0x10; + /// Debug symbol (PDB) loading. + public const EventKeywords DebugInfo = (EventKeywords)0x20; + } + + [Event(1, Level = EventLevel.Informational, Keywords = Keywords.AssemblyLoad)] + public void AssemblyLoadStart(string fileName) + { + WriteEvent(1, fileName); + } + + [Event(2, Level = EventLevel.Informational, Keywords = Keywords.AssemblyLoad)] + public void AssemblyLoadStop(string fileName, string loaderName, bool success) + { + WriteEvent(2, fileName, loaderName, success); + } + + [Event(3, Level = EventLevel.Informational, Keywords = Keywords.Resolver)] + public void AssemblyResolveStart(string referenceName) + { + WriteEvent(3, referenceName); + } + + /// Full name of the assembly reference. + /// One of the values. + [Event(4, Level = EventLevel.Informational, Keywords = Keywords.Resolver)] + public void AssemblyResolveStop(string referenceName, int outcome) + { + WriteEvent(4, referenceName, outcome); + } + + [Event(5, Level = EventLevel.Informational, Keywords = Keywords.Resolver)] + public void SnapshotLookupBuildStart(int assemblyCount) + { + WriteEvent(5, assemblyCount); + } + + [Event(6, Level = EventLevel.Informational, Keywords = Keywords.Resolver)] + public void SnapshotLookupBuildStop(int assemblyCount) + { + WriteEvent(6, assemblyCount); + } + + [Event(7, Level = EventLevel.Informational, Keywords = Keywords.DebugInfo)] + public void DebugInfoLoadStart(string assemblyFileName) + { + WriteEvent(7, assemblyFileName); + } + + [Event(8, Level = EventLevel.Informational, Keywords = Keywords.DebugInfo)] + public void DebugInfoLoadStop(string assemblyFileName, string providerKind) + { + WriteEvent(8, assemblyFileName, providerKind); + } + + [Event(9, Level = EventLevel.Informational, Keywords = Keywords.Search)] + public void SearchModuleStart(string moduleName, string strategyName) + { + WriteEvent(9, moduleName, strategyName); + } + + [Event(10, Level = EventLevel.Informational, Keywords = Keywords.Search)] + public void SearchModuleStop(string moduleName, string strategyName) + { + WriteEvent(10, moduleName, strategyName); + } + + [Event(11, Level = EventLevel.Informational, Keywords = Keywords.Analyzers)] + public void AnalyzerScopeStart(string analyzedEntityName) + { + WriteEvent(11, analyzedEntityName); + } + + [Event(12, Level = EventLevel.Informational, Keywords = Keywords.Analyzers)] + public void AnalyzerScopeStop(string analyzedEntityName, int modulesInScope) + { + WriteEvent(12, analyzedEntityName, modulesInScope); + } + + [Event(13, Level = EventLevel.Informational, Keywords = Keywords.Packages)] + public void PackageOpened(string fileName, string packageKind, int entryCount) + { + WriteEvent(13, fileName, packageKind, entryCount); + } + + [Event(14, Level = EventLevel.Verbose, Keywords = Keywords.Packages)] + public void PackageEntryExtracted(string entryName, long bytes, double elapsedMs) + { + WriteEvent(14, entryName, bytes, elapsedMs); + } + + // Strongly-typed entry points for hot paths: they check IsEnabled() before + // extracting payloads, so a disabled provider costs a single branch and zero + // allocations. + + [NonEvent] + public void AssemblyResolveStart(IAssemblyReference reference) + { + if (IsEnabled(EventLevel.Informational, Keywords.Resolver)) + AssemblyResolveStart(reference.FullName); + } + + [NonEvent] + public void AssemblyResolveStop(IAssemblyReference reference, AssemblyResolveOutcome outcome) + { + if (IsEnabled(EventLevel.Informational, Keywords.Resolver)) + AssemblyResolveStop(reference.FullName, (int)outcome); + } + + [NonEvent] + public void SearchModuleStart(MetadataFile module, AbstractSearchStrategy strategy) + { + if (IsEnabled(EventLevel.Informational, Keywords.Search)) + SearchModuleStart(module.Name, strategy.GetType().Name); + } + + [NonEvent] + public void SearchModuleStop(MetadataFile module, AbstractSearchStrategy strategy) + { + if (IsEnabled(EventLevel.Informational, Keywords.Search)) + SearchModuleStop(module.Name, strategy.GetType().Name); + } + + /// + /// Fractional milliseconds elapsed since a value. + /// + [NonEvent] + public static double ElapsedMilliseconds(long startTimestamp) + { + return (Stopwatch.GetTimestamp() - startTimestamp) * 1000.0 / Stopwatch.Frequency; + } + + /// + /// Gate for the analyzer scope span: AnalyzerScope only wraps its lazily-evaluated + /// module enumeration in the tracing iterator when a session is attached. + /// + [NonEvent] + public bool IsAnalyzerTracingEnabled() + { + return IsEnabled(EventLevel.Informational, Keywords.Analyzers); + } + + /// + /// Gate for the per-entry extraction events: extraction sites capture this once so + /// they skip the Stopwatch.GetTimestamp() calls when no Verbose session is attached. + /// + [NonEvent] + public bool IsPackageExtractionTracingEnabled() + { + return IsEnabled(EventLevel.Verbose, Keywords.Packages); + } + + public static readonly ILSpyXEventSource Log = new ILSpyXEventSource(); + } +} diff --git a/ICSharpCode.ILSpyX/LoadedAssembly.cs b/ICSharpCode.ILSpyX/LoadedAssembly.cs index a75ce520b..e2775843a 100644 --- a/ICSharpCode.ILSpyX/LoadedAssembly.cs +++ b/ICSharpCode.ILSpyX/LoadedAssembly.cs @@ -31,6 +31,7 @@ using ICSharpCode.Decompiler.TypeSystem; using ICSharpCode.Decompiler.TypeSystem.Implementation; using ICSharpCode.Decompiler.Util; using ICSharpCode.ILSpyX.FileLoaders; +using ICSharpCode.ILSpyX.Instrumentation; using ICSharpCode.ILSpyX.PdbProvider; #nullable enable @@ -408,6 +409,23 @@ namespace ICSharpCode.ILSpyX } async Task LoadAsync(Task? streamTask) + { + ILSpyXEventSource.Log.AssemblyLoadStart(fileName); + string loaderName = ""; + bool success = false; + try + { + var result = await LoadCoreAsync(streamTask, name => loaderName = name).ConfigureAwait(false); + success = result.MetadataFile != null || result.Package != null; + return result; + } + finally + { + ILSpyXEventSource.Log.AssemblyLoadStop(fileName, loaderName, success); + } + } + + async Task LoadCoreAsync(Task? streamTask, Action reportLoaderName) { using var stream = await PrepareStream(); FileLoadContext settings = new FileLoadContext(applyWinRTProjections, ParentBundle); @@ -433,6 +451,7 @@ namespace ICSharpCode.ILSpyX result = nextResult; if (result.IsSuccess) { + reportLoaderName(loader.GetType().Name); break; } } @@ -450,6 +469,8 @@ namespace ICSharpCode.ILSpyX try { result = await PEFileLoader.LoadPEFile(fileName, stream, settings).ConfigureAwait(false); + if (result.IsSuccess) + reportLoaderName(nameof(PEFileLoader)); } catch (Exception ex) { @@ -504,6 +525,25 @@ namespace ICSharpCode.ILSpyX } IDebugInfoProvider? LoadDebugInfo(PEFile? module) + { + if (module == null || !useDebugSymbols) + { + return LoadDebugInfoCore(module); + } + ILSpyXEventSource.Log.DebugInfoLoadStart(fileName); + IDebugInfoProvider? provider = null; + try + { + provider = LoadDebugInfoCore(module); + return provider; + } + finally + { + ILSpyXEventSource.Log.DebugInfoLoadStop(fileName, provider?.GetType().Name ?? "none"); + } + } + + IDebugInfoProvider? LoadDebugInfoCore(PEFile? module) { if (module == null) { @@ -574,6 +614,22 @@ namespace ICSharpCode.ILSpyX return ResolveAsync(reference).GetAwaiter().GetResult(); } + public async Task ResolveAsync(IAssemblyReference reference) + { + ILSpyXEventSource.Log.AssemblyResolveStart(reference); + var outcome = AssemblyResolveOutcome.NotFound; + try + { + var (module, resolvedVia) = await ResolveCoreAsync(reference).ConfigureAwait(false); + outcome = resolvedVia; + return module; + } + finally + { + ILSpyXEventSource.Log.AssemblyResolveStop(reference, outcome); + } + } + /// /// 0) if we're inside a package, look for filename.dll in parent directories /// 1) try to find exact match by tfm + full asm name in loaded assemblies @@ -586,7 +642,7 @@ namespace ICSharpCode.ILSpyX /// 8) search C:\Windows\Microsoft.NET\Framework64\v4.0.30319 /// 9) try to find match by asm name (no tfm/version) in loaded assemblies /// - public async Task ResolveAsync(IAssemblyReference reference) + async Task<(MetadataFile? Module, AssemblyResolveOutcome Outcome)> ResolveCoreAsync(IAssemblyReference reference) { MetadataFile? module; // 0) if we're inside a package, look for filename.dll in parent directories @@ -594,7 +650,7 @@ namespace ICSharpCode.ILSpyX { module = await providedAssemblyResolver.ResolveAsync(reference).ConfigureAwait(false); if (module != null) - return module; + return (module, AssemblyResolveOutcome.ProvidedByParentResolver); } string tfm = await tfmTask.ConfigureAwait(false); @@ -604,7 +660,7 @@ namespace ICSharpCode.ILSpyX if (module != null) { referenceLoadInfo.AddMessageOnce(reference.FullName, MessageKind.Info, "Success - Found in Assembly List"); - return module; + return (module, AssemblyResolveOutcome.FoundInList); } string? file = parent.GetUniversalResolver(applyWinRTProjections).FindAssemblyFile(reference); @@ -624,9 +680,10 @@ namespace ICSharpCode.ILSpyX if (asm != null) { referenceLoadInfo.AddMessage(reference.FullName, MessageKind.Info, "Success - Loading from: " + file); - return await asm.GetMetadataFileOrNullAsync().ConfigureAwait(false); + module = await asm.GetMetadataFileOrNullAsync().ConfigureAwait(false); + return (module, module != null ? AssemblyResolveOutcome.LoadedFromDisk : AssemblyResolveOutcome.NotFound); } - return null; + return (null, AssemblyResolveOutcome.NotFound); } else { @@ -635,12 +692,13 @@ namespace ICSharpCode.ILSpyX if (module == null) { referenceLoadInfo.AddMessageOnce(reference.FullName, MessageKind.Error, "Could not find reference: " + reference.FullName); + return (null, AssemblyResolveOutcome.NotFound); } else { referenceLoadInfo.AddMessageOnce(reference.FullName, MessageKind.Info, "Success - Found in Assembly List with different TFM or version: " + module.FileName); + return (module, AssemblyResolveOutcome.SimilarNameMatch); } - return module; } } diff --git a/ICSharpCode.ILSpyX/LoadedPackage.cs b/ICSharpCode.ILSpyX/LoadedPackage.cs index 13891cee9..84793c800 100644 --- a/ICSharpCode.ILSpyX/LoadedPackage.cs +++ b/ICSharpCode.ILSpyX/LoadedPackage.cs @@ -30,6 +30,7 @@ using System.Threading.Tasks; using ICSharpCode.Decompiler; using ICSharpCode.Decompiler.Metadata; +using ICSharpCode.ILSpyX.Instrumentation; namespace ICSharpCode.ILSpyX { @@ -104,8 +105,10 @@ namespace ICSharpCode.ILSpyX { Debug.WriteLine($"LoadedPackage.FromZipFile({file})"); using var archive = ZipFile.OpenRead(file); - return new LoadedPackage(PackageKind.Zip, + var package = new LoadedPackage(PackageKind.Zip, archive.Entries.Select(entry => new ZipFileEntry(file, entry))); + ILSpyXEventSource.Log.PackageOpened(file, "zip", package.Entries.Count); + return package; } /// @@ -124,6 +127,7 @@ namespace ICSharpCode.ILSpyX var result = new LoadedPackage(PackageKind.Bundle, entries); result.BundleHeader = manifest; view = null; // don't dispose the view, we're still using it in the bundle entries + ILSpyXEventSource.Log.PackageOpened(fileName, "bundle", entries.Count); return result; } catch (InvalidDataException) @@ -175,6 +179,8 @@ namespace ICSharpCode.ILSpyX public override Stream? TryOpenStream() { Debug.WriteLine("Decompress " + Name); + bool trace = ILSpyXEventSource.Log.IsPackageExtractionTracingEnabled(); + long traceStart = trace ? Stopwatch.GetTimestamp() : 0; using var archive = ZipFile.OpenRead(zipFile); var entry = archive.GetEntry(Name); if (entry == null) @@ -185,6 +191,8 @@ namespace ICSharpCode.ILSpyX s.CopyTo(memoryStream); } memoryStream.Position = 0; + if (trace) + ILSpyXEventSource.Log.PackageEntryExtracted(Name, memoryStream.Length, ILSpyXEventSource.ElapsedMilliseconds(traceStart)); return memoryStream; } @@ -219,10 +227,15 @@ namespace ICSharpCode.ILSpyX public override Stream TryOpenStream() { Debug.WriteLine("Open bundle member " + Name); + bool trace = ILSpyXEventSource.Log.IsPackageExtractionTracingEnabled(); + long traceStart = trace ? Stopwatch.GetTimestamp() : 0; if (entry.CompressedSize == 0) { - return new UnmanagedMemoryStream(view.SafeMemoryMappedViewHandle, entry.Offset, entry.Size); + var stream = new UnmanagedMemoryStream(view.SafeMemoryMappedViewHandle, entry.Offset, entry.Size); + if (trace) + ILSpyXEventSource.Log.PackageEntryExtracted(Name, entry.Size, ILSpyXEventSource.ElapsedMilliseconds(traceStart)); + return stream; } else { @@ -236,6 +249,8 @@ namespace ICSharpCode.ILSpyX } decompressedStream.Seek(0, SeekOrigin.Begin); + if (trace) + ILSpyXEventSource.Log.PackageEntryExtracted(Name, entry.Size, ILSpyXEventSource.ElapsedMilliseconds(traceStart)); return decompressedStream; } } diff --git a/ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs b/ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs new file mode 100644 index 000000000..bdf4dac9c --- /dev/null +++ b/ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs @@ -0,0 +1,280 @@ +// Copyright (c) 2026 Christoph Wille +// +// Permission is hereby granted, free of charge, to any person obtaining a copy of this +// software and associated documentation files (the "Software"), to deal in the Software +// without restriction, including without limitation the rights to use, copy, modify, merge, +// publish, distribute, sublicense, and/or sell copies of the Software, and to permit persons +// to whom the Software is furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in all copies or +// substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, +// INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR +// PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE +// FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR +// OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +// DEALINGS IN THE SOFTWARE. + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.IO; +using System.IO.Compression; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; + +using Avalonia.Headless.NUnit; + +using ICSharpCode.Decompiler.TypeSystem; +using ICSharpCode.ILSpyX; +using ICSharpCode.ILSpyX.Analyzers; +using ICSharpCode.ILSpyX.Instrumentation; +using ICSharpCode.ILSpyX.Search; + +using ICSharpCode.ILSpy.AppEnv; +using ICSharpCode.ILSpy.Search; + +using NUnit.Framework; + +namespace ICSharpCode.ILSpy.Tests.Instrumentation; + +[TestFixture] +public class ILSpyXEventSourceTests +{ + /// + /// Captures all events the "ICSharpCode.ILSpyX" provider emits while the listener is + /// alive. Events are recorded process-wide, so assertions must filter by payload to stay + /// robust under parallel test runs. + /// + sealed class RecordingListener : EventListener + { + readonly ConcurrentQueue<(string EventName, Dictionary Payload)> events = new(); + + public RecordingListener(EventLevel level, EventKeywords keywords) + { + EnableEvents(ILSpyXEventSource.Log, level, keywords); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + var payload = new Dictionary(); + if (eventData.PayloadNames != null && eventData.Payload != null) + { + for (int i = 0; i < eventData.PayloadNames.Count; i++) + { + payload[eventData.PayloadNames[i]] = eventData.Payload[i]; + } + } + events.Enqueue((eventData.EventName ?? "", payload)); + } + + public List> EventsNamed(string eventName) + { + return events.Where(e => e.EventName == eventName).Select(e => e.Payload).ToList(); + } + } + + [Test] + public void ManifestIsValid() + { + string? manifest = EventSource.GenerateManifest(typeof(ILSpyXEventSource), typeof(ILSpyXEventSource).Assembly.Location, EventManifestOptions.Strict); + Assert.That(manifest, Is.Not.Null.And.Not.Empty); + } + + [Test] + public void FiringEveryEventProducesNoEventSourceErrors() + { + using var listener = new RecordingListener(EventLevel.Verbose, EventKeywords.All); + var log = ILSpyXEventSource.Log; + log.AssemblyLoadStart("test.dll"); + log.AssemblyLoadStop("test.dll", "PEFileLoader", true); + log.AssemblyResolveStart("System.Runtime"); + log.AssemblyResolveStop("System.Runtime", (int)AssemblyResolveOutcome.FoundInList); + log.SnapshotLookupBuildStart(10); + log.SnapshotLookupBuildStop(10); + log.DebugInfoLoadStart("test.dll"); + log.DebugInfoLoadStop("test.dll", "PortableDebugInfoProvider"); + log.SearchModuleStart("TestModule", "MemberSearchStrategy"); + log.SearchModuleStop("TestModule", "MemberSearchStrategy"); + log.AnalyzerScopeStart("MyNamespace.MyType"); + log.AnalyzerScopeStop("MyNamespace.MyType", 3); + log.PackageOpened("app.zip", "zip", 12); + log.PackageEntryExtracted("lib/test.dll", 4096L, 0.5); + + // A mismatch between an [Event] method's signature and its WriteEvent call surfaces + // as an "EventSourceMessage" error event on the same provider. + Assert.That(listener.EventsNamed("EventSourceMessage"), Is.Empty); + + string[] expected = { + "AssemblyLoadStart", "AssemblyLoadStop", + "AssemblyResolveStart", "AssemblyResolveStop", + "SnapshotLookupBuildStart", "SnapshotLookupBuildStop", + "DebugInfoLoadStart", "DebugInfoLoadStop", + "SearchModuleStart", "SearchModuleStop", + "AnalyzerScopeStart", "AnalyzerScopeStop", + "PackageOpened", + "PackageEntryExtracted", + }; + foreach (string eventName in expected) + { + Assert.That(listener.EventsNamed(eventName), Has.Count.EqualTo(1), eventName); + } + } + + [Test] + public void LoadingAssemblyEmitsLoadAndResolveEvents() + { + using var listener = new RecordingListener(EventLevel.Informational, + ILSpyXEventSource.Keywords.AssemblyLoad | ILSpyXEventSource.Keywords.Resolver); + string location = typeof(ILSpyXEventSourceTests).Assembly.Location; + + var assemblyList = new AssemblyList(); + var asm = assemblyList.OpenAssembly(location); + var module = asm.GetMetadataFileOrNull(); + Assert.That(module, Is.Not.Null); + + var loadStarts = listener.EventsNamed("AssemblyLoadStart") + .Where(p => (string?)p["fileName"] == location).ToList(); + var loadStops = listener.EventsNamed("AssemblyLoadStop") + .Where(p => (string?)p["fileName"] == location).ToList(); + Assert.That(loadStarts, Has.Count.EqualTo(1)); + Assert.That(loadStops, Has.Count.EqualTo(1)); + Assert.That((bool)loadStops[0]["success"]!, Is.True); + Assert.That((string?)loadStops[0]["loaderName"], Is.Not.Empty); + + var resolver = asm.GetAssemblyResolver(loadOnDemand: false); + var reference = module!.AssemblyReferences.First(); + resolver.Resolve(reference); + + var resolveStarts = listener.EventsNamed("AssemblyResolveStart") + .Where(p => (string?)p["referenceName"] == reference.FullName).ToList(); + var resolveStops = listener.EventsNamed("AssemblyResolveStop") + .Where(p => (string?)p["referenceName"] == reference.FullName).ToList(); + Assert.That(resolveStarts, Has.Count.EqualTo(1)); + Assert.That(resolveStops, Has.Count.EqualTo(1)); + int outcome = (int)resolveStops[0]["outcome"]!; + Assert.That(outcome, Is.InRange((int)AssemblyResolveOutcome.NotFound, (int)AssemblyResolveOutcome.ProvidedByParentResolver)); + + // The first resolve against a snapshot builds the assembly lookup table. + var lookupStarts = listener.EventsNamed("SnapshotLookupBuildStart"); + var lookupStops = listener.EventsNamed("SnapshotLookupBuildStop"); + Assert.That(lookupStarts, Is.Not.Empty); + Assert.That(lookupStops, Has.Count.EqualTo(lookupStarts.Count)); + Assert.That(lookupStarts.Select(p => (int)p["assemblyCount"]!), Has.All.GreaterThanOrEqualTo(1)); + } + + [Test] + public void LoadingAssemblyWithDebugSymbolsEmitsDebugInfoEvents() + { + using var listener = new RecordingListener(EventLevel.Informational, ILSpyXEventSource.Keywords.DebugInfo); + string location = typeof(ILSpyXEventSourceTests).Assembly.Location; + + var assemblyList = new AssemblyList { + UseDebugSymbols = true + }; + var asm = assemblyList.OpenAssembly(location); + Assert.That(asm.GetMetadataFileOrNull(), Is.Not.Null); + + var starts = listener.EventsNamed("DebugInfoLoadStart") + .Where(p => (string?)p["assemblyFileName"] == location).ToList(); + var stops = listener.EventsNamed("DebugInfoLoadStop") + .Where(p => (string?)p["assemblyFileName"] == location).ToList(); + Assert.That(starts, Has.Count.EqualTo(1)); + Assert.That(stops, Has.Count.EqualTo(1)); + // The test assembly ships a portable PDB next to it. + Assert.That((string?)stops[0]["providerKind"], Is.EqualTo("PortableDebugInfoProvider")); + } + + [AvaloniaTest] + public async Task RunningASearchEmitsSearchModuleEvents() + { + using var listener = new RecordingListener(EventLevel.Informational, ILSpyXEventSource.Keywords.Search); + await TestHarness.BootAsync(); + + var search = AppComposition.Current.GetExport(); + search.Results.Clear(); + search.SelectedSearchMode = search.SearchModes.First(m => m.Mode == SearchMode.Type); + search.SearchTerm = "Enumerable"; + await Waiters.WaitForAsync(() => search.Results.Count > 0, timeout: TimeSpan.FromSeconds(30)); + + // The search keeps walking the remaining assemblies after the first result; + // wait until every started module span has closed. + await Waiters.WaitForAsync( + () => { + var startCount = listener.EventsNamed("SearchModuleStart").Count; + return startCount > 0 && listener.EventsNamed("SearchModuleStop").Count == startCount; + }, + timeout: TimeSpan.FromSeconds(30)); + + var starts = listener.EventsNamed("SearchModuleStart"); + var stops = listener.EventsNamed("SearchModuleStop"); + Assert.That(starts, Is.Not.Empty); + Assert.That(stops, Has.Count.EqualTo(starts.Count)); + Assert.That(starts.Select(p => (string?)p["strategyName"]), Has.All.EqualTo("MemberSearchStrategy")); + Assert.That(starts.Select(p => (string?)p["moduleName"]), Has.All.Not.Empty); + } + + [Test] + public void AnalyzerScopeEnumerationEmitsScopeEvents() + { + using var listener = new RecordingListener(EventLevel.Informational, ILSpyXEventSource.Keywords.Analyzers); + + var assemblyList = new AssemblyList(); + var asm = assemblyList.OpenAssembly(typeof(ILSpyXEventSourceTests).Assembly.Location); + var typeSystem = new DecompilerTypeSystem(asm.GetMetadataFileOrNull()!, asm.GetAssemblyResolver()); + var typeDef = typeSystem.FindType(typeof(ILSpyXEventSourceTests)).GetDefinition()!; + + var scope = new AnalyzerScope(assemblyList, typeDef); + var modules = scope.GetModulesInScope(CancellationToken.None).ToList(); + Assert.That(modules, Is.Not.Empty); + + var starts = listener.EventsNamed("AnalyzerScopeStart") + .Where(p => ((string?)p["analyzedEntityName"])?.Contains(nameof(ILSpyXEventSourceTests)) == true).ToList(); + var stops = listener.EventsNamed("AnalyzerScopeStop") + .Where(p => ((string?)p["analyzedEntityName"])?.Contains(nameof(ILSpyXEventSourceTests)) == true).ToList(); + Assert.That(starts, Has.Count.EqualTo(1)); + Assert.That(stops, Has.Count.EqualTo(1)); + Assert.That((int)stops[0]["modulesInScope"]!, Is.EqualTo(modules.Count)); + } + + [Test] + public void ZipPackageEmitsOpenAndExtractionEvents() + { + using var listener = new RecordingListener(EventLevel.Verbose, ILSpyXEventSource.Keywords.Packages); + + string zipPath = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName() + ".zip"); + byte[] content = new byte[128]; + try + { + using (var archive = ZipFile.Open(zipPath, ZipArchiveMode.Create)) + { + var entry = archive.CreateEntry("lib/test.bin"); + using var stream = entry.Open(); + stream.Write(content, 0, content.Length); + } + + var package = LoadedPackage.FromZipFile(zipPath); + var opened = listener.EventsNamed("PackageOpened") + .Where(p => (string?)p["fileName"] == zipPath).ToList(); + Assert.That(opened, Has.Count.EqualTo(1)); + Assert.That((string?)opened[0]["packageKind"], Is.EqualTo("zip")); + Assert.That((int)opened[0]["entryCount"]!, Is.EqualTo(1)); + + using var entryStream = package.Entries.Single().TryOpenStream(); + Assert.That(entryStream, Is.Not.Null); + + var extracted = listener.EventsNamed("PackageEntryExtracted") + .Where(p => (string?)p["entryName"] == "lib/test.bin").ToList(); + Assert.That(extracted, Has.Count.EqualTo(1)); + Assert.That((long)extracted[0]["bytes"]!, Is.EqualTo(content.Length)); + Assert.That((double)extracted[0]["elapsedMs"]!, Is.GreaterThanOrEqualTo(0.0)); + } + finally + { + File.Delete(zipPath); + } + } +} diff --git a/ILSpy/Search/RunningSearch.cs b/ILSpy/Search/RunningSearch.cs index e59541f19..9320c0d02 100644 --- a/ILSpy/Search/RunningSearch.cs +++ b/ILSpy/Search/RunningSearch.cs @@ -31,6 +31,7 @@ using ICSharpCode.Decompiler; using ICSharpCode.Decompiler.Metadata; using ICSharpCode.ILSpyX; using ICSharpCode.ILSpyX.Extensions; +using ICSharpCode.ILSpyX.Instrumentation; using ICSharpCode.ILSpyX.Search; using ICSharpCode.ILSpy.Languages; @@ -158,6 +159,7 @@ namespace ICSharpCode.ILSpy.Search } if (module == null) continue; + ILSpyXEventSource.Log.SearchModuleStart(module, strategy); try { strategy.Search(module, ct); @@ -172,6 +174,10 @@ namespace ICSharpCode.ILSpy.Search // dependency, internal assert) — keep the run going instead of // faulting the whole search. } + finally + { + ILSpyXEventSource.Log.SearchModuleStop(module, strategy); + } } } catch (OperationCanceledException)