Add CmdPal icon loading observer foundation

This commit is contained in:
Jiří Polášek
2026-08-17 19:30:35 +02:00
parent bbaaad001b
commit fd4244ede7
15 changed files with 1690 additions and 42 deletions

View File

@@ -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,
}

View File

@@ -19,6 +19,7 @@ internal sealed class AdaptiveCache<TKey, TValue>
private readonly int _capacity;
private readonly double _decayFactor;
private readonly TimeSpan _decayInterval;
private readonly Action<TKey, TValue, AdaptiveCacheRemovalReason, int, int>? _removalCallback;
private readonly ConcurrentDictionary<TKey, CacheEntry> _map;
private readonly ConcurrentStack<CacheEntry> _pool = [];
@@ -33,11 +34,16 @@ internal sealed class AdaptiveCache<TKey, TValue>
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<TKey, TValue, AdaptiveCacheRemovalReason, int, int>? removalCallback = null)
{
_capacity = capacity;
_decayInterval = decayInterval ?? TimeSpan.FromMinutes(5);
_decayFactor = decayFactor;
_removalCallback = removalCallback;
_map = new ConcurrentDictionary<TKey, CacheEntry>(Environment.ProcessorCount, capacity);
_maintenanceCallback = static state =>
@@ -115,6 +121,12 @@ internal sealed class AdaptiveCache<TKey, TValue>
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<TKey, TValue>
}
}
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<TKey, TValue>
// 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<TKey, TValue>
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);
}
}
}

View File

@@ -15,13 +15,18 @@ internal sealed class CachedIconSourceProvider : IIconSourceProvider
private readonly AdaptiveCache<IconCacheKey, Task<IconSource?>> _cache;
private readonly ConcurrentDictionary<IconCacheKey, Task<IconSource?>> _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<IconCacheKey, Task<IconSource?>>(cacheSize, TimeSpan.FromMinutes(60));
_cacheSize = cacheSize;
_cache = new AdaptiveCache<IconCacheKey, Task<IconSource?>>(
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<IconSource?> task,
AdaptiveCacheRemovalReason reason,
int remainingCount,
int capacity)
{
_ = key;
_ = task;
IconLoadDiagnostics.RecordCacheEntryRemoved(
_iconSize,
capacity,
remainingCount,
reason);
}
private readonly struct IconCacheKey : IEquatable<IconCacheKey>
{
private readonly string? _icon;

View File

@@ -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,
}

View File

@@ -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,
}

View File

@@ -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<IconLoadDiagnosticsReport> 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))

View File

@@ -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<DispatcherOutlierSample> _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<Task<IconSource?>, IconLoadMeasurement> _loadsByTask = new();
private readonly ConcurrentDictionary<CacheDescriptor, CacheMeasurements> _cacheMeasurements = new();
private readonly ConcurrentDictionary<long, RequestDemandState> _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<IconDispatcherUiSliceKind>();
for (var i = 0; i < sliceKinds.Length; i++)
{
_dispatcherUiExecutionLatencyBySliceKind[i].Append(builder, sliceKinds[i].ToString(), " ");
}
builder.AppendLine(" By materialization kind");
var materializationKinds = Enum.GetValues<IconDispatcherMaterializationKind>();
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<AdaptiveCacheRemovalReason>(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<IconDispatcherUiSliceKind>().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<IconDispatcherMaterializationKind>().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<IconProviderResolution>().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<AdaptiveCacheRemovalReason>().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)

View File

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

View File

@@ -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<bool>? _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)

View File

@@ -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<IconSource?> 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);
}
}

View File

@@ -14,6 +14,7 @@
<EnableMsixTooling>true</EnableMsixTooling>
<ImplicitUsings>enable</ImplicitUsings>
<Nullable>enable</Nullable>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<WindowsAppSDKSelfContained>true</WindowsAppSDKSelfContained>
<LangVersion>preview</LangVersion>

View File

@@ -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<int, int>(
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()

View File

@@ -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<int> 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);
}
}
}

View File

@@ -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<EventWrittenEventArgs> 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 ?? [])));
}
}
}

View File

@@ -3,6 +3,7 @@
<Import Project="$(RepoRoot)src\Common.Dotnet.CsWinRT.props" />
<PropertyGroup>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<IsPackable>false</IsPackable>
<IsTestProject>true</IsTestProject>
<RootNamespace>Microsoft.CmdPal.UI.UnitTests</RootNamespace>
@@ -25,7 +26,10 @@
<ItemGroup>
<Compile Include="..\..\Microsoft.CmdPal.UI\Controls\IconRequestSite.cs" Link="Controls\IconRequestSite.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\AdaptiveCache`2.cs" Link="Helpers\AdaptiveCache`2.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\AdaptiveCacheRemovalReason.cs" Link="Helpers\AdaptiveCacheRemovalReason.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\CachedIconSourceProvider.cs" Link="Helpers\Icons\CachedIconSourceProvider.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\IconDispatcherMaterializationKind.cs" Link="Helpers\Icons\IconDispatcherMaterializationKind.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\IconDispatcherUiSliceKind.cs" Link="Helpers\Icons\IconDispatcherUiSliceKind.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\IconLoadDemandStage.cs" Link="Helpers\Icons\IconLoadDemandStage.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\IconLoadDiagnostics.cs" Link="Helpers\Icons\IconLoadDiagnostics.cs" />
<Compile Include="..\..\Microsoft.CmdPal.UI\Helpers\Icons\IconLoadDiagnosticsReport.cs" Link="Helpers\Icons\IconLoadDiagnosticsReport.cs" />