Opt-in startup phase logging

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

@@ -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;
 		}
 	}
-}
+}

ILSpy/AppEnv/AppLog.cs

@@ -24,23 +24,26 @@ using System.IO;
 namespace ILSpy.AppEnv
 {
 	/// <summary>
-	/// 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 <see cref="IsEnabled"/>
+	/// short-circuits before allocations.
 	/// <list type="bullet">
 	/// <item><see cref="Mark"/> / <see cref="Phase"/> — startup-timing helpers. Each line
 	/// gets a <c>[startup +Nms]</c> prefix where N is milliseconds since the first
-	/// <see cref="AppLog"/> reference (process-wide). The <see cref="Category.Startup"/>
-	/// category is default-enabled so these emit without any opt-in.</item>
+	/// <see cref="AppLog"/> reference (process-wide). Gated on the
+	/// <see cref="Category.Startup"/> category; emits nothing unless that category is
+	/// enabled.</item>
 	/// <item><see cref="Write(string, string)"/> / <see cref="Write(string, Func{string})"/> —
-	/// general category-based logging. Off by default; enable with the
-	/// <c>ILSPY_LOG=Cat1,Cat2</c> environment variable at process start, or
-	/// <see cref="Enable(string)"/> at runtime.</item>
+	/// general category-based logging. Use the <see cref="Func{T}"/> overload for
+	/// messages that interpolate non-trivial state — the factory is only invoked when
+	/// the category is enabled.</item>
 	/// </list>
-	/// Output goes to both <see cref="Debug.WriteLine(string)"/> (so DbgView / IDE
-	/// Debug Output captures it) and <c>%TEMP%\ilspy-avalonia.log</c> (truncated at
-	/// the first write of each process). Use the <see cref="Func{T}"/> overload of
-	/// <see cref="Write(string, Func{string})"/> 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 <c>ILSPY_LOG=Cat1,Cat2</c> environment variable at
+	/// process start (e.g. <c>ILSPY_LOG=Startup</c> to capture the startup timeline) or
+	/// call <see cref="Enable(string)"/> at runtime. Output goes to both
+	/// <see cref="Debug.WriteLine(string)"/> (so DbgView / IDE Debug Output captures it)
+	/// and <c>%TEMP%\ilspy-avalonia.log</c> (created on first emit; truncated at the
+	/// first write of each process).
 	/// </summary>
 	public static class AppLog
 	{
@@ -51,7 +54,7 @@ namespace ILSpy.AppEnv
 		/// </summary>
 		public static class Category
 		{
-			/// <summary>Process startup timeline. Default on so <see cref="Mark"/> / <see cref="Phase"/> emit without env-var opt-in.</summary>
+			/// <summary>Process startup timeline. Off by default — opt in with <c>ILSPY_LOG=Startup</c>.</summary>
 			public const string Startup = "Startup";
 
 			/// <summary>Dock chrome activity — view-recycling cache, layout save/load, drag/drop transitions.</summary>
@@ -152,9 +155,11 @@ namespace ILSpy.AppEnv
 		static ConcurrentDictionary<string, bool> LoadFromEnvironment()
 		{
 			var dict = new ConcurrentDictionary<string, bool>(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;

ILSpy/Commands/ToolPaneRegistry.cs

@@ -45,10 +45,18 @@ namespace ILSpy.Commands
 		public ToolPaneRegistry(
 			[ImportMany("ToolPane")] IEnumerable<ExportFactory<ToolPaneModel, ToolPaneMetadata>> 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<ToolPaneEntry> Panes { get; }

ILSpy/Languages/LanguageService.cs

@@ -51,15 +51,20 @@ namespace ILSpy.Languages
 		[ImportingConstructor]
 		public LanguageService([ImportMany] IEnumerable<Language> 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<Language> 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)

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)
 			{