From 23d8270d7387638660911efc9ca83f904d809718 Mon Sep 17 00:00:00 2001 From: Siegfried Pammer Date: Sat, 23 May 2026 10:17:15 +0200 Subject: [PATCH] Opt-in startup phase logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit AppLog.cs flips the Startup category from default-on to default-off: all categories now require an explicit opt-in via the ILSPY_LOG environment variable (e.g. ILSPY_LOG=Startup) or a runtime AppLog.Enable("Startup") call. Production launches stay silent and incur near-zero overhead — IsEnabled short-circuits before any allocation, the %TEMP%\ilspy-avalonia.log file is only created on first emitted line. Assisted-by: Claude:claude-opus-4-7:Claude Code --- ILSpy/AppEnv/AppComposition.cs | 12 ++- ILSpy/AppEnv/AppLog.cs | 37 ++++---- ILSpy/Commands/ToolPaneRegistry.cs | 16 +++- ILSpy/Languages/LanguageService.cs | 9 +- ILSpy/TextView/DecompilerTabPageModel.cs | 113 +++++++++++++---------- 5 files changed, 112 insertions(+), 75 deletions(-) diff --git a/ILSpy/AppEnv/AppComposition.cs b/ILSpy/AppEnv/AppComposition.cs index 86664b466..f78877e34 100644 --- a/ILSpy/AppEnv/AppComposition.cs +++ b/ILSpy/AppEnv/AppComposition.cs @@ -68,7 +68,8 @@ namespace ILSpy.AppEnv typeof(IAnalyzer).Assembly, typeof(AppComposition).Assembly, }; - assemblies.AddRange(LoadPlugins()); + using (AppLog.Phase("AppComposition.LoadPlugins")) + assemblies.AddRange(LoadPlugins()); composedAssemblies = assemblies; } @@ -82,9 +83,10 @@ namespace ILSpy.AppEnv throw new InvalidOperationException($"{nameof(RegisterPluginResolver)} must be called before {nameof(CreateContainer)}."); current?.Dispose(); - current = new ContainerConfiguration() - .WithAssemblies(composedAssemblies) - .CreateContainer(); + using (AppLog.Phase($"AppComposition.CreateContainer ({composedAssemblies.Count} assemblies)")) + current = new ContainerConfiguration() + .WithAssemblies(composedAssemblies) + .CreateContainer(); return current; } @@ -121,4 +123,4 @@ namespace ILSpy.AppEnv return File.Exists(path) ? context.LoadFromAssemblyPath(path) : null; } } -} +} \ No newline at end of file diff --git a/ILSpy/AppEnv/AppLog.cs b/ILSpy/AppEnv/AppLog.cs index 2e1405e59..1dc39827a 100644 --- a/ILSpy/AppEnv/AppLog.cs +++ b/ILSpy/AppEnv/AppLog.cs @@ -24,23 +24,26 @@ using System.IO; namespace ILSpy.AppEnv { /// - /// Categorized diagnostic log. Two surfaces: + /// Categorized diagnostic log. All categories are off by default; production runs + /// incur near-zero cost from existing call sites because + /// short-circuits before allocations. /// /// / — startup-timing helpers. Each line /// gets a [startup +Nms] prefix where N is milliseconds since the first - /// reference (process-wide). The - /// category is default-enabled so these emit without any opt-in. + /// reference (process-wide). Gated on the + /// category; emits nothing unless that category is + /// enabled. /// / — - /// general category-based logging. Off by default; enable with the - /// ILSPY_LOG=Cat1,Cat2 environment variable at process start, or - /// at runtime. + /// general category-based logging. Use the overload for + /// messages that interpolate non-trivial state — the factory is only invoked when + /// the category is enabled. /// - /// Output goes to both (so DbgView / IDE - /// Debug Output captures it) and %TEMP%\ilspy-avalonia.log (truncated at - /// the first write of each process). Use the overload of - /// for messages that interpolate non- - /// trivial state — the factory is only invoked when the category is enabled, - /// keeping the call site zero-cost when off. + /// Enable categories with the ILSPY_LOG=Cat1,Cat2 environment variable at + /// process start (e.g. ILSPY_LOG=Startup to capture the startup timeline) or + /// call at runtime. Output goes to both + /// (so DbgView / IDE Debug Output captures it) + /// and %TEMP%\ilspy-avalonia.log (created on first emit; truncated at the + /// first write of each process). /// public static class AppLog { @@ -51,7 +54,7 @@ namespace ILSpy.AppEnv /// public static class Category { - /// Process startup timeline. Default on so / emit without env-var opt-in. + /// Process startup timeline. Off by default — opt in with ILSPY_LOG=Startup. public const string Startup = "Startup"; /// Dock chrome activity — view-recycling cache, layout save/load, drag/drop transitions. @@ -152,9 +155,11 @@ namespace ILSpy.AppEnv static ConcurrentDictionary LoadFromEnvironment() { var dict = new ConcurrentDictionary(StringComparer.OrdinalIgnoreCase); - // Startup category is default-on so the existing pattern of unconditional - // Mark/Phase calls in the startup path keeps working without env-var setup. - dict[Category.Startup] = true; + // All categories default off; production runs incur zero cost from the existing + // Mark/Phase call sites because IsEnabled short-circuits before any allocation. + // Opt in via ILSPY_LOG=Startup,Docking,... at process launch, or call + // AppLog.Enable("Startup") at runtime. The %TEMP%\ilspy-avalonia.log file is + // only created on the first emitted line. var env = Environment.GetEnvironmentVariable("ILSPY_LOG"); if (string.IsNullOrWhiteSpace(env)) return dict; diff --git a/ILSpy/Commands/ToolPaneRegistry.cs b/ILSpy/Commands/ToolPaneRegistry.cs index 0fc7dfcd2..3e22ac11a 100644 --- a/ILSpy/Commands/ToolPaneRegistry.cs +++ b/ILSpy/Commands/ToolPaneRegistry.cs @@ -45,10 +45,18 @@ namespace ILSpy.Commands public ToolPaneRegistry( [ImportMany("ToolPane")] IEnumerable> panes) { - Panes = panes - .OrderBy(p => p.Metadata.Order) - .Select(p => new ToolPaneEntry(p.CreateExport().Value, p.Metadata)) - .ToArray(); + using var _ = ILSpy.AppEnv.AppLog.Phase("ToolPaneRegistry ctor (materialise tool panes)"); + var ordered = panes.OrderBy(p => p.Metadata.Order).ToArray(); + var entries = new ToolPaneEntry[ordered.Length]; + for (int i = 0; i < ordered.Length; i++) + { + var factory = ordered[i]; + var id = factory.Metadata.ContentId ?? $"#{i}"; + using (ILSpy.AppEnv.AppLog.Phase($"ToolPane materialise: {id}")) + entries[i] = new ToolPaneEntry(factory.CreateExport().Value, factory.Metadata); + } + Panes = entries; + ILSpy.AppEnv.AppLog.Mark($"ToolPaneRegistry: {Panes.Count} panes resolved"); } public IReadOnlyList Panes { get; } diff --git a/ILSpy/Languages/LanguageService.cs b/ILSpy/Languages/LanguageService.cs index 7951a6e2a..5a333b21d 100644 --- a/ILSpy/Languages/LanguageService.cs +++ b/ILSpy/Languages/LanguageService.cs @@ -51,15 +51,20 @@ namespace ILSpy.Languages [ImportingConstructor] public LanguageService([ImportMany] IEnumerable languages, SettingsService settingsService) { + using var _ = ILSpy.AppEnv.AppLog.Phase("LanguageService ctor (enumerate [ImportMany] Language exports)"); this.settingsService = settingsService; - var ordered = languages.OrderBy(l => l.Name).ToList(); + List ordered; + using (ILSpy.AppEnv.AppLog.Phase("LanguageService: materialise languages.OrderBy")) + ordered = languages.OrderBy(l => l.Name).ToList(); #if DEBUG // Under DEBUG, append one C# language per AST transform step so the dropdown // surfaces the decompiler's intermediate output. Mirrors WPF's LanguageService — // the variants aren't [Export]-ed because they're factory-built from the live // CSharpDecompiler.GetAstTransforms() list, which only the static helper knows. - ordered.AddRange(CSharpLanguage.GetDebugLanguages()); + using (ILSpy.AppEnv.AppLog.Phase("LanguageService: CSharpLanguage.GetDebugLanguages()")) + ordered.AddRange(CSharpLanguage.GetDebugLanguages()); #endif + ILSpy.AppEnv.AppLog.Mark($"LanguageService: {ordered.Count} languages resolved"); Languages = ordered; var saved = settingsService.SessionSettings.ActiveLanguageName; currentLanguage = Languages.FirstOrDefault(l => l.Name == saved) diff --git a/ILSpy/TextView/DecompilerTabPageModel.cs b/ILSpy/TextView/DecompilerTabPageModel.cs index c75345041..b688a3da4 100644 --- a/ILSpy/TextView/DecompilerTabPageModel.cs +++ b/ILSpy/TextView/DecompilerTabPageModel.cs @@ -348,8 +348,17 @@ namespace ILSpy.TextView }, TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously); } + // Process-wide counter so the AppLog markers can distinguish "first decompile after + // boot" (carries the JIT / pipeline-init cold cost) from subsequent runs. Incremented + // at the top of every DecompileAsync invocation including the empty-node short-circuit + // path — that way a no-op restore still bumps the count and the next real decompile is + // labelled #2 rather than #1. + static int decompileInvocationCount; + async Task DecompileAsync() { + var callNumber = System.Threading.Interlocked.Increment(ref decompileInvocationCount); + using var _phase = ILSpy.AppEnv.AppLog.Phase($"DecompileAsync #{callNumber}"); activeCts?.Cancel(); var cts = activeCts = new CancellationTokenSource(); var nodes = currentNodes; @@ -395,48 +404,54 @@ namespace ILSpy.TextView var isDebug = pendingIsDebug; pendingStepLimit = int.MaxValue; pendingIsDebug = false; - var (output, _) = await Task.Run(() => { - var output = new AvaloniaEditTextOutput(); - var options = decompilerSettings != null - ? new DecompilationOptions(decompilerSettings) { - CancellationToken = cts.Token, - StepLimit = stepLimit, - IsDebug = isDebug, + AvaloniaEditTextOutput output; + using (ILSpy.AppEnv.AppLog.Phase($"DecompileAsync #{callNumber}: Task.Run decompile body ({nodes.Count} node(s), language={language.Name})")) + { + (output, _) = await Task.Run(() => { + var output = new AvaloniaEditTextOutput(); + var options = decompilerSettings != null + ? new DecompilationOptions(decompilerSettings) { + CancellationToken = cts.Token, + StepLimit = stepLimit, + IsDebug = isDebug, + } + : new DecompilationOptions { + CancellationToken = cts.Token, + StepLimit = stepLimit, + IsDebug = isDebug, + }; + try + { + for (int i = 0; i < nodes.Count; i++) + { + if (cts.Token.IsCancellationRequested) + break; + if (i > 0) + output.WriteLine(); + nodes[i].Decompile(language, output, options); + } } - : new DecompilationOptions { - CancellationToken = cts.Token, - StepLimit = stepLimit, - IsDebug = isDebug, - }; - try - { - for (int i = 0; i < nodes.Count; i++) + catch (OperationCanceledException) { - if (cts.Token.IsCancellationRequested) - break; - if (i > 0) - output.WriteLine(); - nodes[i].Decompile(language, output, options); + // expected on cancel — just return whatever we got } - } - catch (OperationCanceledException) - { - // expected on cancel — just return whatever we got - } - catch (Exception ex) - { - output.WriteLine(); - output.WriteLine("/* Decompilation failed:"); - output.WriteLine(ex.ToString()); - output.WriteLine("*/"); - } - return (output, cts.Token); - }, cts.Token).ConfigureAwait(true); + catch (Exception ex) + { + output.WriteLine(); + output.WriteLine("/* Decompilation failed:"); + output.WriteLine(ex.ToString()); + output.WriteLine("*/"); + } + return (output, cts.Token); + }, cts.Token).ConfigureAwait(true); + } if (cts.Token.IsCancellationRequested) return; - var rendered = output.GetText(); + string rendered; + using (ILSpy.AppEnv.AppLog.Phase($"DecompileAsync #{callNumber}: collect output (GetText + collateral)")) + rendered = output.GetText(); var model = output.HighlightingModel; var collectedFoldings = output.Foldings; var collectedReferences = output.References; @@ -445,19 +460,21 @@ namespace ILSpy.TextView // Resource nodes (XML/XAML/…) override the highlighter so their content reads as // the embedded format, not as the active language. var effectiveSyntaxExtension = output.SyntaxExtensionOverride ?? newSyntaxExtension; - await Dispatcher.UIThread.InvokeAsync(() => { - // Re-read Text now (instead of capturing it before decompile started) — for - // freshly-opened assemblies, Text only has the rich "(version, tfm)" form - // after the load completes during decompile. - Title = ComposeBaseTitle(); - SyntaxExtension = effectiveSyntaxExtension; - HighlightingModel = model; - Foldings = collectedFoldings; - References = collectedReferences; - DefinitionLookup = collectedLookup; - UIElements = collectedUIElements; - Text = rendered; - }); + ILSpy.AppEnv.AppLog.Mark($"DecompileAsync #{callNumber}: {rendered.Length} chars, {(collectedFoldings?.Count ?? 0)} foldings, {(collectedReferences?.Count ?? 0)} refs"); + using (ILSpy.AppEnv.AppLog.Phase($"DecompileAsync #{callNumber}: Dispatcher.InvokeAsync (apply Text + props, triggers ApplyDocument)")) + await Dispatcher.UIThread.InvokeAsync(() => { + // Re-read Text now (instead of capturing it before decompile started) — for + // freshly-opened assemblies, Text only has the rich "(version, tfm)" form + // after the load completes during decompile. + Title = ComposeBaseTitle(); + SyntaxExtension = effectiveSyntaxExtension; + HighlightingModel = model; + Foldings = collectedFoldings; + References = collectedReferences; + DefinitionLookup = collectedLookup; + UIElements = collectedUIElements; + Text = rendered; + }); } catch (OperationCanceledException) {