Browse Source

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
pull/3906/head
Christoph Wille 2 months ago
parent
commit
f5199fae24
  1. 33
      ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs
  2. 113
      ICSharpCode.ILSpyX/AssemblyListSnapshot.cs
  3. 222
      ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs
  4. 70
      ICSharpCode.ILSpyX/LoadedAssembly.cs
  5. 19
      ICSharpCode.ILSpyX/LoadedPackage.cs
  6. 280
      ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs
  7. 6
      ILSpy/Search/RunningSearch.cs

33
ICSharpCode.ILSpyX/Analyzers/AnalyzerScope.cs

@ -24,6 +24,7 @@ using System.Threading; @@ -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 @@ -55,6 +56,14 @@ namespace ICSharpCode.ILSpyX.Analyzers
}
public IEnumerable<MetadataFile> GetModulesInScope(CancellationToken ct)
{
var modules = GetModulesInScopeCore(ct);
if (!ILSpyXEventSource.Log.IsAnalyzerTracingEnabled())
return modules;
return TraceModulesInScope(modules);
}
IEnumerable<MetadataFile> GetModulesInScopeCore(CancellationToken ct)
{
if (IsLocal)
return new[] { TypeScope.ParentModule!.MetadataFile! };
@ -65,6 +74,30 @@ namespace ICSharpCode.ILSpyX.Analyzers @@ -65,6 +74,30 @@ namespace ICSharpCode.ILSpyX.Analyzers
return GetReferencingModules(TypeScope.ParentModule!.MetadataFile!, ct);
}
/// <summary>
/// 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).
/// </summary>
IEnumerable<MetadataFile> TraceModulesInScope(IEnumerable<MetadataFile> 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<MetadataFile> GetAllModules()
{
return assemblyListSnapshot.GetAllAssembliesAsync().GetAwaiter().GetResult()

113
ICSharpCode.ILSpyX/AssemblyListSnapshot.cs

@ -28,6 +28,7 @@ using ICSharpCode.Decompiler.Metadata; @@ -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 @@ -79,73 +80,89 @@ namespace ICSharpCode.ILSpyX
private async Task<Dictionary<string, MetadataFile>> CreateLoadedAssemblyLookupAsync(bool shortNames)
{
var result = new Dictionary<string, MetadataFile>(StringComparer.OrdinalIgnoreCase);
foreach (LoadedAssembly loaded in assemblies)
ILSpyXEventSource.Log.SnapshotLookupBuildStart(assemblies.Length);
try
{
try
var result = new Dictionary<string, MetadataFile>(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<Dictionary<string, List<(MetadataFile module, Version version)>>> CreateLoadedAssemblyShortNameGroupLookupAsync()
{
var result = new Dictionary<string, List<(MetadataFile module, Version version)>>(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<string, List<(MetadataFile module, Version version)>>(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);
}
}
/// <summary>

222
ICSharpCode.ILSpyX/Instrumentation/ILSpyXEventSource.cs

@ -0,0 +1,222 @@ @@ -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
{
/// <summary>
/// Outcome reported in the AssemblyResolveStop event.
/// </summary>
public enum AssemblyResolveOutcome
{
NotFound = 0,
FoundInList = 1,
LoadedFromDisk = 2,
SimilarNameMatch = 3,
ProvidedByParentResolver = 4,
}
/// <summary>
/// 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.
/// </summary>
[EventSource(Name = "ICSharpCode.ILSpyX")]
public sealed class ILSpyXEventSource : EventSource
{
public static class Keywords
{
/// <summary>Loading assembly files from disk (file loaders, PE parsing).</summary>
public const EventKeywords AssemblyLoad = (EventKeywords)0x1;
/// <summary>Assembly reference resolution and assembly-list lookup construction.</summary>
public const EventKeywords Resolver = (EventKeywords)0x2;
/// <summary>Per-module search strategy execution.</summary>
public const EventKeywords Search = (EventKeywords)0x4;
/// <summary>Analyzer scope determination (referencing-modules scans).</summary>
public const EventKeywords Analyzers = (EventKeywords)0x8;
/// <summary>Bundle/zip package opening and per-entry extraction (extraction is Verbose).</summary>
public const EventKeywords Packages = (EventKeywords)0x10;
/// <summary>Debug symbol (PDB) loading.</summary>
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);
}
/// <param name="referenceName">Full name of the assembly reference.</param>
/// <param name="outcome">One of the <see cref="AssemblyResolveOutcome"/> values.</param>
[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);
}
/// <summary>
/// Fractional milliseconds elapsed since a <see cref="Stopwatch.GetTimestamp"/> value.
/// </summary>
[NonEvent]
public static double ElapsedMilliseconds(long startTimestamp)
{
return (Stopwatch.GetTimestamp() - startTimestamp) * 1000.0 / Stopwatch.Frequency;
}
/// <summary>
/// Gate for the analyzer scope span: AnalyzerScope only wraps its lazily-evaluated
/// module enumeration in the tracing iterator when a session is attached.
/// </summary>
[NonEvent]
public bool IsAnalyzerTracingEnabled()
{
return IsEnabled(EventLevel.Informational, Keywords.Analyzers);
}
/// <summary>
/// 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.
/// </summary>
[NonEvent]
public bool IsPackageExtractionTracingEnabled()
{
return IsEnabled(EventLevel.Verbose, Keywords.Packages);
}
public static readonly ILSpyXEventSource Log = new ILSpyXEventSource();
}
}

70
ICSharpCode.ILSpyX/LoadedAssembly.cs

@ -31,6 +31,7 @@ using ICSharpCode.Decompiler.TypeSystem; @@ -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 @@ -408,6 +409,23 @@ namespace ICSharpCode.ILSpyX
}
async Task<LoadResult> LoadAsync(Task<Stream?>? 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<LoadResult> LoadCoreAsync(Task<Stream?>? streamTask, Action<string> reportLoaderName)
{
using var stream = await PrepareStream();
FileLoadContext settings = new FileLoadContext(applyWinRTProjections, ParentBundle);
@ -433,6 +451,7 @@ namespace ICSharpCode.ILSpyX @@ -433,6 +451,7 @@ namespace ICSharpCode.ILSpyX
result = nextResult;
if (result.IsSuccess)
{
reportLoaderName(loader.GetType().Name);
break;
}
}
@ -450,6 +469,8 @@ namespace ICSharpCode.ILSpyX @@ -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 @@ -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 @@ -574,6 +614,22 @@ namespace ICSharpCode.ILSpyX
return ResolveAsync(reference).GetAwaiter().GetResult();
}
public async Task<MetadataFile?> 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);
}
}
/// <summary>
/// 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 @@ -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
/// </summary>
public async Task<MetadataFile?> 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 @@ -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 @@ -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 @@ -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 @@ -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;
}
}

19
ICSharpCode.ILSpyX/LoadedPackage.cs

@ -30,6 +30,7 @@ using System.Threading.Tasks; @@ -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 @@ -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;
}
/// <summary>
@ -124,6 +127,7 @@ namespace ICSharpCode.ILSpyX @@ -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 @@ -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 @@ -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 @@ -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 @@ -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;
}
}

280
ILSpy.Tests/Instrumentation/ILSpyXEventSourceTests.cs

@ -0,0 +1,280 @@ @@ -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
{
/// <summary>
/// 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.
/// </summary>
sealed class RecordingListener : EventListener
{
readonly ConcurrentQueue<(string EventName, Dictionary<string, object?> Payload)> events = new();
public RecordingListener(EventLevel level, EventKeywords keywords)
{
EnableEvents(ILSpyXEventSource.Log, level, keywords);
}
protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
var payload = new Dictionary<string, object?>();
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<Dictionary<string, object?>> 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<SearchPaneModel>();
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);
}
}
}

6
ILSpy/Search/RunningSearch.cs

@ -31,6 +31,7 @@ using ICSharpCode.Decompiler; @@ -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 @@ -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 @@ -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)

Loading…
Cancel
Save