// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. // // Description: A trace logging manager for collecting debug information. // See doc comments below for more details. // // The underlying logging infrastructure does the right thing with // respect to user opt-in for CEIP. // using MS.Internal; using System.Diagnostics.Tracing; namespace System.Windows.Documents.Tracing { /// <summary> /// When a WPF process that has registered custom spellcheck dictionaries /// is killed (for e.g., when an application being debugged under Visual Studio /// is stopped using the debugger), the process does not have adequate opportunity /// to unregister all the custom dictionaries. /// /// On Windows 8.1+, this results in stale registrations that can cause perf /// problems for the underlying OS COM server that provides the ISpellChecker /// facilities. /// /// The fix for this on the ISpellChecker side is expensive, and we intend to use this /// logger to measure the extent of this problem in the ecosystem, and in turn /// determine whether a fix in ISpellChecker is warranted. /// /// Once we start getting this telemetry, we can track the deviation of /// (Sum(Registered) - Sum(Unregistered)) from zero as a measure of the size of /// the problem. /// /// We will also receive COM call times (average and instantaneous ones) which can be used /// to demonstrate the degree of the problem. These times are represented in 100ns intervals. /// For e.g., if the received value is 123456, it should be interpreted /// as 123456 * 100 ns = 12.3456 ms. /// </summary> /// <remarks> /// When this data is no longer needed, this class and all references to it /// can be safely removed. /// </remarks> internal class SpellerCOMActionTraceLogger : IDisposable { /// <summary> /// The name of the event that will be logged by this class /// </summary> private static readonly string SpellerCOMLatencyMeasurement = nameof(SpellerCOMLatencyMeasurement); /// <summary> /// Various actions that we track in this logger /// </summary> public enum Actions : int { /// <summary> /// SpellChecker Creation /// </summary> SpellCheckerCreation, /// <summary> /// Dictionary Registration /// </summary> RegisterUserDictionary, /// <summary> /// Dictionary Unregistration /// </summary> UnregisterUserDictionary, /// <summary> /// Spellcheck of text /// </summary> ComprehensiveCheck } /// <summary> /// Time limits beyond which we will log a trace as an indicator of perf problems. /// These are magic constants derived by empirical trial-and-error. /// If a call takes less than the time indicated here, that may not mean that /// the perf is ideal - it just means that the responsivness is not excessively /// compromised. /// /// If a specific call takes more than the time indicated here, we will log it. /// If the running average of a particular call exceeds twice the value in this table, /// then we will log those calls as well. /// </summary> private static readonly Dictionary<Actions, long> _timeLimits100Ns = new Dictionary<Actions, long> { {Actions.SpellCheckerCreation, 250 * 10000 }, // 250 ms {Actions.ComprehensiveCheck, 50 * 10000 }, // 50 ms {Actions.RegisterUserDictionary, 1000 * 10000 }, // 1000 ms {Actions.UnregisterUserDictionary, 1000 * 10000 } // 1000 ms }; /// <summary> /// Metadata that is associated uniquely with each instance of <see cref="WinRTSpellerInterop"/>. /// </summary> private class InstanceInfo { public Guid Id { get; set; } public Dictionary<Actions, long> CumulativeCallTime100Ns { get; set; } public Dictionary<Actions, long> NumCallsMeasured { get; set; } } /// <summary> /// A cache of persistent information represented by <see cref="InstanceInfo"/> /// uniquely associated with each <see cref="WinRTSpellerInterop"/> instance. /// </summary> private static WeakDictionary<WinRTSpellerInterop, InstanceInfo> _instanceInfos = new WeakDictionary<WinRTSpellerInterop, InstanceInfo>(); /// <summary> /// A lock object to serialize updates to <see cref="_instanceInfos"/> /// and the <see cref="InstanceInfo"/> instances contained therein. /// </summary> private static readonly object _lockObject = new object(); /// <summary> /// The current COM action being tracked /// </summary> private Actions _action; /// <summary> /// DateTime.Now.Ticks when the <see cref="_action"/> started /// </summary> private long _beginTicks; /// <summary> /// Tracking metadata associated with the instnace of <see cref="WinRTSpellerInterop"/> /// that created this instance. /// </summary> private InstanceInfo _instanceInfo; /// <summary> /// Creates a new instance of <see cref="SpellerCOMActionTraceLogger"/> and instantiates /// and associates tracking metadata (represented by <see cref="InstanceInfo"/>. /// /// This constructer should usually be called within a using block /// </summary> /// <param name="caller"/> /// <param name="action"/> public SpellerCOMActionTraceLogger(WinRTSpellerInterop caller, Actions action) { _action = action; InstanceInfo instanceInfo = null; lock (_lockObject) { if (!_instanceInfos.TryGetValue(caller, out instanceInfo)) { instanceInfo = new InstanceInfo { Id = Guid.NewGuid(), CumulativeCallTime100Ns = new Dictionary<Actions, long>(), NumCallsMeasured = new Dictionary<Actions, long>() }; foreach (Actions a in Enum.GetValues<Actions>()) { instanceInfo.CumulativeCallTime100Ns.Add(a, 0); instanceInfo.NumCallsMeasured.Add(a, 0); } _instanceInfos.Add(caller, instanceInfo); } } _instanceInfo = instanceInfo; _beginTicks = DateTime.Now.Ticks; } /// <summary> /// Does the actual work of logging information /// </summary> /// <remarks> /// We do not want a failure in this method to affect callers - so we /// catch and suppress all exceptions /// /// Skipping overflow checks in this method because long.MaxValue*100 ns ~= 29k years /// </remarks> /// <param name="endTicks"></param> [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Design", "CA1031:DoNotCatchGeneralExceptionTypes")] private void UpdateRunningAverageAndLogDebugInfo(long endTicks) { try { long ticks = (endTicks - _beginTicks); lock (_lockObject) { _instanceInfo.NumCallsMeasured[_action]++; _instanceInfo.CumulativeCallTime100Ns[_action] += ticks; } long runningAverage = (long)Math.Floor(1.0d * _instanceInfo.CumulativeCallTime100Ns[_action] / _instanceInfo.NumCallsMeasured[_action]); // Always log dictionary register/unregister events // Log SpellChecker creation and ComprehensiveCheck if // runningAverage > _timeout100Ns bool alwaysLog = (_action == Actions.RegisterUserDictionary) || (_action == Actions.UnregisterUserDictionary); if (alwaysLog || (ticks > _timeLimits100Ns[_action]) || (runningAverage > 2 * _timeLimits100Ns[_action])) { var logger = MS.Internal.Telemetry.PresentationFramework.TraceLoggingProvider.GetProvider(); var eventSourceOptions = MS.Internal.Telemetry.PresentationFramework.TelemetryEventSource.MeasuresOptions(); // Convert 100 ns units to ms // 1 * 100 ns = (1 * 100 / 1000000) ms = (1/10000) ms var traceData = new SpellerCOMTimingData { TextBoxBaseIdentifier = _instanceInfo.Id.ToString(), SpellerCOMAction = _action.ToString(), CallTimeForCOMCallMs = (long)Math.Floor(ticks * 1.0d / 10000), RunningAverageCallTimeForCOMCallsMs = (long)Math.Floor(runningAverage * 1.0d / 10000) }; logger?.Write<SpellerCOMTimingData>(SpellerCOMLatencyMeasurement, eventSourceOptions, traceData); } } catch { // Catch all exceptions - do not propagate any to the caller } } #region IDisposable Support private bool _disposed = false; // To detect redundant calls protected virtual void Dispose(bool disposing) { if (!_disposed) { if (disposing) { UpdateRunningAverageAndLogDebugInfo(endTicks: DateTime.Now.Ticks); } _disposed = true; } } public void Dispose() { Dispose(true); } #endregion /// <summary> /// Structure encoding data needed to track dictionary COM actions /// </summary> [EventData] private struct SpellerCOMTimingData { /// <summary> /// An identifier that will allow us to group /// the data by a given TextBoxBase instance /// </summary> /// <remarks> /// We maintain a 1:1 correspondence between a WinRTSpellerInterop /// instance and a <see cref="InstanceInfo"/> instance by means /// of the static <see cref="_instanceInfos"/> WeakDictionary. /// /// Usually (though not always), TextBoxBase instances that have /// SpellCheck.IsEnabled = true are associated with a single /// WinRTSpellerInterop instance. At the time of logging telemetry, /// we will use the <see cref="InstanceInfo.Id"/> Guid field as an /// identifier for a TextBoxBase instance and use its stringized /// representation to initialize this property. /// /// During analysis of logs collected from this logger in the backend, /// data can be grouped by this value to get an overview of perf characteristics /// encountered by individual TextBoxBase instances. /// </remarks> public string TextBoxBaseIdentifier { get; set; } /// <summary> /// The speller COM action. This value /// can be "RegisterUserDictionary", "UnregisterUserDictionary", or "ComprehensiveCheck" /// </summary> public string SpellerCOMAction { get; set; } /// <summary> /// The call time (into COM) for this dictionary action /// </summary> public long CallTimeForCOMCallMs { get; set; } /// <summary> /// The current running average call time for all COM calls being tracked in 100ns units /// </summary> public long RunningAverageCallTimeForCOMCallsMs { get; set; } } } }