From fd4244ede74a41c082ad0795cd2e194fb52ef744 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ji=C5=99=C3=AD=20Pol=C3=A1=C5=A1ek?= Date: Mon, 17 Aug 2026 19:30:35 +0200 Subject: [PATCH] Add CmdPal icon loading observer foundation --- .../Helpers/AdaptiveCacheRemovalReason.cs | 14 + .../Helpers/AdaptiveCache`2.cs | 28 +- .../Helpers/Icons/CachedIconSourceProvider.cs | 29 +- .../IconDispatcherMaterializationKind.cs | 17 + .../Icons/IconDispatcherUiSliceKind.cs | 12 + .../Helpers/Icons/IconLoadDiagnostics.cs | 110 ++- .../Icons/IconLoadDiagnosticsSession.cs | 715 +++++++++++++++++- .../Helpers/Icons/IconLoadEventSource.cs | 279 ++++++- .../Helpers/Icons/IconLoadMeasurement.cs | 98 ++- .../Helpers/Icons/IconLoaderService.cs | 100 ++- .../Microsoft.CmdPal.UI.csproj | 1 + .../AdaptiveCacheTests.cs | 41 + .../IconLoadDiagnosticsTests.cs | 182 ++++- .../IconLoadEventSourceTests.cs | 102 +++ .../Microsoft.CmdPal.UI.UnitTests.csproj | 4 + 15 files changed, 1690 insertions(+), 42 deletions(-) create mode 100644 src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCacheRemovalReason.cs create mode 100644 src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherMaterializationKind.cs create mode 100644 src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherUiSliceKind.cs create mode 100644 src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadEventSourceTests.cs diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCacheRemovalReason.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCacheRemovalReason.cs new file mode 100644 index 0000000000..d2db60689c --- /dev/null +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCacheRemovalReason.cs @@ -0,0 +1,14 @@ +// Copyright (c) Microsoft Corporation +// The Microsoft Corporation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.CmdPal.UI.Helpers; + +internal enum AdaptiveCacheRemovalReason +{ + Explicit, + Clear, + Capacity, + LowScore, + Replaced, +} diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCache`2.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCache`2.cs index 706cf2b706..1dd59a387c 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCache`2.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/AdaptiveCache`2.cs @@ -19,6 +19,7 @@ internal sealed class AdaptiveCache private readonly int _capacity; private readonly double _decayFactor; private readonly TimeSpan _decayInterval; + private readonly Action? _removalCallback; private readonly ConcurrentDictionary _map; private readonly ConcurrentStack _pool = []; @@ -33,11 +34,16 @@ internal sealed class AdaptiveCache internal int ApproximateCount => Volatile.Read(ref _entryCount); - public AdaptiveCache(int capacity = 384, TimeSpan? decayInterval = null, double decayFactor = 0.5) + public AdaptiveCache( + int capacity = 384, + TimeSpan? decayInterval = null, + double decayFactor = 0.5, + Action? removalCallback = null) { _capacity = capacity; _decayInterval = decayInterval ?? TimeSpan.FromMinutes(5); _decayFactor = decayFactor; + _removalCallback = removalCallback; _map = new ConcurrentDictionary(Environment.ProcessorCount, capacity); _maintenanceCallback = static state => @@ -115,6 +121,12 @@ internal sealed class AdaptiveCache if (_map.TryGetValue(key, out var existing)) { existing.Update(tick); + _removalCallback?.Invoke( + key, + existing.Value, + AdaptiveCacheRemovalReason.Replaced, + ApproximateCount, + _capacity); existing.SetValue(value); return; } @@ -142,11 +154,14 @@ internal sealed class AdaptiveCache } } - public bool TryRemove(TKey key) + public bool TryRemove(TKey key) => TryRemove(key, AdaptiveCacheRemovalReason.Explicit); + + private bool TryRemove(TKey key, AdaptiveCacheRemovalReason reason) { if (_map.TryRemove(key, out var evicted)) { Interlocked.Decrement(ref _entryCount); + _removalCallback?.Invoke(key, evicted.Value, reason, ApproximateCount, _capacity); evicted.Clear(); _pool.Push(evicted); return true; @@ -161,7 +176,7 @@ internal sealed class AdaptiveCache // while Keys snapshots under every stripe lock. foreach (var (key, _) in _map) { - TryRemove(key); + TryRemove(key, AdaptiveCacheRemovalReason.Clear); } Interlocked.Exchange(ref _currentTick, 0); @@ -200,9 +215,12 @@ internal sealed class AdaptiveCache var score = CalculateScore(entry, currentTick); - if (score < 0.1 || ApproximateCount > _capacity) + var overCapacity = ApproximateCount > _capacity; + if (score < 0.1 || overCapacity) { - TryRemove(key); + TryRemove( + key, + overCapacity ? AdaptiveCacheRemovalReason.Capacity : AdaptiveCacheRemovalReason.LowScore); } } } diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/CachedIconSourceProvider.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/CachedIconSourceProvider.cs index 1a57a5afe4..118870b5c7 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/CachedIconSourceProvider.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/CachedIconSourceProvider.cs @@ -15,13 +15,18 @@ internal sealed class CachedIconSourceProvider : IIconSourceProvider private readonly AdaptiveCache> _cache; private readonly ConcurrentDictionary> _inFlight = new(); private readonly Size _iconSize; + private readonly int _cacheSize; private readonly IIconLoaderService _loader; public CachedIconSourceProvider(IIconLoaderService loader, Size iconSize, int cacheSize) { _loader = loader; _iconSize = iconSize; - _cache = new AdaptiveCache>(cacheSize, TimeSpan.FromMinutes(60)); + _cacheSize = cacheSize; + _cache = new AdaptiveCache>( + cacheSize, + TimeSpan.FromMinutes(60), + removalCallback: OnCacheEntryRemoved); } public CachedIconSourceProvider(IIconLoaderService loader, int iconSize, int cacheSize) @@ -35,10 +40,12 @@ internal sealed class CachedIconSourceProvider : IIconSourceProvider if (_cache.TryGet(key, out var existingTask)) { + IconLoadDiagnostics.RecordCacheLookup(_iconSize, _cacheSize, hit: true); diagnostics.RecordProviderResolution(IconProviderResolution.CacheHit, existingTask); return existingTask; } + IconLoadDiagnostics.RecordCacheLookup(_iconSize, _cacheSize, hit: false); return GetOrCreateSlowPath(key, icon, scale, diagnostics); } @@ -68,6 +75,10 @@ internal sealed class CachedIconSourceProvider : IIconSourceProvider if (completed.IsCompletedSuccessfully) { _cache.Add(key, completed); + IconLoadDiagnostics.RecordCacheEntryAdded( + _iconSize, + _cacheSize, + _cache.ApproximateCount); } } finally @@ -114,6 +125,22 @@ internal sealed class CachedIconSourceProvider : IIconSourceProvider return task; } + private void OnCacheEntryRemoved( + IconCacheKey key, + Task task, + AdaptiveCacheRemovalReason reason, + int remainingCount, + int capacity) + { + _ = key; + _ = task; + IconLoadDiagnostics.RecordCacheEntryRemoved( + _iconSize, + capacity, + remainingCount, + reason); + } + private readonly struct IconCacheKey : IEquatable { private readonly string? _icon; diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherMaterializationKind.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherMaterializationKind.cs new file mode 100644 index 0000000000..ee47dd9c2f --- /dev/null +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherMaterializationKind.cs @@ -0,0 +1,17 @@ +// Copyright (c) Microsoft Corporation +// The Microsoft Corporation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.CmdPal.UI.Helpers; + +internal enum IconDispatcherMaterializationKind +{ + Unknown, + Empty, + BitmapUri, + SvgUri, + Glyph, + Binary, + SvgData, + BitmapStream, +} diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherUiSliceKind.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherUiSliceKind.cs new file mode 100644 index 0000000000..e935aa7dff --- /dev/null +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconDispatcherUiSliceKind.cs @@ -0,0 +1,12 @@ +// Copyright (c) Microsoft Corporation +// The Microsoft Corporation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.CmdPal.UI.Helpers; + +internal enum IconDispatcherUiSliceKind +{ + SynchronousCallback, + BeforeAsyncSuspension, + AsyncContinuation, +} diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnostics.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnostics.cs index 455d1fd9f7..115e757862 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnostics.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnostics.cs @@ -7,6 +7,7 @@ using ManagedCommon; using Microsoft.UI.Dispatching; using Microsoft.UI.Xaml.Controls; using Microsoft.UI.Xaml.Media.Imaging; +using Windows.Foundation; namespace Microsoft.CmdPal.UI.Helpers; @@ -21,6 +22,7 @@ internal static class IconLoadDiagnostics private static readonly List Reports = []; private static long _nextSessionId; private static IconLoadDiagnosticsSession? _activeSession; + private static IconLoadDiagnosticsSession? _etwSession; public static bool IsRecording => Volatile.Read(ref _activeSession) is not null; @@ -40,6 +42,7 @@ internal static class IconLoadDiagnostics Interlocked.Increment(ref _nextSessionId), dispatcherQueue); Interlocked.Exchange(ref _activeSession, session)?.Stop(); + Interlocked.Exchange(ref _etwSession, null)?.Stop(); return session.Id; } @@ -66,6 +69,7 @@ internal static class IconLoadDiagnostics public static void Reset() { Interlocked.Exchange(ref _activeSession, null)?.Stop(); + Interlocked.Exchange(ref _etwSession, null)?.Stop(); lock (ReportsLock) { Reports.Clear(); @@ -79,7 +83,7 @@ internal static class IconLoadDiagnostics public static IconRequestMeasurement BeginRequest(IconRequestReason reason, double scale, IconRequestOrigin origin) { - var session = Volatile.Read(ref _activeSession); + var session = GetCurrentSession(); return session is null ? default : session.BeginRequest(reason, scale, origin); @@ -93,8 +97,8 @@ internal static class IconLoadDiagnostics double height, double scale) { - var session = request.Session ?? Volatile.Read(ref _activeSession); - if (session is null || !ReferenceEquals(session, Volatile.Read(ref _activeSession))) + var session = request.Session ?? GetCurrentSession(); + if (session is null || !IsCurrentSession(session)) { return null; } @@ -102,14 +106,37 @@ internal static class IconLoadDiagnostics return session.CreateLoad(ClassifyInput(iconString, hasStream), width, height, scale); } + internal static void RecordCacheLookup(Size iconSize, int capacity, bool hit) + { + GetCurrentSession()?.RecordCacheLookup(iconSize, capacity, hit); + } + + internal static void RecordCacheEntryAdded(Size iconSize, int capacity, int entryCount) + { + GetCurrentSession()?.RecordCacheEntryAdded(iconSize, capacity, entryCount); + } + + internal static void RecordCacheEntryRemoved( + Size iconSize, + int capacity, + int entryCount, + AdaptiveCacheRemovalReason reason) + { + GetCurrentSession()?.RecordCacheEntryRemoved( + iconSize, + capacity, + entryCount, + reason); + } + public static long BeginElementUpdate() { - return Volatile.Read(ref _activeSession) is null ? 0 : Stopwatch.GetTimestamp(); + return GetCurrentSession() is null ? 0 : Stopwatch.GetTimestamp(); } public static void RecordElementUpdate(bool reused, IconSource? source, long startedAt) { - var session = Volatile.Read(ref _activeSession); + var session = GetCurrentSession(); if (session is null) { return; @@ -119,6 +146,79 @@ internal static class IconLoadDiagnostics session.RecordElementUpdate(reused, ClassifyResult(source), elapsedTicks); } + internal static void OnEtwDisabled() + { + Interlocked.Exchange(ref _etwSession, null)?.Stop(); + } + + private static IconLoadDiagnosticsSession? GetCurrentSession() + { + var activeSession = Volatile.Read(ref _activeSession); + if (activeSession is not null) + { + return activeSession; + } + + if (!IconLoadEventSource.Log.IsEnabled()) + { + // OnEventCommand normally retires the hidden session as soon as the last listener + // detaches. Avoid an unconditional interlocked write on every disabled hot-path + // probe while still covering a disable racing this read. + if (Volatile.Read(ref _etwSession) is not null) + { + OnEtwDisabled(); + } + + return null; + } + + var etwSession = Volatile.Read(ref _etwSession); + if (etwSession is null) + { + var candidate = new IconLoadDiagnosticsSession(Interlocked.Increment(ref _nextSessionId)); + etwSession = Interlocked.CompareExchange(ref _etwSession, candidate, null); + if (etwSession is null) + { + etwSession = candidate; + } + else + { + candidate.Stop(); + } + } + + // An explicit text session may have started while the hidden ETW session was created. + activeSession = Volatile.Read(ref _activeSession); + if (activeSession is not null) + { + if (ReferenceEquals(Interlocked.CompareExchange(ref _etwSession, null, etwSession), etwSession)) + { + etwSession.Stop(); + } + + return activeSession; + } + + return etwSession; + } + + private static bool IsCurrentSession(IconLoadDiagnosticsSession session) + { + var activeSession = Volatile.Read(ref _activeSession); + if (activeSession is not null) + { + return ReferenceEquals(session, activeSession); + } + + if (!IconLoadEventSource.Log.IsEnabled()) + { + OnEtwDisabled(); + return false; + } + + return ReferenceEquals(session, Volatile.Read(ref _etwSession)); + } + private static IconLoadInputKind ClassifyInput(string? iconString, bool hasStream) { if (!string.IsNullOrEmpty(iconString)) diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnosticsSession.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnosticsSession.cs index dd697c1796..a8ad29c524 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnosticsSession.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadDiagnosticsSession.cs @@ -11,6 +11,7 @@ using System.Text; using Microsoft.CmdPal.UI.Controls; using Microsoft.UI.Dispatching; using Microsoft.UI.Xaml.Controls; +using Windows.Foundation; namespace Microsoft.CmdPal.UI.Helpers; @@ -38,11 +39,21 @@ internal sealed class IconLoadDiagnosticsSession private readonly DiagnosticHistogram _backgroundPreparationLatency = new(); private readonly DiagnosticHistogram _dispatcherWaitLatency = new(); private readonly DiagnosticHistogram _dispatcherWorkLatency = new(); + private readonly DiagnosticHistogram _dispatcherUiExecutionLatency = new(); + private readonly DiagnosticHistogram _dispatcherAsyncSuspensionLatency = new(); + private readonly DiagnosticHistogram[] _dispatcherWaitLatencyByDemand = CreateDemandMeasurements(); + private readonly DiagnosticHistogram[] _dispatcherWorkLatencyByDemand = CreateDemandMeasurements(); + private readonly DiagnosticHistogram[] _dispatcherUiExecutionLatencyByDemand = CreateDemandMeasurements(); + private readonly DiagnosticHistogram[] _dispatcherAsyncSuspensionLatencyByDemand = CreateDemandMeasurements(); + private readonly DiagnosticHistogram[] _dispatcherUiExecutionLatencyBySliceKind = CreateDispatcherUiSliceMeasurements(); + private readonly DispatcherMaterializationMeasurements[] _dispatcherMaterializationMeasurements = CreateDispatcherMaterializationMeasurements(); + private readonly ConcurrentQueue _dispatcherOutliers = new(); private readonly DiagnosticHistogram _uiProbeWaitLatency = new(); private readonly DiagnosticHistogram _elementUpdateLatency = new(); private readonly InputKindMeasurements[] _inputKindMeasurements = CreateInputKindMeasurements(); private readonly ElementKindMeasurements[] _elementKindMeasurements = CreateElementKindMeasurements(); private readonly ConditionalWeakTable, IconLoadMeasurement> _loadsByTask = new(); + private readonly ConcurrentDictionary _cacheMeasurements = new(); private readonly ConcurrentDictionary _requestDemandStates = new(); // These lightweight states intentionally survive load completion so later cache hits can be @@ -93,6 +104,17 @@ internal sealed class IconLoadDiagnosticsSession private long _maximumDemandedLoadsBeyondCapacityAtSpeculativeStart; private long _activeWorkers; private long _maximumActiveWorkers; + private long _dispatcherEnqueuedDemanded; + private long _dispatcherEnqueuedSpeculative; + private long _dispatcherStartedDemanded; + private long _dispatcherStartedSpeculative; + private long _dispatcherCompletedDemanded; + private long _dispatcherCompletedSpeculative; + private long _dispatcherWaitFailures; + private long _currentDispatcherWaits; + private long _maximumDispatcherWaits; + private long _currentDispatcherCallbacks; + private long _maximumDispatcherCallbacks; private long _elementsCreated; private long _elementsReused; private long _uiProbeEnqueued; @@ -134,6 +156,30 @@ internal sealed class IconLoadDiagnosticsSession internal void RecordUiProbeRejected() => Interlocked.Increment(ref _uiProbeRejected); + internal void RecordCacheLookup(Size iconSize, int capacity, bool hit) + { + GetCacheMeasurements(iconSize, capacity).RecordLookup(hit); + } + + internal void RecordCacheEntryAdded(Size iconSize, int capacity, int entryCount) + { + GetCacheMeasurements(iconSize, capacity).RecordAdded(entryCount); + } + + internal void RecordCacheEntryRemoved( + Size iconSize, + int capacity, + int entryCount, + AdaptiveCacheRemovalReason reason) + { + GetCacheMeasurements(iconSize, capacity).RecordRemoved(entryCount, reason); + } + + internal bool IsLoadDemanded(long loadId) + { + return _loadDemandStates.TryGetValue(loadId, out var demandState) && demandState.IsDemanded; + } + public IconRequestMeasurement BeginRequest(IconRequestReason reason, double scale, IconRequestOrigin origin) { origin = origin.Normalize(); @@ -530,17 +576,165 @@ internal sealed class IconLoadDiagnosticsSession IconLoadEventSource.Log.BackgroundPreparationCompleted(Id, loadId, ToMicroseconds(elapsedTicks)); } - public void RecordDispatcherWait(long loadId, IconLoadInputKind inputKind, long elapsedTicks) + public void RecordDispatcherEnqueued( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + bool isDemanded) { + _ = loadId; + _ = inputKind; + IncrementDemandCount( + isDemanded, + ref _dispatcherEnqueuedDemanded, + ref _dispatcherEnqueuedSpeculative); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordEnqueued(isDemanded); + var currentWaits = Interlocked.Increment(ref _currentDispatcherWaits); + UpdateMaximum(ref _maximumDispatcherWaits, currentWaits); + } + + public void RecordDispatcherWait( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + bool isDemanded, + long startedAt, + long elapsedTicks) + { + Interlocked.Decrement(ref _currentDispatcherWaits); + var currentCallbacks = Interlocked.Increment(ref _currentDispatcherCallbacks); + UpdateMaximum(ref _maximumDispatcherCallbacks, currentCallbacks); + IncrementDemandCount( + isDemanded, + ref _dispatcherStartedDemanded, + ref _dispatcherStartedSpeculative); _dispatcherWaitLatency.Record(elapsedTicks); + _dispatcherWaitLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); _inputKindMeasurements[(int)inputKind].DispatcherWaitLatency.Record(elapsedTicks); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordStarted(isDemanded, elapsedTicks); + RecordDispatcherOutlier( + loadId, + inputKind, + materializationKind, + DispatcherOutlierPhase.QueueWait, + isDemanded, + startedAt, + elapsedTicks); IconLoadEventSource.Log.DispatcherWaitCompleted(Id, loadId, ToMicroseconds(elapsedTicks)); } - public void RecordDispatcherWork(long loadId, IconLoadInputKind inputKind, long elapsedTicks) + public void RecordDispatcherWaitFailed( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + bool isDemanded, + long startedAt, + long elapsedTicks) { + Interlocked.Decrement(ref _currentDispatcherWaits); + Interlocked.Increment(ref _dispatcherWaitFailures); + _dispatcherWaitLatency.Record(elapsedTicks); + _dispatcherWaitLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + _inputKindMeasurements[(int)inputKind].DispatcherWaitLatency.Record(elapsedTicks); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordWaitFailed(isDemanded, elapsedTicks); + RecordDispatcherOutlier( + loadId, + inputKind, + materializationKind, + DispatcherOutlierPhase.QueueWaitFailed, + isDemanded, + startedAt, + elapsedTicks); + IconLoadEventSource.Log.DispatcherWaitFailed(Id, loadId, ToMicroseconds(elapsedTicks)); + } + + public void RecordDispatcherUiSlice( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + IconDispatcherUiSliceKind sliceKind, + bool isDemanded, + long startedAt, + long elapsedTicks) + { + _dispatcherUiExecutionLatency.Record(elapsedTicks); + _dispatcherUiExecutionLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + _dispatcherUiExecutionLatencyBySliceKind[(int)sliceKind].Record(elapsedTicks); + _inputKindMeasurements[(int)inputKind].DispatcherUiExecutionLatency.Record(elapsedTicks); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordUiExecution(isDemanded, elapsedTicks); + var outlierPhase = sliceKind == IconDispatcherUiSliceKind.AsyncContinuation + ? DispatcherOutlierPhase.UiContinuation + : DispatcherOutlierPhase.UiEntry; + RecordDispatcherOutlier( + loadId, + inputKind, + materializationKind, + outlierPhase, + isDemanded, + startedAt, + elapsedTicks); + IconLoadEventSource.Log.DispatcherUiSliceCompleted( + Id, + loadId, + (int)materializationKind, + (int)sliceKind, + isDemanded, + ToMicroseconds(elapsedTicks)); + } + + public void RecordDispatcherAsyncSuspension( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + bool isDemanded, + long startedAt, + long elapsedTicks) + { + _dispatcherAsyncSuspensionLatency.Record(elapsedTicks); + _dispatcherAsyncSuspensionLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + _inputKindMeasurements[(int)inputKind].DispatcherAsyncSuspensionLatency.Record(elapsedTicks); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordAsyncSuspension(isDemanded, elapsedTicks); + RecordDispatcherOutlier( + loadId, + inputKind, + materializationKind, + DispatcherOutlierPhase.AsyncSuspension, + isDemanded, + startedAt, + elapsedTicks); + IconLoadEventSource.Log.DispatcherAsyncSuspensionCompleted( + Id, + loadId, + (int)materializationKind, + isDemanded, + ToMicroseconds(elapsedTicks)); + } + + public void RecordDispatcherWork( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + bool isDemanded, + long startedAt, + long elapsedTicks) + { + Interlocked.Decrement(ref _currentDispatcherCallbacks); + IncrementDemandCount( + isDemanded, + ref _dispatcherCompletedDemanded, + ref _dispatcherCompletedSpeculative); _dispatcherWorkLatency.Record(elapsedTicks); + _dispatcherWorkLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); _inputKindMeasurements[(int)inputKind].DispatcherWorkLatency.Record(elapsedTicks); + _dispatcherMaterializationMeasurements[(int)materializationKind].RecordCompleted(isDemanded, elapsedTicks); + RecordDispatcherOutlier( + loadId, + inputKind, + materializationKind, + DispatcherOutlierPhase.CallbackWindow, + isDemanded, + startedAt, + elapsedTicks); IconLoadEventSource.Log.DispatcherWorkCompleted(Id, loadId, ToMicroseconds(elapsedTicks)); } @@ -659,6 +853,10 @@ internal sealed class IconLoadDiagnosticsSession AppendRequestMeasurements(builder); builder.AppendLine(); + builder.AppendLine("Icon caches"); + AppendCacheMeasurements(builder); + builder.AppendLine(); + builder.AppendLine("Request origins"); AppendRequestOriginMeasurements(builder); builder.AppendLine(); @@ -679,6 +877,10 @@ internal sealed class IconLoadDiagnosticsSession _dispatcherWorkLatency.Append(builder, "Dispatcher callback wall time"); builder.AppendLine(); + builder.AppendLine("Dispatcher materialization"); + AppendDispatcherMeasurements(builder); + builder.AppendLine(); + builder.AppendLine("Load demand"); AppendLoadDemandMeasurements(builder); builder.AppendLine(); @@ -771,6 +973,217 @@ internal sealed class IconLoadDiagnosticsSession _uiProbeWaitLatency.Append(builder, "Normal-priority queue wait"); } + private void AppendDispatcherMeasurements(StringBuilder builder) + { + builder.AppendLine(" Definitions:"); + builder.AppendLine(" Queue wait is from publishing low-priority icon work until its dispatcher callback starts."); + builder.AppendLine(" Callback wall time includes asynchronous suspension; it is worker-slot occupancy, not STA CPU time."); + builder.AppendLine(" Measured STA execution slices cover the loader's managed callback entry and outer continuation work around asynchronous operations."); + builder.AppendLine(" Framework work, nested async-helper continuations, and native rendering may occur inside a suspension window or continue outside the measured slices."); + builder.AppendLine(" Later XAML layout, rasterization, and rendering of the created source are outside this section; the responsiveness probe can still expose resulting dispatcher stalls."); + builder.AppendLine(" Queue-wait demand is sampled when the wait ends: at callback start or enqueue failure."); + builder.AppendLine(" Cumulative times sum all loads and can overlap across workers. Demand is sampled independently at enqueue, callback start, and completion."); + + builder.AppendLine(" Phase counts"); + AppendValue(builder, "Enqueued demanded", Volatile.Read(ref _dispatcherEnqueuedDemanded), " "); + AppendValue(builder, "Enqueued speculative", Volatile.Read(ref _dispatcherEnqueuedSpeculative), " "); + AppendValue(builder, "Callbacks started demanded", Volatile.Read(ref _dispatcherStartedDemanded), " "); + AppendValue(builder, "Callbacks started speculative", Volatile.Read(ref _dispatcherStartedSpeculative), " "); + AppendValue(builder, "Callbacks completed demanded", Volatile.Read(ref _dispatcherCompletedDemanded), " "); + AppendValue(builder, "Callbacks completed speculative", Volatile.Read(ref _dispatcherCompletedSpeculative), " "); + AppendValue(builder, "Dispatcher enqueue failures", Volatile.Read(ref _dispatcherWaitFailures), " "); + AppendValue(builder, "Waits outstanding at stop", Math.Max(0, Volatile.Read(ref _currentDispatcherWaits)), " "); + AppendValue(builder, "Maximum simultaneous waits", Volatile.Read(ref _maximumDispatcherWaits), " "); + AppendValue(builder, "Callback windows outstanding at stop", Math.Max(0, Volatile.Read(ref _currentDispatcherCallbacks)), " "); + AppendValue(builder, "Maximum simultaneous callback windows", Volatile.Read(ref _maximumDispatcherCallbacks), " "); + + var preparationTicks = _backgroundPreparationLatency.SumTicks; + var waitTicks = _dispatcherWaitLatency.SumTicks; + var callbackTicks = _dispatcherWorkLatency.SumTicks; + var uiHandoffTicks = waitTicks + callbackTicks; + var postWorkerStartTicks = preparationTicks + uiHandoffTicks; + builder.AppendLine(" Cumulative worker-path time"); + AppendCumulativeTime(builder, "Background preparation", preparationTicks); + AppendCumulativeTime(builder, "Low-priority dispatcher wait", waitTicks); + AppendCumulativeTime(builder, "Dispatcher callback wall windows", callbackTicks); + AppendCumulativeTime(builder, "UI handoff total", uiHandoffTicks); + AppendCumulativeTime(builder, "Post-worker-start materialization total", postWorkerStartTicks); + builder.Append(" UI handoff share of post-worker-start time: ") + .Append(postWorkerStartTicks == 0 + ? "n/a" + : (uiHandoffTicks * 100D / postWorkerStartTicks).ToString("0.###", CultureInfo.InvariantCulture) + " %") + .AppendLine(); + AppendCumulativeTime(builder, "Measured managed STA execution", _dispatcherUiExecutionLatency.SumTicks); + AppendCumulativeTime(builder, "Asynchronous materialization suspension", _dispatcherAsyncSuspensionLatency.SumTicks); + + var measuredUiThreadTicks = _directGlyphLatency.SumTicks + + _dispatcherUiExecutionLatency.SumTicks + + _elementUpdateLatency.SumTicks; + builder.AppendLine(" Measured UI-thread work in instrumented icon paths"); + builder.AppendLine(" Definition: a lower bound composed of direct glyph construction, loader-managed STA slices, and IconBox element updates. It excludes later XAML rendering and unrelated UI work."); + AppendCumulativeTime(builder, "Direct glyph construction", _directGlyphLatency.SumTicks); + AppendCumulativeTime(builder, "Loader-managed STA slices", _dispatcherUiExecutionLatency.SumTicks); + AppendCumulativeTime(builder, "IconBox element updates", _elementUpdateLatency.SumTicks); + AppendCumulativeTime(builder, "Measured icon UI-thread total", measuredUiThreadTicks); + + builder.AppendLine(" Overall timing"); + _dispatcherWaitLatency.Append(builder, "Low-priority dispatcher wait", " "); + _dispatcherWorkLatency.Append(builder, "Dispatcher callback wall time", " "); + _dispatcherUiExecutionLatency.Append(builder, "Measured STA execution slices", " "); + _dispatcherAsyncSuspensionLatency.Append(builder, "Asynchronous materialization suspension", " "); + + builder.AppendLine(" By demand at measured phase"); + AppendDispatcherDemandMeasurements(builder, "Speculative", 0); + AppendDispatcherDemandMeasurements(builder, "Demanded", 1); + + builder.AppendLine(" Measured STA execution by slice kind"); + var sliceKinds = Enum.GetValues(); + for (var i = 0; i < sliceKinds.Length; i++) + { + _dispatcherUiExecutionLatencyBySliceKind[i].Append(builder, sliceKinds[i].ToString(), " "); + } + + builder.AppendLine(" By materialization kind"); + var materializationKinds = Enum.GetValues(); + var wroteMaterialization = false; + for (var i = 0; i < materializationKinds.Length; i++) + { + var measurements = _dispatcherMaterializationMeasurements[i]; + if (!measurements.HasSamples) + { + continue; + } + + wroteMaterialization = true; + builder.Append(" ").AppendLine(materializationKinds[i].ToString()); + AppendValue(builder, "Enqueued demanded", measurements.EnqueuedDemanded, " "); + AppendValue(builder, "Enqueued speculative", measurements.EnqueuedSpeculative, " "); + AppendValue(builder, "Callbacks started demanded", measurements.StartedDemanded, " "); + AppendValue(builder, "Callbacks started speculative", measurements.StartedSpeculative, " "); + AppendValue(builder, "Callbacks completed demanded", measurements.CompletedDemanded, " "); + AppendValue(builder, "Callbacks completed speculative", measurements.CompletedSpeculative, " "); + AppendValue(builder, "Dispatcher enqueue failures", measurements.WaitFailures, " "); + measurements.DispatcherWaitLatency.Append(builder, "Low-priority dispatcher wait", " "); + measurements.CallbackWallLatency.Append(builder, "Dispatcher callback wall time", " "); + measurements.UiExecutionLatency.Append(builder, "Measured STA execution slices", " "); + measurements.AsyncSuspensionLatency.Append(builder, "Asynchronous materialization suspension", " "); + measurements.AppendDemandTimings(builder, "Speculative", 0); + measurements.AppendDemandTimings(builder, "Demanded", 1); + } + + if (!wroteMaterialization) + { + builder.AppendLine(" no samples"); + } + + var outliers = _dispatcherOutliers.ToArray(); + Array.Sort(outliers, static (left, right) => right.ElapsedTicks.CompareTo(left.ElapsedTicks)); + builder.AppendLine(" Dispatcher outliers (>=16 ms, top 10 by duration)"); + AppendValue(builder, "Samples captured", outliers.Length, " "); + if (outliers.Length == 0) + { + builder.AppendLine(" no samples"); + } + else + { + for (var i = 0; i < Math.Min(10, outliers.Length); i++) + { + var sample = outliers[i]; + builder.Append(" Load ").Append(sample.LoadId.ToString(CultureInfo.InvariantCulture)) + .Append(": phase=").Append(sample.Phase) + .Append(", input=").Append(sample.InputKind) + .Append(", materialization=").Append(sample.MaterializationKind) + .Append(", demand=").Append(sample.IsDemanded ? "Demanded" : "Speculative") + .Append(", session offset=").Append(FormatMilliseconds(Math.Max(0, sample.StartedAt - _startedAt))).Append(" ms") + .Append(", duration=").Append(FormatMilliseconds(sample.ElapsedTicks)).AppendLine(" ms"); + } + } + } + + private void AppendDispatcherDemandMeasurements(StringBuilder builder, string name, int index) + { + builder.Append(" ").AppendLine(name); + _dispatcherWaitLatencyByDemand[index].Append(builder, "Low-priority dispatcher wait", " "); + _dispatcherWorkLatencyByDemand[index].Append(builder, "Dispatcher callback wall time", " "); + _dispatcherUiExecutionLatencyByDemand[index].Append(builder, "Measured STA execution slices", " "); + _dispatcherAsyncSuspensionLatencyByDemand[index].Append(builder, "Asynchronous materialization suspension", " "); + } + + private static void AppendCumulativeTime(StringBuilder builder, string name, long stopwatchTicks) + { + builder.Append(" ").Append(name).Append(": ").Append(FormatMilliseconds(stopwatchTicks)).AppendLine(" ms"); + } + + private void AppendCacheMeasurements(StringBuilder builder) + { + builder.AppendLine(" Definition: each entry is a cached IconSource task; counts are approximate concurrent observations. Eviction only drops the cache reference."); + builder.AppendLine(" A request coalesced with an in-flight load is a cache miss; see Provider resolution for in-flight reuse."); + builder.AppendLine(" Capacity means the cache was over its limit when removal was attempted and takes precedence over LowScore; LowScore means score alone caused removal."); + if (_cacheMeasurements.IsEmpty) + { + builder.AppendLine(" No cache activity was observed during this session."); + return; + } + + var caches = _cacheMeasurements.ToArray(); + Array.Sort( + caches, + static (left, right) => + { + var width = left.Key.Width.CompareTo(right.Key.Width); + if (width != 0) + { + return width; + } + + var height = left.Key.Height.CompareTo(right.Key.Height); + return height != 0 ? height : left.Key.Capacity.CompareTo(right.Key.Capacity); + }); + + foreach (var (descriptor, measurements) in caches) + { + var snapshot = measurements.CreateSnapshot(); + builder + .Append(" ") + .Append(descriptor.Width) + .Append('x') + .Append(descriptor.Height) + .Append(", capacity ") + .AppendLine(descriptor.Capacity.ToString(CultureInfo.InvariantCulture)); + AppendValue(builder, "Lookups", snapshot.Hits + snapshot.Misses, " "); + AppendValue(builder, "Hits", snapshot.Hits, " "); + AppendValue(builder, "Misses", snapshot.Misses, " "); + builder.Append(" Hit rate: ") + .Append(snapshot.Hits + snapshot.Misses == 0 + ? "n/a" + : (snapshot.Hits * 100D / (snapshot.Hits + snapshot.Misses)).ToString("0.###", CultureInfo.InvariantCulture) + " %") + .AppendLine(); + AppendValue(builder, "First observed entries", snapshot.FirstObservedCount, " "); + AppendValue(builder, "Last observed entries", snapshot.LastObservedCount, " "); + AppendValue(builder, "Maximum observed entries", snapshot.MaximumObservedCount, " "); + AppendValue(builder, "Entries added during session", snapshot.EntriesAdded, " "); + AppendValue(builder, "Entries removed during session", snapshot.EntriesRemoved, " "); + builder.AppendLine(" Removal reasons"); + AppendEnumCounts(builder, snapshot.RemovalsByReason, " "); + } + } + + private CacheMeasurements GetCacheMeasurements(Size iconSize, int capacity) + { + var descriptor = new CacheDescriptor( + NormalizeCacheDimension(iconSize.Width), + NormalizeCacheDimension(iconSize.Height), + capacity); + return _cacheMeasurements.GetOrAdd(descriptor, static _ => new CacheMeasurements()); + } + + private static int NormalizeCacheDimension(double value) + { + return double.IsFinite(value) && value >= 0 + ? (int)Math.Round(value) + : 0; + } + private void AppendLoadDemandMeasurements(StringBuilder builder) { var linkedRequests = 0L; @@ -938,6 +1351,8 @@ internal sealed class IconLoadDiagnosticsSession measurements.BackgroundPreparationLatency.Append(builder, "Background preparation", " "); measurements.DispatcherWaitLatency.Append(builder, "Dispatcher wait", " "); measurements.DispatcherWorkLatency.Append(builder, "Dispatcher callback wall time", " "); + measurements.DispatcherUiExecutionLatency.Append(builder, "Measured STA execution slices", " "); + measurements.DispatcherAsyncSuspensionLatency.Append(builder, "Asynchronous materialization suspension", " "); } } @@ -1052,6 +1467,33 @@ internal sealed class IconLoadDiagnosticsSession return measurements; } + private static DiagnosticHistogram[] CreateDemandMeasurements() + { + return [new DiagnosticHistogram(), new DiagnosticHistogram()]; + } + + private static DiagnosticHistogram[] CreateDispatcherUiSliceMeasurements() + { + var measurements = new DiagnosticHistogram[Enum.GetValues().Length]; + for (var i = 0; i < measurements.Length; i++) + { + measurements[i] = new DiagnosticHistogram(); + } + + return measurements; + } + + private static DispatcherMaterializationMeasurements[] CreateDispatcherMaterializationMeasurements() + { + var measurements = new DispatcherMaterializationMeasurements[Enum.GetValues().Length]; + for (var i = 0; i < measurements.Length; i++) + { + measurements[i] = new DispatcherMaterializationMeasurements(); + } + + return measurements; + } + private static DiagnosticHistogram[][] CreateRequestMeasurements() { var measurements = new DiagnosticHistogram[Enum.GetValues().Length][]; @@ -1105,6 +1547,17 @@ internal sealed class IconLoadDiagnosticsSession return total; } + private static long[] SnapshotCounts(long[] values) + { + var snapshot = new long[values.Length]; + for (var i = 0; i < values.Length; i++) + { + snapshot[i] = Volatile.Read(ref values[i]); + } + + return snapshot; + } + private static void UpdateMaximum(ref long maximum, long value) { var current = Volatile.Read(ref maximum); @@ -1120,6 +1573,44 @@ internal sealed class IconLoadDiagnosticsSession } } + private void RecordDispatcherOutlier( + long loadId, + IconLoadInputKind inputKind, + IconDispatcherMaterializationKind materializationKind, + DispatcherOutlierPhase phase, + bool isDemanded, + long startedAt, + long elapsedTicks) + { + if (elapsedTicks < Stopwatch.Frequency * 16L / 1000L) + { + return; + } + + _dispatcherOutliers.Enqueue(new DispatcherOutlierSample( + loadId, + inputKind, + materializationKind, + phase, + isDemanded, + startedAt, + elapsedTicks)); + } + + private static int DemandIndex(bool isDemanded) => isDemanded ? 1 : 0; + + private static void IncrementDemandCount(bool isDemanded, ref long demanded, ref long speculative) + { + if (isDemanded) + { + Interlocked.Increment(ref demanded); + } + else + { + Interlocked.Increment(ref speculative); + } + } + private static long GetProcessCpuTicks() { try @@ -1156,6 +1647,95 @@ internal sealed class IconLoadDiagnosticsSession private static string FormatMilliseconds(long ticks) => (ticks * 1000D / Stopwatch.Frequency).ToString("0.###", CultureInfo.InvariantCulture); + private enum DispatcherOutlierPhase + { + QueueWait, + QueueWaitFailed, + UiEntry, + AsyncSuspension, + UiContinuation, + CallbackWindow, + } + + private readonly record struct DispatcherOutlierSample( + long LoadId, + IconLoadInputKind InputKind, + IconDispatcherMaterializationKind MaterializationKind, + DispatcherOutlierPhase Phase, + bool IsDemanded, + long StartedAt, + long ElapsedTicks); + + private readonly record struct CacheDescriptor(int Width, int Height, int Capacity); + + private readonly record struct CacheMeasurementsSnapshot( + long Hits, + long Misses, + long FirstObservedCount, + long LastObservedCount, + long MaximumObservedCount, + long EntriesAdded, + long EntriesRemoved, + long[] RemovalsByReason); + + private sealed class CacheMeasurements + { + private readonly long[] _removalsByReason = new long[Enum.GetValues().Length]; + private long _hits; + private long _misses; + private long _firstObservedCount = -1; + private long _lastObservedCount; + private long _maximumObservedCount; + private long _entriesAdded; + private long _entriesRemoved; + + public void RecordLookup(bool hit) + { + if (hit) + { + Interlocked.Increment(ref _hits); + } + else + { + Interlocked.Increment(ref _misses); + } + } + + public void RecordAdded(int entryCount) + { + RecordObservation(entryCount); + Interlocked.Increment(ref _entriesAdded); + } + + public void RecordRemoved(int entryCount, AdaptiveCacheRemovalReason reason) + { + RecordObservation(entryCount); + Interlocked.Increment(ref _entriesRemoved); + Interlocked.Increment(ref _removalsByReason[(int)reason]); + } + + public CacheMeasurementsSnapshot CreateSnapshot() + { + return new CacheMeasurementsSnapshot( + Volatile.Read(ref _hits), + Volatile.Read(ref _misses), + Math.Max(0, Volatile.Read(ref _firstObservedCount)), + Math.Max(0, Volatile.Read(ref _lastObservedCount)), + Math.Max(0, Volatile.Read(ref _maximumObservedCount)), + Volatile.Read(ref _entriesAdded), + Volatile.Read(ref _entriesRemoved), + SnapshotCounts(_removalsByReason)); + } + + private void RecordObservation(int entryCount) + { + var normalizedCount = Math.Max(0, entryCount); + Interlocked.CompareExchange(ref _firstObservedCount, normalizedCount, -1); + Interlocked.Exchange(ref _lastObservedCount, normalizedCount); + UpdateMaximum(ref _maximumObservedCount, normalizedCount); + } + } + private readonly record struct LoadResolutionResult( bool TracksLiveRequester, bool RetainedResultCacheHit, @@ -1349,6 +1929,10 @@ internal sealed class IconLoadDiagnosticsSession _inputKind = inputKind; } + // Dispatcher diagnostics only need a point-in-time attribution. Keep this read lock-free + // so recording a callback phase can never block the WinUI STA on a demand-state writer. + public bool IsDemanded => Volatile.Read(ref _liveRequesters) > 0; + public LoadResolutionResult RecordResolution( IconProviderResolution resolution, bool requesterInvalidated, @@ -1577,6 +2161,131 @@ internal sealed class IconLoadDiagnosticsSession public DiagnosticHistogram DispatcherWaitLatency { get; } = new(); public DiagnosticHistogram DispatcherWorkLatency { get; } = new(); + + public DiagnosticHistogram DispatcherUiExecutionLatency { get; } = new(); + + public DiagnosticHistogram DispatcherAsyncSuspensionLatency { get; } = new(); + } + + private sealed class DispatcherMaterializationMeasurements + { + private long _enqueuedDemanded; + private long _enqueuedSpeculative; + private long _startedDemanded; + private long _startedSpeculative; + private long _completedDemanded; + private long _completedSpeculative; + private long _waitFailures; + + public long EnqueuedDemanded => Volatile.Read(ref _enqueuedDemanded); + + public long EnqueuedSpeculative => Volatile.Read(ref _enqueuedSpeculative); + + public long StartedDemanded => Volatile.Read(ref _startedDemanded); + + public long StartedSpeculative => Volatile.Read(ref _startedSpeculative); + + public long CompletedDemanded => Volatile.Read(ref _completedDemanded); + + public long CompletedSpeculative => Volatile.Read(ref _completedSpeculative); + + public long WaitFailures => Volatile.Read(ref _waitFailures); + + public DiagnosticHistogram DispatcherWaitLatency { get; } = new(); + + public DiagnosticHistogram CallbackWallLatency { get; } = new(); + + public DiagnosticHistogram UiExecutionLatency { get; } = new(); + + public DiagnosticHistogram AsyncSuspensionLatency { get; } = new(); + + private DiagnosticHistogram[] DispatcherWaitLatencyByDemand { get; } = CreateDemandMeasurements(); + + private DiagnosticHistogram[] CallbackWallLatencyByDemand { get; } = CreateDemandMeasurements(); + + private DiagnosticHistogram[] UiExecutionLatencyByDemand { get; } = CreateDemandMeasurements(); + + private DiagnosticHistogram[] AsyncSuspensionLatencyByDemand { get; } = CreateDemandMeasurements(); + + public bool HasSamples => EnqueuedDemanded + EnqueuedSpeculative > 0; + + public void RecordEnqueued(bool isDemanded) + { + if (isDemanded) + { + Interlocked.Increment(ref _enqueuedDemanded); + } + else + { + Interlocked.Increment(ref _enqueuedSpeculative); + } + } + + public void RecordStarted(bool isDemanded, long elapsedTicks) + { + if (isDemanded) + { + Interlocked.Increment(ref _startedDemanded); + } + else + { + Interlocked.Increment(ref _startedSpeculative); + } + + DispatcherWaitLatency.Record(elapsedTicks); + DispatcherWaitLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + } + + public void RecordWaitFailed(bool isDemanded, long elapsedTicks) + { + Interlocked.Increment(ref _waitFailures); + DispatcherWaitLatency.Record(elapsedTicks); + DispatcherWaitLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + } + + public void RecordCompleted(bool isDemanded, long elapsedTicks) + { + if (isDemanded) + { + Interlocked.Increment(ref _completedDemanded); + } + else + { + Interlocked.Increment(ref _completedSpeculative); + } + + CallbackWallLatency.Record(elapsedTicks); + CallbackWallLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + } + + public void RecordUiExecution(bool isDemanded, long elapsedTicks) + { + UiExecutionLatency.Record(elapsedTicks); + UiExecutionLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + } + + public void RecordAsyncSuspension(bool isDemanded, long elapsedTicks) + { + AsyncSuspensionLatency.Record(elapsedTicks); + AsyncSuspensionLatencyByDemand[DemandIndex(isDemanded)].Record(elapsedTicks); + } + + public void AppendDemandTimings(StringBuilder builder, string name, int index) + { + if (DispatcherWaitLatencyByDemand[index].Count == 0 && + CallbackWallLatencyByDemand[index].Count == 0 && + UiExecutionLatencyByDemand[index].Count == 0 && + AsyncSuspensionLatencyByDemand[index].Count == 0) + { + return; + } + + builder.Append(" ").Append(name).AppendLine(" timing"); + DispatcherWaitLatencyByDemand[index].Append(builder, "Low-priority dispatcher wait", " "); + CallbackWallLatencyByDemand[index].Append(builder, "Dispatcher callback wall time", " "); + UiExecutionLatencyByDemand[index].Append(builder, "Measured STA execution slices", " "); + AsyncSuspensionLatencyByDemand[index].Append(builder, "Asynchronous materialization suspension", " "); + } } private sealed class ElementKindMeasurements @@ -1632,6 +2341,8 @@ internal sealed class IconLoadDiagnosticsSession public long Count => Volatile.Read(ref _count); + public long SumTicks => Volatile.Read(ref _sumTicks); + public void Record(long elapsedTicks) { if (elapsedTicks < 0) diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadEventSource.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadEventSource.cs index 3987c9927a..fe649aea96 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadEventSource.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadEventSource.cs @@ -2,11 +2,14 @@ // The Microsoft Corporation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System.Diagnostics.CodeAnalysis; using System.Diagnostics.Tracing; namespace Microsoft.CmdPal.UI.Helpers; -[EventSource(Name = "Microsoft.PowerToys.CmdPal.IconLoading")] +[EventSource( + Name = "Microsoft.PowerToys.CmdPal.IconLoading", + Guid = "AA068BA3-1767-5F92-7A9B-8F5DA0397413")] internal sealed partial class IconLoadEventSource : EventSource { public static IconLoadEventSource Log { get; } = new(); @@ -15,6 +18,15 @@ internal sealed partial class IconLoadEventSource : EventSource { } + protected override void OnEventCommand(EventCommandEventArgs command) + { + base.OnEventCommand(command); + if (command.Command == EventCommand.Disable && !IsEnabled()) + { + IconLoadDiagnostics.OnEtwDisabled(); + } + } + [Event(1, Level = EventLevel.Informational)] public void RequestStarted(long sessionId, long requestId, int reason, double scale) { @@ -268,6 +280,50 @@ internal sealed partial class IconLoadEventSource : EventSource demandedBeyondCapacity); } + [Event(34, Level = EventLevel.Warning)] + public void DispatcherWaitFailed(long sessionId, long loadId, long elapsedMicroseconds) + { + if (!IsEnabled()) + { + return; + } + + WriteEvent(34, sessionId, loadId, elapsedMicroseconds); + } + + [Event(35, Level = EventLevel.Informational)] + public void DispatcherUiSliceCompleted( + long sessionId, + long loadId, + int materializationKind, + int sliceKind, + bool isDemanded, + long elapsedMicroseconds) + { + if (!IsEnabled()) + { + return; + } + + WriteEvent(35, sessionId, loadId, materializationKind, sliceKind, isDemanded, elapsedMicroseconds); + } + + [Event(36, Level = EventLevel.Informational)] + public void DispatcherAsyncSuspensionCompleted( + long sessionId, + long loadId, + int materializationKind, + bool isDemanded, + long elapsedMicroseconds) + { + if (!IsEnabled()) + { + return; + } + + WriteEvent(36, sessionId, loadId, materializationKind, isDemanded, elapsedMicroseconds); + } + // Event IDs follow the final grouped diagnostics schema and intentionally remain sparse so // independently reviewable layers can land without changing an event's published identity. [Event(37, Level = EventLevel.Informational)] @@ -280,4 +336,225 @@ internal sealed partial class IconLoadEventSource : EventSource WriteEvent(37, sessionId, elapsedMicroseconds); } + + // These exact overloads intentionally shadow EventSource.WriteEvent(params object?[]). + // The params overload allocates an array and boxes values while ETW is enabled, which + // would make the icon diagnostics measurably perturb the paths they are observing. + [NonEvent] + private new unsafe void WriteEvent(int eventId, long value1, long value2) + { + EventData* data = stackalloc EventData[2]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + WritePrimitiveEvent(eventId, 2, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3) + { + EventData* data = stackalloc EventData[3]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + WritePrimitiveEvent(eventId, 3, data); + } + + [NonEvent] + private new unsafe void WriteEvent(int eventId, long value1, long value2, long value3) + { + EventData* data = stackalloc EventData[3]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(long)); + WritePrimitiveEvent(eventId, 3, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, double value4) + { + EventData* data = stackalloc EventData[4]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(double)); + WritePrimitiveEvent(eventId, 4, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, long value3, int value4) + { + EventData* data = stackalloc EventData[4]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(long)); + SetEventData(&data[3], &value4, sizeof(int)); + WritePrimitiveEvent(eventId, 4, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, long value4) + { + EventData* data = stackalloc EventData[4]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(long)); + WritePrimitiveEvent(eventId, 4, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, long value3, long value4) + { + EventData* data = stackalloc EventData[4]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(long)); + SetEventData(&data[3], &value4, sizeof(long)); + WritePrimitiveEvent(eventId, 4, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, int value2, bool value3, long value4) + { + var boolValue3 = value3 ? 1 : 0; + EventData* data = stackalloc EventData[4]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(int)); + SetEventData(&data[2], &boolValue3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(long)); + WritePrimitiveEvent(eventId, 4, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, int value4, long value5) + { + EventData* data = stackalloc EventData[5]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(int)); + SetEventData(&data[4], &value5, sizeof(long)); + WritePrimitiveEvent(eventId, 5, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, long value3, int value4, int value5) + { + EventData* data = stackalloc EventData[5]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(long)); + SetEventData(&data[3], &value4, sizeof(int)); + SetEventData(&data[4], &value5, sizeof(int)); + WritePrimitiveEvent(eventId, 5, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, long value4, long value5) + { + EventData* data = stackalloc EventData[5]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(long)); + SetEventData(&data[4], &value5, sizeof(long)); + WritePrimitiveEvent(eventId, 5, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, bool value4, long value5) + { + var boolValue4 = value4 ? 1 : 0; + EventData* data = stackalloc EventData[5]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &boolValue4, sizeof(int)); + SetEventData(&data[4], &value5, sizeof(long)); + WritePrimitiveEvent(eventId, 5, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, double value4, double value5, double value6) + { + EventData* data = stackalloc EventData[6]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(double)); + SetEventData(&data[4], &value5, sizeof(double)); + SetEventData(&data[5], &value6, sizeof(double)); + WritePrimitiveEvent(eventId, 6, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, int value3, int value4, bool value5, long value6) + { + var boolValue5 = value5 ? 1 : 0; + EventData* data = stackalloc EventData[6]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(int)); + SetEventData(&data[4], &boolValue5, sizeof(int)); + SetEventData(&data[5], &value6, sizeof(long)); + WritePrimitiveEvent(eventId, 6, data); + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, long value1, long value2, long value3, int value4, string value5) + { + value5 ??= string.Empty; + fixed (char* value5Pointer = value5) + { + EventData* data = stackalloc EventData[5]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(long)); + SetEventData(&data[3], &value4, sizeof(int)); + SetEventData(&data[4], value5Pointer, checked((value5.Length + 1) * sizeof(char))); + WritePrimitiveEvent(eventId, 5, data); + } + } + + [NonEvent] + private unsafe void WriteEvent( + int eventId, + long value1, + long value2, + int value3, + long value4, + long value5, + long value6, + int value7, + long value8) + { + EventData* data = stackalloc EventData[8]; + SetEventData(&data[0], &value1, sizeof(long)); + SetEventData(&data[1], &value2, sizeof(long)); + SetEventData(&data[2], &value3, sizeof(int)); + SetEventData(&data[3], &value4, sizeof(long)); + SetEventData(&data[4], &value5, sizeof(long)); + SetEventData(&data[5], &value6, sizeof(long)); + SetEventData(&data[6], &value7, sizeof(int)); + SetEventData(&data[7], &value8, sizeof(long)); + WritePrimitiveEvent(eventId, 8, data); + } + + [NonEvent] + private static unsafe void SetEventData(EventData* eventData, void* value, int size) + { + eventData->DataPointer = (IntPtr)value; + eventData->Size = size; + } + + [NonEvent] + [UnconditionalSuppressMessage( + "Trimming", + "IL2026", + Justification = "Payload descriptors reference only primitive values or an explicitly pinned string buffer; no object graph is serialized.")] + private unsafe void WritePrimitiveEvent(int eventId, int eventDataCount, EventData* data) + { + WriteEventCore(eventId, eventDataCount, data); + } } diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadMeasurement.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadMeasurement.cs index 87dd5cb0a6..fa533339d1 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadMeasurement.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoadMeasurement.cs @@ -9,6 +9,10 @@ namespace Microsoft.CmdPal.UI.Helpers; internal sealed class IconLoadMeasurement { + private const int DispatcherWaitingState = 1; + private const int DispatcherCallbackState = 2; + private const int DispatcherCompletedState = 3; + private enum EnqueueState { Pending, @@ -25,6 +29,8 @@ internal sealed class IconLoadMeasurement private int _completed; private int _resultKind; private TaskCompletionSource? _enqueueWaiter; + private int _dispatcherState; + private int _dispatcherMaterializationKind; internal IconLoadDiagnosticsSession Session { get; } @@ -98,18 +104,102 @@ internal sealed class IconLoadMeasurement Session.RecordBackgroundPreparation(Id, InputKind, Stopwatch.GetTimestamp() - startedAt); } - public long BeginDispatcherWait() => Stopwatch.GetTimestamp(); + public long BeginDispatcherWait( + IconDispatcherMaterializationKind materializationKind = IconDispatcherMaterializationKind.Unknown) + { + var now = Stopwatch.GetTimestamp(); + Volatile.Write(ref _dispatcherMaterializationKind, (int)materializationKind); + if (Interlocked.CompareExchange(ref _dispatcherState, DispatcherWaitingState, 0) == 0) + { + Session.RecordDispatcherEnqueued(Id, InputKind, materializationKind, Session.IsLoadDemanded(Id)); + } + + return now; + } public long DispatcherStarted(long enqueuedAt) { var now = Stopwatch.GetTimestamp(); - Session.RecordDispatcherWait(Id, InputKind, now - enqueuedAt); - return now; + if (Interlocked.CompareExchange( + ref _dispatcherState, + DispatcherCallbackState, + DispatcherWaitingState) == DispatcherWaitingState) + { + Session.RecordDispatcherWait( + Id, + InputKind, + (IconDispatcherMaterializationKind)Volatile.Read(ref _dispatcherMaterializationKind), + Session.IsLoadDemanded(Id), + enqueuedAt, + now - enqueuedAt); + } + + // Start callback-wall and UI-slice timing after recording the queue-wait + // sample so diagnostics bookkeeping is not attributed to materialization. + return Stopwatch.GetTimestamp(); + } + + public long DispatcherUiSliceCompleted(long startedAt, IconDispatcherUiSliceKind sliceKind) + { + var now = Stopwatch.GetTimestamp(); + Session.RecordDispatcherUiSlice( + Id, + InputKind, + (IconDispatcherMaterializationKind)Volatile.Read(ref _dispatcherMaterializationKind), + sliceKind, + Session.IsLoadDemanded(Id), + startedAt, + now - startedAt); + return Stopwatch.GetTimestamp(); + } + + public long DispatcherAsyncSuspensionCompleted(long startedAt) + { + var now = Stopwatch.GetTimestamp(); + Session.RecordDispatcherAsyncSuspension( + Id, + InputKind, + (IconDispatcherMaterializationKind)Volatile.Read(ref _dispatcherMaterializationKind), + Session.IsLoadDemanded(Id), + startedAt, + now - startedAt); + return Stopwatch.GetTimestamp(); } public void DispatcherCompleted(long startedAt) { - Session.RecordDispatcherWork(Id, InputKind, Stopwatch.GetTimestamp() - startedAt); + var now = Stopwatch.GetTimestamp(); + if (Interlocked.CompareExchange( + ref _dispatcherState, + DispatcherCompletedState, + DispatcherCallbackState) == DispatcherCallbackState) + { + Session.RecordDispatcherWork( + Id, + InputKind, + (IconDispatcherMaterializationKind)Volatile.Read(ref _dispatcherMaterializationKind), + Session.IsLoadDemanded(Id), + startedAt, + now - startedAt); + } + } + + public void DispatcherWaitFailed(long enqueuedAt) + { + var now = Stopwatch.GetTimestamp(); + if (Interlocked.CompareExchange( + ref _dispatcherState, + DispatcherCompletedState, + DispatcherWaitingState) == DispatcherWaitingState) + { + Session.RecordDispatcherWaitFailed( + Id, + InputKind, + (IconDispatcherMaterializationKind)Volatile.Read(ref _dispatcherMaterializationKind), + Session.IsLoadDemanded(Id), + enqueuedAt, + now - enqueuedAt); + } } public void SetResult(IconSource? result) diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoaderService.cs b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoaderService.cs index f978f23182..05e1d998d0 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoaderService.cs +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Helpers/Icons/IconLoaderService.cs @@ -192,25 +192,38 @@ internal sealed partial class IconLoaderService : IIconLoaderService if (!string.IsNullOrEmpty(iconString)) { - var dispatcherEnqueuedAt = diagnostics?.BeginDispatcherWait() ?? 0; - return await _dispatcherQueue - .EnqueueAsync( - () => - { - var dispatcherStartedAt = diagnostics?.DispatcherStarted(dispatcherEnqueuedAt) ?? 0; - try + var dispatcherEnqueuedAt = diagnostics?.BeginDispatcherWait( + IconDispatcherMaterializationKind.Unknown) ?? 0; + try + { + return await _dispatcherQueue + .EnqueueAsync( + () => { - var result = GetStringIconSource(iconString, fontFamily, scaledSize); - diagnostics?.SetResult(result); - return result; - } - finally - { - diagnostics?.DispatcherCompleted(dispatcherStartedAt); - } - }, - LoadingPriorityOnDispatcher) - .ConfigureAwait(false); + var dispatcherStartedAt = diagnostics?.DispatcherStarted(dispatcherEnqueuedAt) ?? 0; + try + { + var result = GetStringIconSource(iconString, fontFamily, scaledSize); + diagnostics?.SetResult(result); + return result; + } + finally + { + diagnostics?.DispatcherUiSliceCompleted( + dispatcherStartedAt, + IconDispatcherUiSliceKind.SynchronousCallback); + diagnostics?.DispatcherCompleted(dispatcherStartedAt); + } + }, + LoadingPriorityOnDispatcher) + .ConfigureAwait(false); + } + catch + { + // This is a no-op after the callback has started or completed. + diagnostics?.DispatcherWaitFailed(dispatcherEnqueuedAt); + throw; + } } if (streamRef != null) @@ -221,25 +234,66 @@ internal sealed partial class IconLoaderService : IIconLoaderService using var bitmapStream = await streamRef.OpenReadAsync().AsTask().ConfigureAwait(false); diagnostics?.CompleteBackgroundPreparation(preparationStartedAt); - var dispatcherEnqueuedAt = diagnostics?.BeginDispatcherWait() ?? 0; - return await _dispatcherQueue - .EnqueueAsync(BuildImageSource, LoadingPriorityOnDispatcher) - .ConfigureAwait(false); + var dispatcherEnqueuedAt = diagnostics?.BeginDispatcherWait( + IconDispatcherMaterializationKind.BitmapStream) ?? 0; + try + { + return await _dispatcherQueue + .EnqueueAsync(BuildImageSource, LoadingPriorityOnDispatcher) + .ConfigureAwait(false); + } + catch + { + // This is a no-op after the callback has started or completed. + diagnostics?.DispatcherWaitFailed(dispatcherEnqueuedAt); + throw; + } async Task BuildImageSource() { var dispatcherStartedAt = diagnostics?.DispatcherStarted(dispatcherEnqueuedAt) ?? 0; + var suspensionStartedAt = 0L; + var continuationStartedAt = 0L; try { var bitmap = new BitmapImage(); ApplyDecodeSize(bitmap, scaledSize); - await bitmap.SetSourceAsync(bitmapStream); + var operation = bitmap.SetSourceAsync(bitmapStream); + suspensionStartedAt = diagnostics?.DispatcherUiSliceCompleted( + dispatcherStartedAt, + IconDispatcherUiSliceKind.BeforeAsyncSuspension) ?? 0; + try + { + await operation; + } + finally + { + if (suspensionStartedAt != 0) + { + continuationStartedAt = diagnostics?.DispatcherAsyncSuspensionCompleted( + suspensionStartedAt) ?? 0; + } + } + var result = new ImageIconSource { ImageSource = bitmap }; diagnostics?.SetResult(result); return result; } finally { + if (suspensionStartedAt == 0) + { + diagnostics?.DispatcherUiSliceCompleted( + dispatcherStartedAt, + IconDispatcherUiSliceKind.SynchronousCallback); + } + else if (continuationStartedAt != 0) + { + diagnostics?.DispatcherUiSliceCompleted( + continuationStartedAt, + IconDispatcherUiSliceKind.AsyncContinuation); + } + diagnostics?.DispatcherCompleted(dispatcherStartedAt); } } diff --git a/src/modules/cmdpal/Microsoft.CmdPal.UI/Microsoft.CmdPal.UI.csproj b/src/modules/cmdpal/Microsoft.CmdPal.UI/Microsoft.CmdPal.UI.csproj index 435fa8f0c1..2302688641 100644 --- a/src/modules/cmdpal/Microsoft.CmdPal.UI/Microsoft.CmdPal.UI.csproj +++ b/src/modules/cmdpal/Microsoft.CmdPal.UI/Microsoft.CmdPal.UI.csproj @@ -14,6 +14,7 @@ true enable enable + true true preview diff --git a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/AdaptiveCacheTests.cs b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/AdaptiveCacheTests.cs index cf3cd1d4dc..62520e6732 100644 --- a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/AdaptiveCacheTests.cs +++ b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/AdaptiveCacheTests.cs @@ -37,6 +37,47 @@ public class AdaptiveCacheTests Assert.AreEqual(0, cache.ApproximateCount); } + [TestMethod] + [Timeout(5_000)] + public void RemovalCallbackReportsReasonValueAndRemainingCount() + { + var removals = new ConcurrentQueue<(int Key, int Value, AdaptiveCacheRemovalReason Reason, int Count, int Capacity)>(); + var cache = new AdaptiveCache( + capacity: 1, + decayInterval: TimeSpan.FromHours(1), + removalCallback: (key, value, reason, count, capacity) => + removals.Enqueue((key, value, reason, count, capacity))); + + cache.Add(1, 101); + cache.Add(2, 202); + + Assert.IsTrue( + SpinWait.SpinUntil( + () => removals.Any(removal => removal.Reason == AdaptiveCacheRemovalReason.Capacity), + TimeSpan.FromSeconds(2)), + "Capacity removal was not reported."); + Assert.IsTrue(removals.TryPeek(out var capacityRemoval)); + Assert.AreEqual(AdaptiveCacheRemovalReason.Capacity, capacityRemoval.Reason); + Assert.AreEqual(1, capacityRemoval.Count); + Assert.AreEqual(1, capacityRemoval.Capacity); + Assert.AreEqual(capacityRemoval.Key == 1 ? 101 : 202, capacityRemoval.Value); + + var remainingKey = cache.TryGet(1, out _) ? 1 : 2; + var replacedValue = remainingKey == 1 ? 101 : 202; + cache.Add(remainingKey, 303); + Assert.IsTrue(removals.Any( + removal => + removal.Reason == AdaptiveCacheRemovalReason.Replaced && + removal.Key == remainingKey && + removal.Value == replacedValue && + removal.Count == 1)); + Assert.IsTrue(cache.TryGet(remainingKey, out var replacement)); + Assert.AreEqual(303, replacement); + + Assert.IsTrue(cache.TryRemove(remainingKey)); + Assert.IsTrue(removals.Any(removal => removal.Reason == AdaptiveCacheRemovalReason.Explicit)); + } + [TestMethod] [Timeout(15_000)] public async Task ConcurrentCleanupAndFailedLoadsKeepApproximateCountConsistent() diff --git a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadDiagnosticsTests.cs b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadDiagnosticsTests.cs index 2eb018e294..c978d50e13 100644 --- a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadDiagnosticsTests.cs +++ b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadDiagnosticsTests.cs @@ -2,6 +2,9 @@ // The Microsoft Corporation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Diagnostics.Tracing; using Microsoft.CmdPal.UI.Controls; using Microsoft.CmdPal.UI.Helpers; using Microsoft.UI.Dispatching; @@ -38,8 +41,11 @@ public class IconLoadDiagnosticsTests StartWorker(load); var preparationStartedAt = load.BeginBackgroundPreparation(); load.CompleteBackgroundPreparation(preparationStartedAt); - var dispatcherEnqueuedAt = load.BeginDispatcherWait(); + var dispatcherEnqueuedAt = load.BeginDispatcherWait(IconDispatcherMaterializationKind.Binary); var dispatcherStartedAt = load.DispatcherStarted(dispatcherEnqueuedAt); + load.DispatcherUiSliceCompleted( + dispatcherStartedAt, + IconDispatcherUiSliceKind.SynchronousCallback); load.DispatcherCompleted(dispatcherStartedAt); load.SetResult(null); load.Complete(); @@ -72,6 +78,9 @@ public class IconLoadDiagnosticsTests StringAssert.Contains(report.Text, "Empty: 1"); StringAssert.Contains(report.Text, "Maximum low queue depth: 1"); StringAssert.Contains(report.Text, "Dispatcher wait: count=1"); + StringAssert.Contains(report.Text, "Dispatcher materialization"); + StringAssert.Contains(report.Text, "Measured STA execution slices: count=1"); + StringAssert.Contains(report.Text, " Binary"); StringAssert.Contains(report.Text, "Load demand"); StringAssert.Contains(report.Text, "Requests linked to session loads: 1"); StringAssert.Contains(report.Text, " Completed: 1"); @@ -204,6 +213,126 @@ public class IconLoadDiagnosticsTests StringAssert.Contains(report.Text, "Empty: 1"); } + [TestMethod] + public void CacheReportTracksLookupsOccupancyAndRemovalReasons() + { + IconLoadDiagnostics.Start(); + var size = new global::Windows.Foundation.Size(20, 20); + IconLoadDiagnostics.RecordCacheLookup(size, capacity: 16, hit: false); + IconLoadDiagnostics.RecordCacheEntryAdded(size, capacity: 16, entryCount: 1); + IconLoadDiagnostics.RecordCacheLookup(size, capacity: 16, hit: true); + IconLoadDiagnostics.RecordCacheEntryRemoved( + size, + capacity: 16, + entryCount: 0, + AdaptiveCacheRemovalReason.Explicit); + + var report = IconLoadDiagnostics.StopAndCreateReport(); + + Assert.IsNotNull(report); + var expectedHeader = + $"Icon caches{Environment.NewLine}" + + $" Definition: each entry is a cached IconSource task; counts are approximate concurrent observations. Eviction only drops the cache reference.{Environment.NewLine}" + + $" A request coalesced with an in-flight load is a cache miss; see Provider resolution for in-flight reuse.{Environment.NewLine}" + + $" Capacity means the cache was over its limit when removal was attempted and takes precedence over LowScore; LowScore means score alone caused removal.{Environment.NewLine}" + + " 20x20, capacity 16"; + StringAssert.Contains(report.Text, expectedHeader); + StringAssert.Contains(report.Text, " Lookups: 2"); + StringAssert.Contains(report.Text, " Hits: 1"); + StringAssert.Contains(report.Text, " Misses: 1"); + StringAssert.Contains(report.Text, " Hit rate: 50 %"); + StringAssert.Contains(report.Text, " Maximum observed entries: 1"); + var expectedRemovalReason = + $" Removal reasons{Environment.NewLine}" + + " Explicit: 1"; + StringAssert.Contains(report.Text, expectedRemovalReason); + } + + [TestMethod] + public void DispatcherReportSeparatesUiExecutionFromAsyncSuspensionAndSamplesLiveDemand() + { + IconLoadDiagnostics.Start(); + var request = IconLoadDiagnostics.BeginRequest(IconRequestReason.SourceChanged, 1.0); + var load = IconLoadDiagnostics.CreateLoad( + request, + "bitmap.png", + hasStream: false, + width: 20, + height: 20, + scale: 1.0); + + Assert.IsNotNull(load); + request.RecordProviderResolution(IconProviderResolution.NewLoad, load); + load.Enqueued(IconLoadPriority.Low); + StartWorker(load); + var dispatcherEnqueuedAt = load.BeginDispatcherWait(IconDispatcherMaterializationKind.BitmapStream); + + // The enqueue is demanded, but callback phases should observe the invalidated request + // without taking the demand-state lock on the dispatcher thread. + request.Invalidate(); + var dispatcherStartedAt = load.DispatcherStarted(dispatcherEnqueuedAt); + var artificialOutlierStart = Stopwatch.GetTimestamp() - (Stopwatch.Frequency / 50); + _ = load.DispatcherUiSliceCompleted( + artificialOutlierStart, + IconDispatcherUiSliceKind.BeforeAsyncSuspension); + var continuationStartedAt = load.DispatcherAsyncSuspensionCompleted(artificialOutlierStart); + load.DispatcherUiSliceCompleted( + continuationStartedAt, + IconDispatcherUiSliceKind.AsyncContinuation); + load.DispatcherCompleted(dispatcherStartedAt); + load.SetResult(null); + load.Complete(); + request.Complete(IconRequestStatus.Stale); + + var report = IconLoadDiagnostics.StopAndCreateReport(); + + Assert.IsNotNull(report); + StringAssert.Contains(report.Text, "Dispatcher materialization"); + StringAssert.Contains(report.Text, " Enqueued demanded: 1"); + StringAssert.Contains(report.Text, " Callbacks started speculative: 1"); + StringAssert.Contains(report.Text, " Callbacks completed speculative: 1"); + StringAssert.Contains(report.Text, " Measured STA execution slices: count=2"); + StringAssert.Contains(report.Text, " Asynchronous materialization suspension: count=1"); + StringAssert.Contains(report.Text, " BitmapStream"); + StringAssert.Contains(report.Text, "phase=UiEntry"); + StringAssert.Contains(report.Text, "phase=AsyncSuspension"); + StringAssert.Contains(report.Text, "materialization=BitmapStream"); + StringAssert.Contains(report.Text, "demand=Speculative"); + } + + [TestMethod] + public void DispatcherEnqueueFailureClosesTheWaitAtCurrentDemand() + { + IconLoadDiagnostics.Start(); + var request = IconLoadDiagnostics.BeginRequest(IconRequestReason.SourceChanged, 1.0); + var load = IconLoadDiagnostics.CreateLoad( + request, + "failed.png", + hasStream: false, + width: 20, + height: 20, + scale: 1.0); + + Assert.IsNotNull(load); + request.RecordProviderResolution(IconProviderResolution.NewLoad, load); + load.Enqueued(IconLoadPriority.Low); + StartWorker(load); + var dispatcherEnqueuedAt = load.BeginDispatcherWait(IconDispatcherMaterializationKind.BitmapUri); + request.Invalidate(); + load.DispatcherWaitFailed(dispatcherEnqueuedAt); + load.Fail(); + request.Complete(IconRequestStatus.Failed); + + var report = IconLoadDiagnostics.StopAndCreateReport(); + + Assert.IsNotNull(report); + StringAssert.Contains(report.Text, " Enqueued demanded: 1"); + StringAssert.Contains(report.Text, " Dispatcher enqueue failures: 1"); + StringAssert.Contains( + report.Text, + $" Speculative{Environment.NewLine} Low-priority dispatcher wait: count=1"); + } + [TestMethod] public void StaleQueuedRequestTracksRetainedCacheUse() { @@ -605,6 +734,39 @@ public class IconLoadDiagnosticsTests Assert.IsEmpty(IconLoadDiagnostics.GetReports()); } + [TestMethod] + public void ExternalEtwListenerActivatesMeasurementsWithoutCreatingATextReport() + { + using (var listener = new EnablingEventListener()) + { + Assert.IsFalse(IconLoadDiagnostics.IsRecording); + Assert.IsNull(IconLoadDiagnostics.ActiveSessionId); + + var request = IconLoadDiagnostics.BeginRequest(IconRequestReason.SourceChanged, 1.0); + var load = IconLoadDiagnostics.CreateLoad( + request, + "icon.png", + hasStream: false, + width: 20, + height: 20, + scale: 1.0); + + Assert.IsNotNull(request.Session); + Assert.IsNotNull(load); + request.RecordProviderResolution(IconProviderResolution.NewLoad, load); + request.Invalidate(); + request.Complete(IconRequestStatus.Stale); + + CollectionAssert.Contains(listener.EventIds.ToArray(), 1); + CollectionAssert.Contains(listener.EventIds.ToArray(), 4); + } + + var inactiveRequest = IconLoadDiagnostics.BeginRequest(IconRequestReason.SourceChanged, 1.0); + Assert.IsNull(inactiveRequest.Session); + Assert.IsNull(IconLoadDiagnostics.StopAndCreateReport()); + Assert.IsEmpty(IconLoadDiagnostics.GetReports()); + } + private static int CountOccurrences(string value, string text) { var count = 0; @@ -624,4 +786,22 @@ public class IconLoadDiagnosticsTests Assert.IsTrue(workerStart.IsCompletedSuccessfully); Assert.IsTrue(workerStart.GetAwaiter().GetResult()); } + + private sealed class EnablingEventListener : EventListener + { + internal ConcurrentQueue EventIds { get; } = new(); + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "Microsoft.PowerToys.CmdPal.IconLoading") + { + EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All); + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + EventIds.Enqueue(eventData.EventId); + } + } } diff --git a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadEventSourceTests.cs b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadEventSourceTests.cs new file mode 100644 index 0000000000..9b48119eb0 --- /dev/null +++ b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/IconLoadEventSourceTests.cs @@ -0,0 +1,102 @@ +// Copyright (c) Microsoft Corporation +// The Microsoft Corporation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Collections.Concurrent; +using System.Diagnostics.Tracing; +using Microsoft.CmdPal.UI.Helpers; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Microsoft.CmdPal.UI.UnitTests; + +[TestClass] +[DoNotParallelize] +public sealed class IconLoadEventSourceTests +{ + [TestMethod] + public void EventPayloadsPreserveDeclaredTypesAndOrder() + { + using var listener = new CollectingEventListener(); + var log = IconLoadEventSource.Log; + + Assert.AreEqual(new Guid("AA068BA3-1767-5F92-7A9B-8F5DA0397413"), log.Guid); + + log.RequestStarted(11, 12, 13, 1.5); + log.ProviderResolved(11, 12, 14, 15); + log.RequestCompleted(11, 12, 16, 17); + log.LoadCreated(11, 14, 18, 19.5, 20.5, 1.25); + log.LoadEnqueued(11, 14, 21, 22); + log.LoadRejected(11, 14); + log.LoadStarted(11, 14, 23, 24); + log.LoadCompleted(11, 14, 25, 26); + log.BackgroundPreparationCompleted(11, 14, 27); + log.DispatcherWaitCompleted(11, 14, 28); + log.DispatcherWorkCompleted(11, 14, 29); + log.DirectGlyphLoadCompleted(11, 14, 30, 31); + log.ElementUpdated(11, 32, reused: true, 33); + log.RequestAttributed(11, 12, 34, 35, 36); + log.RequestInvalidated(11, 12, 14, 37, 38); + log.LoadStartedWithoutRequester(11, 14, 39); + log.LoadCompletedWithoutRequester(11, 14, 40); + log.RetainedLoadCacheHit(11, 14, 41); + log.RequestOrigin(11, 12, 42, 43, "ListItem / SingleRow"); + log.LoadQueueDemandChanged(11, 14, 44, 45, 46); + log.LoadDemandAtWorkerStart(11, 14, 1, 47, 48, 49, 4, 50); + log.DispatcherWaitFailed(11, 14, 51); + log.DispatcherUiSliceCompleted(11, 14, 52, 53, isDemanded: true, 54); + log.DispatcherAsyncSuspensionCompleted(11, 14, 55, isDemanded: false, 56); + log.UiResponsivenessProbeCompleted(11, 57); + + Assert.AreEqual(25, listener.Events.Count); + Assert.IsFalse(listener.Events.Any(e => e.EventId == 0), listener.GetEventSourceErrors()); + + CollectionAssert.AreEqual( + new object?[] { 11L, 12L, 13, 1.5 }, + listener.GetEvent(1).Payload!.ToArray()); + CollectionAssert.AreEqual( + new object?[] { 11L, 32, true, 33L }, + listener.GetEvent(13).Payload!.ToArray()); + CollectionAssert.AreEqual( + new object?[] { 11L, 12L, 42L, 43, "ListItem / SingleRow" }, + listener.GetEvent(19).Payload!.ToArray()); + CollectionAssert.AreEqual( + new object?[] { 11L, 14L, 1, 47L, 48L, 49L, 4, 50L }, + listener.GetEvent(21).Payload!.ToArray()); + CollectionAssert.AreEqual( + new object?[] { 11L, 14L, 52, 53, true, 54L }, + listener.GetEvent(35).Payload!.ToArray()); + CollectionAssert.AreEqual( + new object?[] { 11L, 14L, 55, false, 56L }, + listener.GetEvent(36).Payload!.ToArray()); + } + + private sealed class CollectingEventListener : EventListener + { + internal ConcurrentQueue Events { get; } = new(); + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "Microsoft.PowerToys.CmdPal.IconLoading") + { + EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All); + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + Events.Enqueue(eventData); + } + + internal EventWrittenEventArgs GetEvent(int eventId) + { + return Events.Single(e => e.EventId == eventId); + } + + internal string GetEventSourceErrors() + { + return string.Join( + Environment.NewLine, + Events.Where(e => e.EventId == 0).Select(e => string.Join(", ", e.Payload ?? []))); + } + } +} diff --git a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/Microsoft.CmdPal.UI.UnitTests.csproj b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/Microsoft.CmdPal.UI.UnitTests.csproj index 1ec3269bb9..e5bff9a330 100644 --- a/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/Microsoft.CmdPal.UI.UnitTests.csproj +++ b/src/modules/cmdpal/Tests/Microsoft.CmdPal.UI.UnitTests/Microsoft.CmdPal.UI.UnitTests.csproj @@ -3,6 +3,7 @@ + true false true Microsoft.CmdPal.UI.UnitTests @@ -25,7 +26,10 @@ + + +