Redesign DecompilerEventSource with Start/Stop tracing and keyword gating

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

ICSharpCode.Decompiler.Tests/Instrumentation/DecompilerEventSourceTests.cs

@@ -0,0 +1,310 @@
+// 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.Linq;
+
+using System.IO;
+
+using ICSharpCode.Decompiler.CSharp;
+using ICSharpCode.Decompiler.CSharp.ProjectDecompiler;
+using ICSharpCode.Decompiler.Instrumentation;
+using ICSharpCode.Decompiler.Metadata;
+using ICSharpCode.Decompiler.TypeSystem;
+
+using Microsoft.CodeAnalysis;
+using Microsoft.CodeAnalysis.CSharp;
+
+using NUnit.Framework;
+
+namespace ICSharpCode.Decompiler.Tests.Instrumentation
+{
+	[TestFixture]
+	public class DecompilerEventSourceTests
+	{
+		/// <summary>
+		/// Captures all events the "ICSharpCode.Decompiler" provider emits while the listener
+		/// is alive. Events are recorded process-wide, so assertions must filter by payload
+		/// (e.g. the decompiled type's full name) 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(DecompilerEventSource.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();
+			}
+
+			public List<string> EventNames => events.Select(e => e.EventName).Distinct().ToList();
+		}
+
+		/// <summary>Sample decompilation input covering all member kinds.</summary>
+		class SampleDecompilationTarget
+		{
+			public int field;
+
+			public int Property { get; set; }
+
+			public event EventHandler? Event;
+
+			public int Method(int x)
+			{
+				if (x > 0)
+				{
+					Event?.Invoke(this, EventArgs.Empty);
+					return x + field;
+				}
+				return -x;
+			}
+		}
+
+		static CSharpDecompiler CreateDecompilerForTestAssembly(out PEFile module)
+		{
+			module = new PEFile(typeof(DecompilerEventSourceTests).Assembly.Location);
+			var resolver = new UniversalAssemblyResolver(module.FileName, false, module.Metadata.DetectTargetFrameworkId());
+			return new CSharpDecompiler(module, resolver, new DecompilerSettings());
+		}
+
+		static void DecompileSampleTarget()
+		{
+			var decompiler = CreateDecompilerForTestAssembly(out var module);
+			using (module)
+			{
+				decompiler.DecompileType(new FullTypeName(typeof(SampleDecompilationTarget).FullName));
+			}
+		}
+
+		[Test]
+		public void ManifestIsValid()
+		{
+			string manifest = EventSource.GenerateManifest(typeof(DecompilerEventSource), typeof(DecompilerEventSource).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 = DecompilerEventSource.Log;
+			log.DecompileTypeStart("T");
+			log.DecompileTypeStop("T");
+			log.DecompileMemberStart("T.M", 0x06000001, (int)DecompiledMemberKind.Method, 42);
+			log.DecompileMemberStop("T.M", 0x06000001, (int)DecompiledMemberKind.Method);
+			log.TypeSystemInitStart("module");
+			log.TypeSystemInitStop("module", 3);
+			log.AssemblyResolveStart("System.Runtime");
+			log.AssemblyResolveStop("System.Runtime", "/path/System.Runtime.dll", true);
+			log.ProjectDecompilationStart("module");
+			log.ProjectDecompilationStop("module", 10, 2);
+			log.ProjectFileStart("File.cs", 5);
+			log.ProjectFileStop("File.cs");
+			log.ILTransformExecuted("ILInlining", 0x06000001, 0.5);
+			log.AstTransformExecuted("PatternStatementTransform", 1.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 = {
+				"DecompileTypeStart", "DecompileTypeStop",
+				"DecompileMemberStart", "DecompileMemberStop",
+				"TypeSystemInitStart", "TypeSystemInitStop",
+				"AssemblyResolveStart", "AssemblyResolveStop",
+				"ProjectDecompilationStart", "ProjectDecompilationStop",
+				"ProjectFileStart", "ProjectFileStop",
+				"ILTransformExecuted", "AstTransformExecuted",
+			};
+			foreach (string eventName in expected)
+			{
+				Assert.That(listener.EventsNamed(eventName), Has.Count.EqualTo(1), eventName);
+			}
+		}
+
+		[Test]
+		public void DecompilingTypeEmitsPairedStartStopEvents()
+		{
+			using var listener = new RecordingListener(EventLevel.Informational, DecompilerEventSource.Keywords.Decompilation);
+			DecompileSampleTarget();
+
+			var typeStarts = listener.EventsNamed("DecompileTypeStart")
+				.Where(p => ((string?)p["fullName"])?.Contains(nameof(SampleDecompilationTarget)) == true).ToList();
+			var typeStops = listener.EventsNamed("DecompileTypeStop")
+				.Where(p => ((string?)p["fullName"])?.Contains(nameof(SampleDecompilationTarget)) == true).ToList();
+			Assert.That(typeStarts, Has.Count.EqualTo(1));
+			Assert.That(typeStops, Has.Count.EqualTo(1));
+
+			var memberStarts = listener.EventsNamed("DecompileMemberStart")
+				.Where(p => ((string?)p["fullName"])?.Contains(nameof(SampleDecompilationTarget)) == true).ToList();
+			var memberStops = listener.EventsNamed("DecompileMemberStop")
+				.Where(p => ((string?)p["fullName"])?.Contains(nameof(SampleDecompilationTarget)) == true).ToList();
+			Assert.That(memberStarts, Is.Not.Empty);
+			Assert.That(memberStops, Has.Count.EqualTo(memberStarts.Count));
+
+			var kinds = memberStarts.Select(p => (int)p["memberKind"]!).Distinct().ToList();
+			Assert.That(kinds, Is.SubsetOf(new[] {
+				(int)DecompiledMemberKind.Method,
+				(int)DecompiledMemberKind.Field,
+				(int)DecompiledMemberKind.Property,
+				(int)DecompiledMemberKind.Event,
+			}));
+			// The sample type has at least one of each member kind.
+			Assert.That(kinds, Has.Count.EqualTo(4));
+			Assert.That(memberStarts.Select(p => (int)p["metadataToken"]!), Has.All.Not.EqualTo(0));
+
+			var methodStarts = memberStarts.Where(p => (int)p["memberKind"]! == (int)DecompiledMemberKind.Method).ToList();
+			Assert.That(methodStarts.Select(p => (int)p["ilBodySize"]!), Has.Some.GreaterThan(0));
+
+			// Per-transform events require the Transforms keyword at Verbose level.
+			Assert.That(listener.EventsNamed("ILTransformExecuted"), Is.Empty);
+			Assert.That(listener.EventsNamed("AstTransformExecuted"), Is.Empty);
+		}
+
+		[Test]
+		public void CreatingTypeSystemEmitsTypeSystemAndResolveEvents()
+		{
+			using var listener = new RecordingListener(EventLevel.Informational,
+				DecompilerEventSource.Keywords.TypeSystem | DecompilerEventSource.Keywords.AssemblyResolver);
+			using var module = new PEFile(typeof(DecompilerEventSourceTests).Assembly.Location);
+			var resolver = new UniversalAssemblyResolver(module.FileName, false, module.Metadata.DetectTargetFrameworkId());
+			_ = new DecompilerTypeSystem(module, resolver);
+
+			// Other fixtures may build type systems concurrently (events are process-wide),
+			// so assert presence rather than exact global counts.
+			var initStarts = listener.EventsNamed("TypeSystemInitStart")
+				.Where(p => (string?)p["moduleName"] == module.Name).ToList();
+			var initStops = listener.EventsNamed("TypeSystemInitStop")
+				.Where(p => (string?)p["moduleName"] == module.Name).ToList();
+			Assert.That(initStarts, Is.Not.Empty);
+			Assert.That(initStops, Is.Not.Empty);
+			Assert.That(initStops.Select(p => (int)p["referencedAssembliesResolved"]!), Has.Some.GreaterThan(0));
+
+			var resolveStarts = listener.EventsNamed("AssemblyResolveStart")
+				.Where(p => ((string?)p["referenceName"])?.StartsWith("System.Runtime,", StringComparison.Ordinal) == true).ToList();
+			var resolveStops = listener.EventsNamed("AssemblyResolveStop")
+				.Where(p => ((string?)p["referenceName"])?.StartsWith("System.Runtime,", StringComparison.Ordinal) == true).ToList();
+			Assert.That(resolveStarts, Is.Not.Empty);
+			Assert.That(resolveStops, Is.Not.Empty);
+			Assert.That(resolveStops.Where(p => (bool)p["success"]! && !string.IsNullOrEmpty((string?)p["resolvedPath"])),
+				Is.Not.Empty, "System.Runtime must resolve to a file on disk");
+		}
+
+		[Test]
+		public void WholeProjectDecompilationEmitsProjectEvents()
+		{
+			string tempDir = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName());
+			Directory.CreateDirectory(tempDir);
+			try
+			{
+				string dllPath = Path.Combine(tempDir, "TraceTestAssembly.dll");
+				CompileTinyAssembly(dllPath);
+				string projectDir = Path.Combine(tempDir, "project");
+				Directory.CreateDirectory(projectDir);
+
+				using var listener = new RecordingListener(EventLevel.Informational, DecompilerEventSource.Keywords.ProjectDecompiler);
+				using (var module = new PEFile(dllPath))
+				{
+					var resolver = new UniversalAssemblyResolver(dllPath, false, module.Metadata.DetectTargetFrameworkId());
+					new WholeProjectDecompiler(resolver).DecompileProject(module, projectDir);
+				}
+
+				var runStarts = listener.EventsNamed("ProjectDecompilationStart")
+					.Where(p => ((string?)p["moduleName"])?.Contains("TraceTestAssembly") == true).ToList();
+				var runStops = listener.EventsNamed("ProjectDecompilationStop")
+					.Where(p => ((string?)p["moduleName"])?.Contains("TraceTestAssembly") == true).ToList();
+				Assert.That(runStarts, Has.Count.EqualTo(1));
+				Assert.That(runStops, Has.Count.EqualTo(1));
+				Assert.That((int)runStops[0]["codeFileCount"]!, Is.GreaterThanOrEqualTo(2));
+
+				string[] expectedFiles = { "TraceTestClassA.cs", "TraceTestClassB.cs" };
+				var fileStarts = listener.EventsNamed("ProjectFileStart")
+					.Where(p => expectedFiles.Contains((string?)p["fileName"])).ToList();
+				var fileStops = listener.EventsNamed("ProjectFileStop")
+					.Where(p => expectedFiles.Contains((string?)p["fileName"])).ToList();
+				Assert.That(fileStarts, Has.Count.EqualTo(2));
+				Assert.That(fileStops, Has.Count.EqualTo(2));
+				Assert.That(fileStarts.Select(p => (int)p["typeCount"]!), Has.All.EqualTo(1));
+			}
+			finally
+			{
+				Directory.Delete(tempDir, recursive: true);
+			}
+		}
+
+		static void CompileTinyAssembly(string dllPath)
+		{
+			const string source = @"
+public class TraceTestClassA { public int M(int x) { return x + 1; } }
+public class TraceTestClassB { public string N() { return ""b""; } }";
+			string runtimeDir = Path.GetDirectoryName(typeof(object).Assembly.Location)!;
+			var compilation = CSharpCompilation.Create("TraceTestAssembly",
+				new[] { CSharpSyntaxTree.ParseText(source) },
+				new[] {
+					MetadataReference.CreateFromFile(typeof(object).Assembly.Location),
+					MetadataReference.CreateFromFile(Path.Combine(runtimeDir, "System.Runtime.dll")),
+				},
+				new CSharpCompilationOptions(OutputKind.DynamicallyLinkedLibrary));
+			var result = compilation.Emit(dllPath);
+			Assert.That(result.Success, Is.True,
+				string.Join(Environment.NewLine, result.Diagnostics.Select(d => d.ToString())));
+		}
+
+		[Test]
+		public void TransformsKeywordEmitsPerTransformEvents()
+		{
+			using var listener = new RecordingListener(EventLevel.Verbose, DecompilerEventSource.Keywords.Transforms);
+			DecompileSampleTarget();
+
+			var ilTransforms = listener.EventsNamed("ILTransformExecuted");
+			Assert.That(ilTransforms, Is.Not.Empty);
+			Assert.That(ilTransforms.Select(p => (string?)p["transformName"]), Has.All.Not.Empty);
+			Assert.That(ilTransforms.Select(p => (string?)p["transformName"]), Has.Some.EqualTo("ILInlining"));
+			Assert.That(ilTransforms.Select(p => (int)p["methodToken"]!), Has.All.Not.EqualTo(0));
+			Assert.That(ilTransforms.Select(p => (double)p["elapsedMs"]!), Has.All.GreaterThanOrEqualTo(0.0));
+
+			var astTransforms = listener.EventsNamed("AstTransformExecuted");
+			Assert.That(astTransforms, Is.Not.Empty);
+			Assert.That(astTransforms.Select(p => (string?)p["transformName"]), Has.Some.EqualTo("PatternStatementTransform"));
+
+			// The Transforms keyword alone must not enable the per-type/per-member events.
+			Assert.That(listener.EventsNamed("DecompileTypeStart"), Is.Empty);
+			Assert.That(listener.EventsNamed("DecompileMemberStart"), Is.Empty);
+		}
+	}
+}

