From a6e0ea45bfbb03b2417a0fd4b316d5a0ca2f8e01 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Tue, 30 Apr 2024 17:19:19 -0700 Subject: [PATCH 1/6] Move AsyncBatchingWorkQueue usage in telemetry to TelemetryLogging level Doing this as I noticed a large (10x) difference in the number of requestcounter and requestduration events in our dashboard. These events go through the system in slightly different fashions, requestcounter goes through standard telemetry calls on disposal whereas requestduration goes through the aggregated telemetry logging. Both of these are intended to aggregate multiple calls into a single message, but the cadence at which they send telemetry differs. The requestduration method will flush both on project/VS close and every 30 minutes, whereas the requestcounter method only flushes on project/VS close. I've noticed that VS shutdown is now more abrupt than previously, often not giving our disposers a chance to send out telemetry. This is why I believe there is such a large discepency in the telemetry numbers for these methods, when they should be the same. This PR allows for the requestcounter messages to also be sent out every 30 minutes in case the disposal codepath isn't executed. --- .../Handler/RequestTelemetryLogger.cs | 13 ++++-- .../Shared/AggregatingTelemetryLog.cs | 2 - .../Shared/AggregatingTelemetryLogManager.cs | 34 +-------------- .../Telemetry/Shared/TelemetryLogProvider.cs | 8 ++-- .../Portable/Telemetry/TelemetryLogging.cs | 41 ++++++++++++++++++- 5 files changed, 55 insertions(+), 43 deletions(-) diff --git a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs index 1ff18f536c1e3..7341d04b9c5d9 100644 --- a/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs +++ b/src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs @@ -36,6 +36,8 @@ public RequestTelemetryLogger(string serverTypeName) _requestCounters = new(); _findDocumentResults = new(); _usedForkedSolutionCounter = new(); + + TelemetryLogging.Flushed += OnFlushed; } public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind) @@ -92,6 +94,14 @@ public void Dispose() return; } + // Flush all telemetry logged through TelemetryLogging + TelemetryLogging.Flush(); + + TelemetryLogging.Flushed -= OnFlushed; + } + + private void OnFlushed(object? sender, EventArgs e) + { foreach (var kvp in _requestCounters) { TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m => @@ -124,9 +134,6 @@ public void Dispose() } })); - // Flush all telemetry logged through TelemetryLogging - TelemetryLogging.Flush(); - _requestCounters.Clear(); } diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs index 042a8bb5877a1..0d398d328d9e5 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs @@ -104,8 +104,6 @@ public void Log(KeyValueLogMessage logMessage) { histogram.Record(value); } - - _aggregatingTelemetryLogManager.EnsureTelemetryWorkQueued(); } public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs index 1188da45610ee..6bb76cd0d435f 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs @@ -2,39 +2,24 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. -using System; using System.Collections.Immutable; -using System.Threading; -using System.Threading.Tasks; using Microsoft.CodeAnalysis.Internal.Log; -using Microsoft.CodeAnalysis.Shared.TestHooks; using Microsoft.VisualStudio.Telemetry; -using Roslyn.Utilities; namespace Microsoft.CodeAnalysis.Telemetry; /// -/// Manages creation and obtaining aggregated telemetry logs. Also, notifies logs to -/// send aggregated events every 30 minutes. +/// Manages creation and obtaining aggregated telemetry logs. /// internal sealed class AggregatingTelemetryLogManager { - private static readonly TimeSpan s_batchedTelemetryCollectionPeriod = TimeSpan.FromMinutes(30); - private readonly TelemetrySession _session; - private readonly AsyncBatchingWorkQueue _postTelemetryQueue; private ImmutableDictionary _aggregatingLogs = ImmutableDictionary.Empty; - public AggregatingTelemetryLogManager(TelemetrySession session, IAsynchronousOperationListener asyncListener) + public AggregatingTelemetryLogManager(TelemetrySession session) { _session = session; - - _postTelemetryQueue = new AsyncBatchingWorkQueue( - s_batchedTelemetryCollectionPeriod, - PostCollectedTelemetryAsync, - asyncListener, - CancellationToken.None); } public ITelemetryLog? GetLog(FunctionId functionId, double[]? bucketBoundaries) @@ -45,21 +30,6 @@ public AggregatingTelemetryLogManager(TelemetrySession session, IAsynchronousOpe return ImmutableInterlocked.GetOrAdd(ref _aggregatingLogs, functionId, functionId => new AggregatingTelemetryLog(_session, functionId, bucketBoundaries, this)); } - public void EnsureTelemetryWorkQueued() - { - // Ensure PostCollectedTelemetryAsync will get fired after the collection period. - _postTelemetryQueue.AddWork(); - } - - private ValueTask PostCollectedTelemetryAsync(CancellationToken token) - { - token.ThrowIfCancellationRequested(); - - Flush(); - - return ValueTaskFactory.CompletedTask; - } - public void Flush() { if (!_session.IsOptedIn) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs index 3bc330135068c..16e44077e4178 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs @@ -17,17 +17,17 @@ internal sealed class TelemetryLogProvider : ITelemetryLogProvider private readonly AggregatingTelemetryLogManager _aggregatingTelemetryLogManager; private readonly VisualStudioTelemetryLogManager _visualStudioTelemetryLogManager; - private TelemetryLogProvider(TelemetrySession session, ILogger telemetryLogger, IAsynchronousOperationListener asyncListener) + private TelemetryLogProvider(TelemetrySession session, ILogger telemetryLogger) { - _aggregatingTelemetryLogManager = new AggregatingTelemetryLogManager(session, asyncListener); + _aggregatingTelemetryLogManager = new AggregatingTelemetryLogManager(session); _visualStudioTelemetryLogManager = new VisualStudioTelemetryLogManager(session, telemetryLogger); } public static TelemetryLogProvider Create(TelemetrySession session, ILogger telemetryLogger, IAsynchronousOperationListener asyncListener) { - var logProvider = new TelemetryLogProvider(session, telemetryLogger, asyncListener); + var logProvider = new TelemetryLogProvider(session, telemetryLogger); - TelemetryLogging.SetLogProvider(logProvider); + TelemetryLogging.SetLogProvider(logProvider, asyncListener); return logProvider; } diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index b26b770f7dcf0..5844805803c25 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -3,26 +3,49 @@ // See the LICENSE file in the project root for more information. using System; +using System.Threading; +using System.Threading.Tasks; using Microsoft.CodeAnalysis.Internal.Log; +using Microsoft.CodeAnalysis.Shared.TestHooks; +using Roslyn.Utilities; namespace Microsoft.CodeAnalysis.Telemetry; /// /// Provides access to posting telemetry events or adding information -/// to aggregated telemetry events. +/// to aggregated telemetry events. Posts pending telemetry at 30 +/// minute intervals. /// internal static class TelemetryLogging { private static ITelemetryLogProvider? s_logProvider; + private static AsyncBatchingWorkQueue? s_postTelemetryQueue; public const string KeyName = "Name"; public const string KeyValue = "Value"; public const string KeyLanguageName = "LanguageName"; public const string KeyMetricName = "MetricName"; - public static void SetLogProvider(ITelemetryLogProvider logProvider) + public static event EventHandler? Flushed; + + public static void SetLogProvider(ITelemetryLogProvider logProvider, IAsynchronousOperationListener asyncListener) { s_logProvider = logProvider; + + if (s_postTelemetryQueue is null) + { + var postTelemetryQueue = new AsyncBatchingWorkQueue( + TimeSpan.FromMinutes(30), + PostCollectedTelemetryAsync, + asyncListener, + CancellationToken.None); + + if (null == Interlocked.CompareExchange(ref s_postTelemetryQueue, postTelemetryQueue, null)) + { + // We created the work queue in use. Add an item into it to kick things off. + s_postTelemetryQueue?.AddWork(); + } + } } /// @@ -112,5 +135,19 @@ public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMe public static void Flush() { s_logProvider?.Flush(); + + Flushed?.Invoke(null, EventArgs.Empty); + } + + private static ValueTask PostCollectedTelemetryAsync(CancellationToken token) + { + token.ThrowIfCancellationRequested(); + + Flush(); + + // Ensure PostCollectedTelemetryAsync will get fired again after the collection period. + s_postTelemetryQueue?.AddWork(); + + return ValueTaskFactory.CompletedTask; } } From af5271f864240aa6c825f90434fc6ad8353af267 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Tue, 30 Apr 2024 18:35:22 -0700 Subject: [PATCH 2/6] Ensure s_logProvider isn't already set --- .../Portable/Telemetry/TelemetryLogging.cs | 23 ++++++++----------- 1 file changed, 9 insertions(+), 14 deletions(-) diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index 5844805803c25..96cbde2604c8d 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -30,22 +30,17 @@ internal static class TelemetryLogging public static void SetLogProvider(ITelemetryLogProvider logProvider, IAsynchronousOperationListener asyncListener) { + Contract.ThrowIfTrue(s_logProvider != null); + s_logProvider = logProvider; - if (s_postTelemetryQueue is null) - { - var postTelemetryQueue = new AsyncBatchingWorkQueue( - TimeSpan.FromMinutes(30), - PostCollectedTelemetryAsync, - asyncListener, - CancellationToken.None); - - if (null == Interlocked.CompareExchange(ref s_postTelemetryQueue, postTelemetryQueue, null)) - { - // We created the work queue in use. Add an item into it to kick things off. - s_postTelemetryQueue?.AddWork(); - } - } + s_postTelemetryQueue = new AsyncBatchingWorkQueue( + TimeSpan.FromMinutes(30), + PostCollectedTelemetryAsync, + asyncListener, + CancellationToken.None); + + s_postTelemetryQueue?.AddWork(); } /// From 4145a2b1a132e888423e59679b295c7a7ce41960 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Tue, 30 Apr 2024 20:52:54 -0700 Subject: [PATCH 3/6] cleanup unnecessary field --- .../Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs | 4 +--- .../Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs | 2 +- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs index 0d398d328d9e5..711cf06437e77 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs @@ -28,7 +28,6 @@ internal sealed class AggregatingTelemetryLog : ITelemetryLog private readonly HistogramConfiguration? _histogramConfiguration; private readonly string _eventName; private readonly FunctionId _functionId; - private readonly AggregatingTelemetryLogManager _aggregatingTelemetryLogManager; private readonly object _flushLock; private ImmutableDictionary Histogram, TelemetryEvent TelemetryEvent, object Lock)> _histograms = ImmutableDictionary, TelemetryEvent, object)>.Empty; @@ -40,7 +39,7 @@ internal sealed class AggregatingTelemetryLog : ITelemetryLog /// Used to derive meter name /// Optional values indicating bucket boundaries in milliseconds. If not specified, /// all histograms created will use the default histogram configuration - public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, double[]? bucketBoundaries, AggregatingTelemetryLogManager aggregatingTelemetryLogManager) + public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, double[]? bucketBoundaries) { var meterName = TelemetryLogger.GetPropertyName(functionId, "meter"); var meterProvider = new VSTelemetryMeterProvider(); @@ -49,7 +48,6 @@ public AggregatingTelemetryLog(TelemetrySession session, FunctionId functionId, _meter = meterProvider.CreateMeter(meterName, version: MeterVersion); _eventName = TelemetryLogger.GetEventName(functionId); _functionId = functionId; - _aggregatingTelemetryLogManager = aggregatingTelemetryLogManager; _flushLock = new(); if (bucketBoundaries != null) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs index 6bb76cd0d435f..7daa10767e2c2 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs @@ -27,7 +27,7 @@ public AggregatingTelemetryLogManager(TelemetrySession session) if (!_session.IsOptedIn) return null; - return ImmutableInterlocked.GetOrAdd(ref _aggregatingLogs, functionId, functionId => new AggregatingTelemetryLog(_session, functionId, bucketBoundaries, this)); + return ImmutableInterlocked.GetOrAdd(ref _aggregatingLogs, functionId, functionId => new AggregatingTelemetryLog(_session, functionId, bucketBoundaries)); } public void Flush() From 4a4584163c7dcc31e8cc419a95e5aac0e79dc33f Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Tue, 30 Apr 2024 22:00:31 -0700 Subject: [PATCH 4/6] Revert back the check against s_logProvider being null as tests hit this case --- .../Portable/Telemetry/TelemetryLogging.cs | 23 +++++++++++-------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index 96cbde2604c8d..5844805803c25 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -30,17 +30,22 @@ internal static class TelemetryLogging public static void SetLogProvider(ITelemetryLogProvider logProvider, IAsynchronousOperationListener asyncListener) { - Contract.ThrowIfTrue(s_logProvider != null); - s_logProvider = logProvider; - s_postTelemetryQueue = new AsyncBatchingWorkQueue( - TimeSpan.FromMinutes(30), - PostCollectedTelemetryAsync, - asyncListener, - CancellationToken.None); - - s_postTelemetryQueue?.AddWork(); + if (s_postTelemetryQueue is null) + { + var postTelemetryQueue = new AsyncBatchingWorkQueue( + TimeSpan.FromMinutes(30), + PostCollectedTelemetryAsync, + asyncListener, + CancellationToken.None); + + if (null == Interlocked.CompareExchange(ref s_postTelemetryQueue, postTelemetryQueue, null)) + { + // We created the work queue in use. Add an item into it to kick things off. + s_postTelemetryQueue?.AddWork(); + } + } } /// From 37d041b928a975cb8a46a109d681f735e55ac207 Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Wed, 1 May 2024 06:43:00 -0700 Subject: [PATCH 5/6] Rename parameter and don't check token in non-useful case --- src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index 5844805803c25..8061177e52d8d 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -139,10 +139,8 @@ public static void Flush() Flushed?.Invoke(null, EventArgs.Empty); } - private static ValueTask PostCollectedTelemetryAsync(CancellationToken token) + private static ValueTask PostCollectedTelemetryAsync(CancellationToken cancellationToken) { - token.ThrowIfCancellationRequested(); - Flush(); // Ensure PostCollectedTelemetryAsync will get fired again after the collection period. From e5d98dd67e9d5b0a4a178b8f3c8c2914da8d7dff Mon Sep 17 00:00:00 2001 From: Todd Grunke Date: Wed, 1 May 2024 11:13:44 -0700 Subject: [PATCH 6/6] 1) Use InterlockedOperations.Initialize to simplify 2) As AddWork batches work together, no need to protect against multiple calls 3) Get rid of closure allocation in commonly called telemetry method --- .../Shared/AggregatingTelemetryLogManager.cs | 6 +++++- .../Core/Portable/Telemetry/TelemetryLogging.cs | 17 ++++++----------- 2 files changed, 11 insertions(+), 12 deletions(-) diff --git a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs index 7daa10767e2c2..2b3042e607592 100644 --- a/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs +++ b/src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs @@ -27,7 +27,11 @@ public AggregatingTelemetryLogManager(TelemetrySession session) if (!_session.IsOptedIn) return null; - return ImmutableInterlocked.GetOrAdd(ref _aggregatingLogs, functionId, functionId => new AggregatingTelemetryLog(_session, functionId, bucketBoundaries)); + return ImmutableInterlocked.GetOrAdd( + ref _aggregatingLogs, + functionId, + static (functionId, arg) => new AggregatingTelemetryLog(arg._session, functionId, arg.bucketBoundaries), + factoryArgument: (_session, bucketBoundaries)); } public void Flush() diff --git a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs index 8061177e52d8d..23aded8e6276a 100644 --- a/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs +++ b/src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs @@ -32,20 +32,15 @@ public static void SetLogProvider(ITelemetryLogProvider logProvider, IAsynchrono { s_logProvider = logProvider; - if (s_postTelemetryQueue is null) - { - var postTelemetryQueue = new AsyncBatchingWorkQueue( + InterlockedOperations.Initialize(ref s_postTelemetryQueue, () => + new AsyncBatchingWorkQueue( TimeSpan.FromMinutes(30), PostCollectedTelemetryAsync, asyncListener, - CancellationToken.None); - - if (null == Interlocked.CompareExchange(ref s_postTelemetryQueue, postTelemetryQueue, null)) - { - // We created the work queue in use. Add an item into it to kick things off. - s_postTelemetryQueue?.AddWork(); - } - } + CancellationToken.None)); + + // Add the initial item to the queue to ensure later processing. + s_postTelemetryQueue?.AddWork(); } ///