Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Move AsyncBatchingWorkQueue usage in telemetry to TelemetryLogging level #73287

Merged
merged 6 commits into from
May 1, 2024
Merged

Move AsyncBatchingWorkQueue usage in telemetry to TelemetryLogging level #73287

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
a6e0ea4
Move AsyncBatchingWorkQueue usage in telemetry to TelemetryLogging level
ToddGrun May 1, 2024
af5271f
Ensure s_logProvider isn't already set
ToddGrun May 1, 2024
4145a2b
cleanup unnecessary field
ToddGrun May 1, 2024
4a45841
Revert back the check against s_logProvider being null as tests hit t…
ToddGrun May 1, 2024
37d041b
Rename parameter and don't check token in non-useful case
ToddGrun May 1, 2024
e5d98dd
1) Use InterlockedOperations.Initialize to simplify
ToddGrun May 1, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 10 additions & 3 deletions src/Features/LanguageServer/Protocol/Handler/RequestTelemetryLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,8 @@ public RequestTelemetryLogger(string serverTypeName)
_requestCounters = new();
_findDocumentResults = new();
_usedForkedSolutionCounter = new();

TelemetryLogging.Flushed += OnFlushed;
}

public void UpdateFindDocumentTelemetryData(bool success, string? workspaceKind)
Expand Down Expand Up @@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't remember if the queries are resilient to multiple events for the same server for the same session. I assume they are since I don't think we drill down into the session in particular, but I can't remember.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The queries that I know don't drill into the session, so they are resilient. If we find some that do use the session, it seems feasible to change them to allow multiple items from a session.

{
foreach (var kvp in _requestCounters)
{
TelemetryLogging.Log(FunctionId.LSP_RequestCounter, KeyValueLogMessage.Create(LogType.Trace, m =>
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was trying to figure out why these didn't use TelemetryLogging.LogAggregated - but its because we're not using a bucket based aggregation here right? We're just logging pure sums.

Wondering if we should have another variant of the LogAggregated that does a sum or something. But maybe a change for a later date.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that's exactly right. I considered that as part of this, but it seemed like overkill for now. Especially, as I know we have more upcoming work in this area as part of potentially moving towards OTel.

Expand Down Expand Up @@ -124,9 +134,6 @@ public void Dispose()
}
}));

// Flush all telemetry logged through TelemetryLogging
TelemetryLogging.Flush();

_requestCounters.Clear();
}

Expand Down
6 changes: 1 addition & 5 deletions src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLog.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<string, (IHistogram<long> Histogram, TelemetryEvent TelemetryEvent, object Lock)> _histograms = ImmutableDictionary<string, (IHistogram<long>, TelemetryEvent, object)>.Empty;
Expand All @@ -40,7 +39,7 @@ internal sealed class AggregatingTelemetryLog : ITelemetryLog
/// <param name="functionId">Used to derive meter name</param>
/// <param name="bucketBoundaries">Optional values indicating bucket boundaries in milliseconds. If not specified,
/// all histograms created will use the default histogram configuration</param>
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();
Expand All @@ -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)
Expand Down Expand Up @@ -104,8 +102,6 @@ public void Log(KeyValueLogMessage logMessage)
{
histogram.Record(value);
}

_aggregatingTelemetryLogManager.EnsureTelemetryWorkQueued();
}

public IDisposable? LogBlockTime(KeyValueLogMessage logMessage, int minThresholdMs)
Expand Down
40 changes: 7 additions & 33 deletions src/VisualStudio/Core/Def/Telemetry/Shared/AggregatingTelemetryLogManager.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,62 +2,36 @@
// 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;

/// <summary>
/// Manages creation and obtaining aggregated telemetry logs. Also, notifies logs to
/// send aggregated events every 30 minutes.
/// Manages creation and obtaining aggregated telemetry logs.
/// </summary>
internal sealed class AggregatingTelemetryLogManager
{
private static readonly TimeSpan s_batchedTelemetryCollectionPeriod = TimeSpan.FromMinutes(30);

private readonly TelemetrySession _session;
private readonly AsyncBatchingWorkQueue _postTelemetryQueue;

private ImmutableDictionary<FunctionId, AggregatingTelemetryLog> _aggregatingLogs = ImmutableDictionary<FunctionId, AggregatingTelemetryLog>.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)
{
if (!_session.IsOptedIn)
return null;

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;
return ImmutableInterlocked.GetOrAdd(
ref _aggregatingLogs,
functionId,
static (functionId, arg) => new AggregatingTelemetryLog(arg._session, functionId, arg.bucketBoundaries),
factoryArgument: (_session, bucketBoundaries));
}

public void Flush()
Expand Down
8 changes: 4 additions & 4 deletions src/VisualStudio/Core/Def/Telemetry/Shared/TelemetryLogProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
34 changes: 32 additions & 2 deletions src/Workspaces/Core/Portable/Telemetry/TelemetryLogging.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,26 +3,44 @@
// 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;

/// <summary>
/// Provides access to posting telemetry events or adding information
/// to aggregated telemetry events.
/// to aggregated telemetry events. Posts pending telemetry at 30
/// minute intervals.
/// </summary>
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<EventArgs>? Flushed;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what is the event for?

Copy link
Contributor Author

@ToddGrun ToddGrun May 1, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

RequestTelemetryLogger not only uses TelemetryLogging for aggregated telemetry, but also accumulation it's own counts that it will send to telemetry itself.

RequestTelemetryLogger uses Dispose to both notify this object to Flush and also handles firing the telemetry counts it is accumulating. However, Dispose isn't a reliable mechanism by which to fire telemetry, as the process might be terminated before we get the opportunity to act.

To handle that, the aggregating telemetry code previously fired off telemetry every 30 minutes, using an ABWQ. This PR moves that out to the TelemetryLogging level, but it's still not hooked into the telemetry that fires due to the accounting in RequestTelemetryLogger.

This event allows RequestTelemetryLogger to hook into when that ABWQ derived telemetry firing is happening, and when it does RequestTelemetryLogger can fire off the telemetry that it is accounting for.


public static void SetLogProvider(ITelemetryLogProvider logProvider, IAsynchronousOperationListener asyncListener)
{
s_logProvider = logProvider;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this throw if there's already a log provider?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done!

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undid as it caused test failures


InterlockedOperations.Initialize(ref s_postTelemetryQueue, () =>
new AsyncBatchingWorkQueue(
TimeSpan.FromMinutes(30),
PostCollectedTelemetryAsync,
asyncListener,
CancellationToken.None));

// Add the initial item to the queue to ensure later processing.
s_postTelemetryQueue?.AddWork();
}

/// <summary>
Expand Down Expand Up @@ -112,5 +130,17 @@ public static void LogAggregated(FunctionId functionId, KeyValueLogMessage logMe
public static void Flush()
{
s_logProvider?.Flush();

Flushed?.Invoke(null, EventArgs.Empty);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not quite sure i get the point of the events.

}

private static ValueTask PostCollectedTelemetryAsync(CancellationToken cancellationToken)
{
Flush();

// Ensure PostCollectedTelemetryAsync will get fired again after the collection period.
s_postTelemetryQueue?.AddWork();

return ValueTaskFactory.CompletedTask;
}
}
Loading