ICSharpCode.Decompiler/CSharp/CSharpDecompiler.cs

@@ -40,6 +40,7 @@ using ICSharpCode.Decompiler.Documentation;
 using ICSharpCode.Decompiler.IL;
 using ICSharpCode.Decompiler.IL.ControlFlow;
 using ICSharpCode.Decompiler.IL.Transforms;
+using ICSharpCode.Decompiler.Instrumentation;
 using ICSharpCode.Decompiler.Metadata;
 using ICSharpCode.Decompiler.Semantics;
 using ICSharpCode.Decompiler.TypeSystem;
@@ -760,13 +761,17 @@ namespace ICSharpCode.Decompiler.CSharp
 			// The tree handed to the pipeline must already be well-formed; check it once up front so a
 			// malformed builder output is caught here rather than blamed on the first transform (DEBUG only).
 			rootNode.CheckInvariant();
+			bool traceTransforms = DecompilerEventSource.Log.IsTransformTracingEnabled();
 			try
 			{
 				foreach (var transform in astTransforms)
 				{
 					CancellationToken.ThrowIfCancellationRequested();
 					context.StepStartGroup(transform.GetType().Name);
+					long traceStart = traceTransforms ? Stopwatch.GetTimestamp() : 0;
 					transform.Run(rootNode, context);
+					if (traceTransforms)
+						DecompilerEventSource.Log.AstTransformExecuted(transform, traceStart);
 					// Verify the slot structure survived the transform (DEBUG only); mirrors the IL
 					// pipeline's per-transform ILInstruction.CheckInvariant.
 					rootNode.CheckInvariant();
@@ -1621,7 +1626,7 @@ namespace ICSharpCode.Decompiler.CSharp
 		EntityDeclaration DoDecompile(ITypeDefinition typeDef, DecompileRun decompileRun, ITypeResolveContext decompilationContext, bool asExtension = false)
 		{
 			Debug.Assert(decompilationContext.CurrentTypeDefinition == typeDef);
-			var watch = System.Diagnostics.Stopwatch.StartNew();
+			DecompilerEventSource.Log.DecompileTypeStart(typeDef);
 			var entityMap = new MultiDictionary<IEntity, EntityDeclaration>();
 			var workList = new Queue<IEntity>();
 			TypeSystemAstBuilder typeSystemAstBuilder;
@@ -1804,8 +1809,7 @@ namespace ICSharpCode.Decompiler.CSharp
 			}
 			finally
 			{
-				watch.Stop();
-				Instrumentation.DecompilerEventSource.Log.DoDecompileTypeDefinition(typeDef.FullName, watch.ElapsedMilliseconds);
+				DecompilerEventSource.Log.DecompileTypeStop(typeDef);
 			}
 
 			// MemberIsHidden identifies event backing fields from the metadata name association
@@ -2014,7 +2018,7 @@ namespace ICSharpCode.Decompiler.CSharp
 		EntityDeclaration DoDecompile(IMethod method, DecompileRun decompileRun, ITypeResolveContext decompilationContext, ExtensionInfo? extensionInfo)
 		{
 			Debug.Assert(decompilationContext.CurrentMember == method);
-			var watch = System.Diagnostics.Stopwatch.StartNew();
+			DecompilerEventSource.Log.DecompileMemberStart(method, DecompiledMemberKind.Method);
 			try
 			{
 				var typeSystemAstBuilder = CreateAstBuilder(decompileRun.Settings);
@@ -2087,8 +2091,7 @@ namespace ICSharpCode.Decompiler.CSharp
 			}
 			finally
 			{
-				watch.Stop();
-				Instrumentation.DecompilerEventSource.Log.DoDecompileMethod(method.FullName, watch.ElapsedMilliseconds);
+				DecompilerEventSource.Log.DecompileMemberStop(method, DecompiledMemberKind.Method);
 			}
 		}
 
@@ -2359,7 +2362,7 @@ namespace ICSharpCode.Decompiler.CSharp
 		EntityDeclaration DoDecompile(IField field, DecompileRun decompileRun, ITypeResolveContext decompilationContext)
 		{
 			Debug.Assert(decompilationContext.CurrentMember == field);
-			var watch = System.Diagnostics.Stopwatch.StartNew();
+			DecompilerEventSource.Log.DecompileMemberStart(field, DecompiledMemberKind.Field);
 			try
 			{
 				var typeSystemAstBuilder = CreateAstBuilder(decompileRun.Settings);
@@ -2432,8 +2435,7 @@ namespace ICSharpCode.Decompiler.CSharp
 			}
 			finally
 			{
-				watch.Stop();
-				Instrumentation.DecompilerEventSource.Log.DoDecompileField(field.FullName, watch.ElapsedMilliseconds);
+				DecompilerEventSource.Log.DecompileMemberStop(field, DecompiledMemberKind.Field);
 			}
 		}
 
@@ -2457,7 +2459,7 @@ namespace ICSharpCode.Decompiler.CSharp
 		EntityDeclaration DoDecompile(IProperty property, DecompileRun decompileRun, ITypeResolveContext decompilationContext, ExtensionInfo? extensionInfo)
 		{
 			Debug.Assert(decompilationContext.CurrentMember == property);
-			var watch = System.Diagnostics.Stopwatch.StartNew();
+			DecompilerEventSource.Log.DecompileMemberStart(property, DecompiledMemberKind.Property);
 			try
 			{
 				var typeSystemAstBuilder = CreateAstBuilder(decompileRun.Settings);
@@ -2518,15 +2520,14 @@ namespace ICSharpCode.Decompiler.CSharp
 			}
 			finally
 			{
-				watch.Stop();
-				Instrumentation.DecompilerEventSource.Log.DoDecompileProperty(property.FullName, watch.ElapsedMilliseconds);
+				DecompilerEventSource.Log.DecompileMemberStop(property, DecompiledMemberKind.Property);
 			}
 		}
 
 		EntityDeclaration DoDecompile(IEvent ev, DecompileRun decompileRun, ITypeResolveContext decompilationContext)
 		{
 			Debug.Assert(decompilationContext.CurrentMember == ev);
-			var watch = System.Diagnostics.Stopwatch.StartNew();
+			DecompilerEventSource.Log.DecompileMemberStart(ev, DecompiledMemberKind.Event);
 			try
 			{
 				bool adderHasBody = ev.CanAdd && ev.AddAccessor!.HasBody;
@@ -2581,8 +2582,7 @@ namespace ICSharpCode.Decompiler.CSharp
 			}
 			finally
 			{
-				watch.Stop();
-				Instrumentation.DecompilerEventSource.Log.DoDecompileEvent(ev.FullName, watch.ElapsedMilliseconds);
+				DecompilerEventSource.Log.DecompileMemberStop(ev, DecompiledMemberKind.Event);
 			}
 		}
 

ICSharpCode.Decompiler/CSharp/ProjectDecompiler/WholeProjectDecompiler.cs

@@ -32,6 +32,7 @@ using ICSharpCode.Decompiler.CSharp.OutputVisitor;
 using ICSharpCode.Decompiler.CSharp.Syntax;
 using ICSharpCode.Decompiler.CSharp.Transforms;
 using ICSharpCode.Decompiler.DebugInfo;
+using ICSharpCode.Decompiler.Instrumentation;
 using ICSharpCode.Decompiler.Metadata;
 using ICSharpCode.Decompiler.Semantics;
 using ICSharpCode.Decompiler.Solution;
@@ -151,25 +152,36 @@ namespace ICSharpCode.Decompiler.CSharp.ProjectDecompiler
 			{
 				throw new InvalidOperationException("Must set TargetDirectory");
 			}
-			TargetDirectory = targetDirectory;
-			directories.Clear();
-			var resources = WriteResourceFilesInProject(file).ToList();
-			var files = WriteCodeFilesInProject(file, resources.SelectMany(r => r.PartialTypes ?? Enumerable.Empty<PartialTypeInfo>()).ToList(), cancellationToken).ToList();
-			files.AddRange(resources);
-			var module = file as PEFile;
-			if (module != null)
+			DecompilerEventSource.Log.ProjectDecompilationStart(file.Name);
+			int codeFileCount = 0, resourceFileCount = 0;
+			try
 			{
-				files.AddRange(WriteMiscellaneousFilesInProject(module));
+				TargetDirectory = targetDirectory;
+				directories.Clear();
+				var resources = WriteResourceFilesInProject(file).ToList();
+				resourceFileCount = resources.Count;
+				var files = WriteCodeFilesInProject(file, resources.SelectMany(r => r.PartialTypes ?? Enumerable.Empty<PartialTypeInfo>()).ToList(), cancellationToken).ToList();
+				codeFileCount = files.Count;
+				files.AddRange(resources);
+				var module = file as PEFile;
+				if (module != null)
+				{
+					files.AddRange(WriteMiscellaneousFilesInProject(module));
+				}
+				if (StrongNameKeyFile != null)
+				{
+					File.Copy(StrongNameKeyFile, Path.Combine(targetDirectory, Path.GetFileName(StrongNameKeyFile)), overwrite: true);
+				}
+
+				projectWriter.Write(projectFileWriter, this, files, file);
+
+				string platformName = module != null ? TargetServices.GetPlatformName(module) : "AnyCPU";
+				return new ProjectId(platformName, ProjectGuid, ProjectTypeGuids.CSharpWindows);
 			}
-			if (StrongNameKeyFile != null)
+			finally
 			{
-				File.Copy(StrongNameKeyFile, Path.Combine(targetDirectory, Path.GetFileName(StrongNameKeyFile)), overwrite: true);
+				DecompilerEventSource.Log.ProjectDecompilationStop(file.Name, codeFileCount, resourceFileCount);
 			}
-
-			projectWriter.Write(projectFileWriter, this, files, file);
-
-			string platformName = module != null ? TargetServices.GetPlatformName(module) : "AnyCPU";
-			return new ProjectId(platformName, ProjectGuid, ProjectTypeGuids.CSharpWindows);
 		}
 
 		#region WriteCodeFilesInProject
@@ -287,6 +299,8 @@ namespace ICSharpCode.Decompiler.CSharp.ProjectDecompiler
 						CancellationToken = cancellationToken
 					},
 					delegate (IGrouping<string, TypeDefinitionHandle> file) {
+						var declaredTypes = file.ToArray();
+						DecompilerEventSource.Log.ProjectFileStart(file.Key, declaredTypes.Length);
 						try
 						{
 							using var w = CreateFile(Path.Combine(TargetDirectory, file.Key));
@@ -298,7 +312,6 @@ namespace ICSharpCode.Decompiler.CSharp.ProjectDecompiler
 							}
 
 							decompiler.CancellationToken = cancellationToken;
-							var declaredTypes = file.ToArray();
 							var syntaxTree = decompiler.DecompileTypes(declaredTypes);
 
 							foreach (var node in syntaxTree.Descendants)
@@ -325,6 +338,10 @@ namespace ICSharpCode.Decompiler.CSharp.ProjectDecompiler
 						{
 							throw new DecompilerException(module, $"Error decompiling for '{file.Key}'", innerException);
 						}
+						finally
+						{
+							DecompilerEventSource.Log.ProjectFileStop(file.Key);
+						}
 						progress.Status = file.Key;
 						Interlocked.Increment(ref progress.UnitsCompleted);
 						progressReporter?.Report(progress);

ICSharpCode.Decompiler/IL/Instructions/ILFunction.cs

@@ -23,6 +23,7 @@ using System.Diagnostics;
 using System.Linq;
 
 using ICSharpCode.Decompiler.IL.Transforms;
+using ICSharpCode.Decompiler.Instrumentation;
 using ICSharpCode.Decompiler.TypeSystem;
 using ICSharpCode.Decompiler.Util;
 
@@ -401,6 +402,7 @@ namespace ICSharpCode.Decompiler.IL
 		public void RunTransforms(IEnumerable<IILTransform> transforms, ILTransformContext context)
 		{
 			this.CheckInvariant(ILPhase.Normal);
+			bool traceTransforms = DecompilerEventSource.Log.IsTransformTracingEnabled();
 			foreach (var transform in transforms)
 			{
 				context.CancellationToken.ThrowIfCancellationRequested();
@@ -412,7 +414,10 @@ namespace ICSharpCode.Decompiler.IL
 				{
 					context.StepStartGroup(transform.GetType().Name);
 				}
+				long traceStart = traceTransforms ? System.Diagnostics.Stopwatch.GetTimestamp() : 0;
 				transform.Run(this, context);
+				if (traceTransforms)
+					DecompilerEventSource.Log.ILTransformExecuted(transform, this, traceStart);
 				this.CheckInvariant(ILPhase.Normal);
 				context.StepEndGroup(keepIfEmpty: true);
 			}

ICSharpCode.Decompiler/Instrumentation/DecompilerEventSource.cs

@@ -1,14 +1,14 @@
 // Copyright (c) 2021 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
@@ -16,44 +16,260 @@
 // OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
 // DEALINGS IN THE SOFTWARE.
 
+#nullable enable
+
+using System;
+using System.Diagnostics;
 using System.Diagnostics.Tracing;
+using System.Reflection.Metadata;
+using System.Reflection.Metadata.Ecma335;
+
+using ICSharpCode.Decompiler.CSharp.Transforms;
+using ICSharpCode.Decompiler.IL;
+using ICSharpCode.Decompiler.IL.Transforms;
+using ICSharpCode.Decompiler.Metadata;
+using ICSharpCode.Decompiler.TypeSystem;
 
 namespace ICSharpCode.Decompiler.Instrumentation
 {
+	/// <summary>
+	/// Member kind reported in the DecompileMemberStart/Stop events.
+	/// </summary>
+	public enum DecompiledMemberKind
+	{
+		Method = 1,
+		Field = 2,
+		Property = 3,
+		Event = 4,
+	}
+
+	/// <summary>
+	/// Performance tracing for the decompilation pipeline.
+	///
+	/// 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-transform), which carry an explicit elapsedMs payload.
+	///
+	/// Call sites use the strongly-typed [NonEvent] overloads below, which check
+	/// IsEnabled() before computing any payload (FullName strings, IL body sizes) and
+	/// before the params-array marshaling of the underlying WriteEvent calls. This keeps
+	/// call sites free of guard clutter while tracing still costs only a branch when no
+	/// listener is attached. The [Event] methods define the wire format and are public
+	/// for tests.
+	/// </summary>
 	[EventSource(Name = "ICSharpCode.Decompiler")]
 	public sealed class DecompilerEventSource : EventSource
 	{
-		[Event(1, Level = EventLevel.Informational)]
-		public void DoDecompileEvent(string eventName, long elapsedMilliseconds)
+		public static class Keywords
 		{
-			WriteEvent(1, eventName, elapsedMilliseconds);
+			/// <summary>Per-type and per-member decompilation events.</summary>
+			public const EventKeywords Decompilation = (EventKeywords)0x1;
+			/// <summary>Type system construction.</summary>
+			public const EventKeywords TypeSystem = (EventKeywords)0x2;
+			/// <summary>Assembly reference resolution (directory probing, disk I/O).</summary>
+			public const EventKeywords AssemblyResolver = (EventKeywords)0x4;
+			/// <summary>Whole-project decompilation (per-run and per-file).</summary>
+			public const EventKeywords ProjectDecompiler = (EventKeywords)0x8;
+			/// <summary>Per-transform timing of the IL and AST pipelines (Verbose, high volume).</summary>
+			public const EventKeywords Transforms = (EventKeywords)0x10;
 		}
 
-		[Event(2, Level = EventLevel.Informational)]
-		public void DoDecompileProperty(string propertyName, long elapsedMilliseconds)
+		[Event(1, Level = EventLevel.Informational, Keywords = Keywords.Decompilation)]
+		public void DecompileTypeStart(string fullName)
 		{
-			WriteEvent(2, propertyName, elapsedMilliseconds);
+			WriteEvent(1, fullName);
 		}
 
-		[Event(3, Level = EventLevel.Informational)]
-		public void DoDecompileField(string fieldName, long elapsedMilliseconds)
+		[Event(2, Level = EventLevel.Informational, Keywords = Keywords.Decompilation)]
+		public void DecompileTypeStop(string fullName)
 		{
-			WriteEvent(3, fieldName, elapsedMilliseconds);
+			WriteEvent(2, fullName);
 		}
 
-		[Event(4, Level = EventLevel.Informational)]
-		public void DoDecompileTypeDefinition(string typeDefName, long elapsedMilliseconds)
+		/// <param name="fullName">Full name of the decompiled member.</param>
+		/// <param name="metadataToken">Metadata token of the member (int-encoded).</param>
+		/// <param name="memberKind">One of the <see cref="DecompiledMemberKind"/> values.</param>
+		/// <param name="ilBodySize">IL body size in bytes; 0 for members without a body.</param>
+		[Event(3, Level = EventLevel.Informational, Keywords = Keywords.Decompilation)]
+		public void DecompileMemberStart(string fullName, int metadataToken, int memberKind, int ilBodySize)
 		{
-			WriteEvent(4, typeDefName, elapsedMilliseconds);
+			WriteEvent(3, fullName, metadataToken, memberKind, ilBodySize);
 		}
 
-		[Event(5, Level = EventLevel.Informational)]
-		public void DoDecompileMethod(string methodName, long elapsedMilliseconds)
+		[Event(4, Level = EventLevel.Informational, Keywords = Keywords.Decompilation)]
+		public void DecompileMemberStop(string fullName, int metadataToken, int memberKind)
 		{
-			WriteEvent(5, methodName, elapsedMilliseconds);
+			WriteEvent(4, fullName, metadataToken, memberKind);
 		}
 
-		public static DecompilerEventSource Log = new DecompilerEventSource();
+		[Event(5, Level = EventLevel.Informational, Keywords = Keywords.TypeSystem)]
+		public void TypeSystemInitStart(string moduleName)
+		{
+			WriteEvent(5, moduleName);
+		}
+
+		[Event(6, Level = EventLevel.Informational, Keywords = Keywords.TypeSystem)]
+		public void TypeSystemInitStop(string moduleName, int referencedAssembliesResolved)
+		{
+			WriteEvent(6, moduleName, referencedAssembliesResolved);
+		}
+
+		[Event(7, Level = EventLevel.Informational, Keywords = Keywords.AssemblyResolver)]
+		public void AssemblyResolveStart(string referenceName)
+		{
+			WriteEvent(7, referenceName);
+		}
+
+		[Event(8, Level = EventLevel.Informational, Keywords = Keywords.AssemblyResolver)]
+		public void AssemblyResolveStop(string referenceName, string resolvedPath, bool success)
+		{
+			WriteEvent(8, referenceName, resolvedPath, success);
+		}
+
+		[Event(9, Level = EventLevel.Informational, Keywords = Keywords.ProjectDecompiler)]
+		public void ProjectDecompilationStart(string moduleName)
+		{
+			WriteEvent(9, moduleName);
+		}
+
+		[Event(10, Level = EventLevel.Informational, Keywords = Keywords.ProjectDecompiler)]
+		public void ProjectDecompilationStop(string moduleName, int codeFileCount, int resourceFileCount)
+		{
+			WriteEvent(10, moduleName, codeFileCount, resourceFileCount);
+		}
+
+		[Event(11, Level = EventLevel.Informational, Keywords = Keywords.ProjectDecompiler)]
+		public void ProjectFileStart(string fileName, int typeCount)
+		{
+			WriteEvent(11, fileName, typeCount);
+		}
+
+		[Event(12, Level = EventLevel.Informational, Keywords = Keywords.ProjectDecompiler)]
+		public void ProjectFileStop(string fileName)
+		{
+			WriteEvent(12, fileName);
+		}
+
+		[Event(13, Level = EventLevel.Verbose, Keywords = Keywords.Transforms)]
+		public void ILTransformExecuted(string transformName, int methodToken, double elapsedMs)
+		{
+			WriteEvent(13, transformName, methodToken, elapsedMs);
+		}
+
+		[Event(14, Level = EventLevel.Verbose, Keywords = Keywords.Transforms)]
+		public void AstTransformExecuted(string transformName, double elapsedMs)
+		{
+			WriteEvent(14, transformName, elapsedMs);
+		}
+
+		// Strongly-typed entry points for the instrumented code. Each one checks
+		// IsEnabled() before extracting the payload, so a disabled provider costs a
+		// single branch and zero allocations.
+
+		[NonEvent]
+		public void DecompileTypeStart(ITypeDefinition typeDef)
+		{
+			if (IsEnabled(EventLevel.Informational, Keywords.Decompilation))
+				DecompileTypeStart(typeDef.FullName);
+		}
+
+		[NonEvent]
+		public void DecompileTypeStop(ITypeDefinition typeDef)
+		{
+			if (IsEnabled(EventLevel.Informational, Keywords.Decompilation))
+				DecompileTypeStop(typeDef.FullName);
+		}
+
+		[NonEvent]
+		public void DecompileMemberStart(IEntity member, DecompiledMemberKind kind)
+		{
+			if (!IsEnabled(EventLevel.Informational, Keywords.Decompilation))
+				return;
+			int ilBodySize = 0;
+			if (kind == DecompiledMemberKind.Method && !member.MetadataToken.IsNil
+				&& member.ParentModule?.MetadataFile is { } file)
+			{
+				var methodDef = file.Metadata.GetMethodDefinition((MethodDefinitionHandle)member.MetadataToken);
+				if (methodDef.RelativeVirtualAddress != 0)
+				{
+					try
+					{
+						ilBodySize = file.GetMethodBody(methodDef.RelativeVirtualAddress).GetILReader().Length;
+					}
+					catch (BadImageFormatException)
+					{
+						// A corrupted body must not break tracing; the decompilation itself
+						// reports the problem when it reads the body.
+					}
+				}
+			}
+			DecompileMemberStart(member.FullName, MetadataTokens.GetToken(member.MetadataToken), (int)kind, ilBodySize);
+		}
+
+		[NonEvent]
+		public void DecompileMemberStop(IEntity member, DecompiledMemberKind kind)
+		{
+			if (IsEnabled(EventLevel.Informational, Keywords.Decompilation))
+				DecompileMemberStop(member.FullName, MetadataTokens.GetToken(member.MetadataToken), (int)kind);
+		}
+
+		[NonEvent]
+		public void AssemblyResolveStart(IAssemblyReference reference)
+		{
+			if (IsEnabled(EventLevel.Informational, Keywords.AssemblyResolver))
+				AssemblyResolveStart(reference.FullName);
+		}
+
+		[NonEvent]
+		public void AssemblyResolveStop(IAssemblyReference reference, string? resolvedPath)
+		{
+			if (IsEnabled(EventLevel.Informational, Keywords.AssemblyResolver))
+				AssemblyResolveStop(reference.FullName, resolvedPath ?? "", resolvedPath != null);
+		}
+
+		[NonEvent]
+		public void ILTransformExecuted(IILTransform transform, ILFunction function, long startTimestamp)
+		{
+			if (!IsEnabled(EventLevel.Verbose, Keywords.Transforms))
+				return;
+			string transformName = transform is BlockILTransform blockTransform
+				? blockTransform.ToString()
+				: transform.GetType().Name;
+			int methodToken = 0;
+			if (function.Method != null && !function.Method.MetadataToken.IsNil)
+				methodToken = MetadataTokens.GetToken(function.Method.MetadataToken);
+			ILTransformExecuted(transformName, methodToken, ElapsedMilliseconds(startTimestamp));
+		}
+
+		[NonEvent]
+		public void AstTransformExecuted(IAstTransform transform, long startTimestamp)
+		{
+			if (IsEnabled(EventLevel.Verbose, Keywords.Transforms))
+				AstTransformExecuted(transform.GetType().Name, ElapsedMilliseconds(startTimestamp));
+		}
+
+		/// <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 per-transform timestamps in the IL/AST pipeline loops: the loops
+		/// capture this once so they skip the Stopwatch.GetTimestamp() calls entirely (per
+		/// transform, per method) when no Verbose trace session is attached.
+		/// </summary>
+		[NonEvent]
+		public bool IsTransformTracingEnabled()
+		{
+			return IsEnabled(EventLevel.Verbose, Keywords.Transforms);
+		}
+
+		public static readonly DecompilerEventSource Log = new DecompilerEventSource();
 	}
-
 }

ICSharpCode.Decompiler/Metadata/UniversalAssemblyResolver.cs

@@ -272,6 +272,26 @@ namespace ICSharpCode.Decompiler.Metadata
 
 		public string? FindAssemblyFile(IAssemblyReference name)
 		{
+#if VSADDIN
+			// The VS add-in compiles this file without the Instrumentation sources.
+			return FindAssemblyFileCore(name);
+#else
+			Instrumentation.DecompilerEventSource.Log.AssemblyResolveStart(name);
+			string? resolvedFile = null;
+			try
+			{
+				resolvedFile = FindAssemblyFileCore(name);
+				return resolvedFile;
+			}
+			finally
+			{
+				Instrumentation.DecompilerEventSource.Log.AssemblyResolveStop(name, resolvedFile);
+			}
+#endif
+		}
+
+		string? FindAssemblyFileCore(IAssemblyReference name)
+		{
 			if (name.IsWindowsRuntime)
 			{
 				return FindWindowsMetadataFile(name);

ICSharpCode.Decompiler/TypeSystem/DecompilerTypeSystem.cs

@@ -21,6 +21,7 @@ using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
 
+using ICSharpCode.Decompiler.Instrumentation;
 using ICSharpCode.Decompiler.Metadata;
 using ICSharpCode.Decompiler.TypeSystem.Implementation;
 using ICSharpCode.Decompiler.Util;
@@ -273,6 +274,22 @@ namespace ICSharpCode.Decompiler.TypeSystem
 		};
 
 		private async Task InitializeAsync(MetadataFile mainModule, IAssemblyResolver assemblyResolver)
+		{
+			DecompilerEventSource.Log.TypeSystemInitStart(mainModule.Name);
+			int referencedAssembliesResolved = 0;
+			try
+			{
+				referencedAssembliesResolved = await InitializeCoreAsync(mainModule, assemblyResolver).ConfigureAwait(false);
+			}
+			finally
+			{
+				DecompilerEventSource.Log.TypeSystemInitStop(mainModule.Name, referencedAssembliesResolved);
+			}
+		}
+
+		/// <returns>The number of referenced assemblies (including transitively pulled-in
+		/// type-forwarder targets) that were successfully resolved.</returns>
+		private async Task<int> InitializeCoreAsync(MetadataFile mainModule, IAssemblyResolver assemblyResolver)
 		{
 			// Load referenced assemblies and type-forwarder references.
 			// This is necessary to make .NET Core/PCL binaries work better.
@@ -398,6 +415,7 @@ namespace ICSharpCode.Decompiler.TypeSystem
 				Init(mainModuleWithOptions, referencedAssembliesWithOptions);
 			}
 			this.mainModule = (MetadataModule)base.MainModule;
+			return referencedAssemblies.Count;
 
 			void AddToQueue(bool isAssembly, MetadataFile mainModule, object reference)
 			{