diff --git a/ICSharpCode.Decompiler.Tests/Instrumentation/DecompilerEventSourceTests.cs b/ICSharpCode.Decompiler.Tests/Instrumentation/DecompilerEventSourceTests.cs new file mode 100644 index 000000000..ae5d23f91 --- /dev/null +++ b/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 + { + /// + /// 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. + /// + sealed class RecordingListener : EventListener + { + readonly ConcurrentQueue<(string EventName, Dictionary Payload)> events = new(); + + public RecordingListener(EventLevel level, EventKeywords keywords) + { + EnableEvents(DecompilerEventSource.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(); + } + + public List EventNames => events.Select(e => e.EventName).Distinct().ToList(); + } + + /// Sample decompilation input covering all member kinds. + 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); + } + } +} diff --git a/ICSharpCode.Decompiler/CSharp/CSharpDecompiler.cs b/ICSharpCode.Decompiler/CSharp/CSharpDecompiler.cs index d9bf7d55e..3c5c61d41 100644 --- a/ICSharpCode.Decompiler/CSharp/CSharpDecompiler.cs +++ b/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(); var workList = new Queue(); 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); } } diff --git a/ICSharpCode.Decompiler/CSharp/ProjectDecompiler/WholeProjectDecompiler.cs b/ICSharpCode.Decompiler/CSharp/ProjectDecompiler/WholeProjectDecompiler.cs index f68fe5bc9..18061b9d6 100644 --- a/ICSharpCode.Decompiler/CSharp/ProjectDecompiler/WholeProjectDecompiler.cs +++ b/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()).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()).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 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); diff --git a/ICSharpCode.Decompiler/IL/Instructions/ILFunction.cs b/ICSharpCode.Decompiler/IL/Instructions/ILFunction.cs index 762d57e8a..a990f05c6 100644 --- a/ICSharpCode.Decompiler/IL/Instructions/ILFunction.cs +++ b/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 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); } diff --git a/ICSharpCode.Decompiler/Instrumentation/DecompilerEventSource.cs b/ICSharpCode.Decompiler/Instrumentation/DecompilerEventSource.cs index 180efbb92..5d8fad730 100644 --- a/ICSharpCode.Decompiler/Instrumentation/DecompilerEventSource.cs +++ b/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 { + /// + /// Member kind reported in the DecompileMemberStart/Stop events. + /// + public enum DecompiledMemberKind + { + Method = 1, + Field = 2, + Property = 3, + Event = 4, + } + + /// + /// 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. + /// [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); + /// Per-type and per-member decompilation events. + public const EventKeywords Decompilation = (EventKeywords)0x1; + /// Type system construction. + public const EventKeywords TypeSystem = (EventKeywords)0x2; + /// Assembly reference resolution (directory probing, disk I/O). + public const EventKeywords AssemblyResolver = (EventKeywords)0x4; + /// Whole-project decompilation (per-run and per-file). + public const EventKeywords ProjectDecompiler = (EventKeywords)0x8; + /// Per-transform timing of the IL and AST pipelines (Verbose, high volume). + 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) + /// Full name of the decompiled member. + /// Metadata token of the member (int-encoded). + /// One of the values. + /// IL body size in bytes; 0 for members without a body. + [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)); + } + + /// + /// Fractional milliseconds elapsed since a value. + /// + [NonEvent] + public static double ElapsedMilliseconds(long startTimestamp) + { + return (Stopwatch.GetTimestamp() - startTimestamp) * 1000.0 / Stopwatch.Frequency; + } + + /// + /// 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. + /// + [NonEvent] + public bool IsTransformTracingEnabled() + { + return IsEnabled(EventLevel.Verbose, Keywords.Transforms); + } + + public static readonly DecompilerEventSource Log = new DecompilerEventSource(); + } } diff --git a/ICSharpCode.Decompiler/Metadata/UniversalAssemblyResolver.cs b/ICSharpCode.Decompiler/Metadata/UniversalAssemblyResolver.cs index 891611c91..f72c95396 100644 --- a/ICSharpCode.Decompiler/Metadata/UniversalAssemblyResolver.cs +++ b/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); diff --git a/ICSharpCode.Decompiler/TypeSystem/DecompilerTypeSystem.cs b/ICSharpCode.Decompiler/TypeSystem/DecompilerTypeSystem.cs index ad0021608..38638457f 100644 --- a/ICSharpCode.Decompiler/TypeSystem/DecompilerTypeSystem.cs +++ b/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); + } + } + + /// The number of referenced assemblies (including transitively pulled-in + /// type-forwarder targets) that were successfully resolved. + private async Task 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) {