Skip to content

Commit

Permalink
Merge pull request #61669 from jasonmalinowski/log-aggregator-cleanups
Browse files Browse the repository at this point in the history
Cleanups for our logging helpers
  • Loading branch information
jasonmalinowski authored Jun 14, 2022
2 parents ff8175f + 42c5e0a commit 1c13b39
Show file tree
Hide file tree
Showing 27 changed files with 302 additions and 256 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -2,15 +2,16 @@
// 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 Microsoft.CodeAnalysis.Internal.Log;

namespace Microsoft.CodeAnalysis.Editor.Implementation.IntelliSense.AsyncCompletion
{
internal static class AsyncCompletionLogger
{
private static readonly LogAggregator s_logAggregator = new();
private static readonly StatisticLogAggregator s_statisticLogAggregator = new();
private static readonly HistogramLogAggregator s_histogramLogAggregator = new(25, 500);
private static readonly CountLogAggregator<ActionInfo> s_countLogAggregator = new();
private static readonly StatisticLogAggregator<ActionInfo> s_statisticLogAggregator = new();
private static readonly HistogramLogAggregator<ActionInfo> s_histogramLogAggregator = new(25, 500);

private enum ActionInfo
{
Expand Down Expand Up @@ -44,60 +45,60 @@ private enum ActionInfo

internal static void LogImportCompletionGetContext(bool isBlocking, bool delayed)
{
s_logAggregator.IncreaseCount((int)ActionInfo.SessionWithTypeImportCompletionEnabled);
s_countLogAggregator.IncreaseCount(ActionInfo.SessionWithTypeImportCompletionEnabled);

if (isBlocking)
s_logAggregator.IncreaseCount((int)ActionInfo.SessionWithImportCompletionBlocking);
s_countLogAggregator.IncreaseCount(ActionInfo.SessionWithImportCompletionBlocking);

if (delayed)
s_logAggregator.IncreaseCount((int)ActionInfo.SessionWithImportCompletionDelayed);
s_countLogAggregator.IncreaseCount(ActionInfo.SessionWithImportCompletionDelayed);
}

internal static void LogSessionWithDelayedImportCompletionIncludedInUpdate() =>
s_logAggregator.IncreaseCount((int)ActionInfo.SessionWithDelayedImportCompletionIncludedInUpdate);
s_countLogAggregator.IncreaseCount(ActionInfo.SessionWithDelayedImportCompletionIncludedInUpdate);

internal static void LogAdditionalTicksToCompleteDelayedImportCompletionDataPoint(int count) =>
s_histogramLogAggregator.IncreaseCount((int)ActionInfo.AdditionalTicksToCompleteDelayedImportCompletion, count);
internal static void LogAdditionalTicksToCompleteDelayedImportCompletionDataPoint(TimeSpan timeSpan) =>
s_histogramLogAggregator.LogTime(ActionInfo.AdditionalTicksToCompleteDelayedImportCompletion, timeSpan);

internal static void LogDelayedImportCompletionIncluded() =>
s_logAggregator.IncreaseCount((int)ActionInfo.SessionWithTypeImportCompletionEnabled);
s_countLogAggregator.IncreaseCount(ActionInfo.SessionWithTypeImportCompletionEnabled);

internal static void LogExpanderUsage() =>
s_logAggregator.IncreaseCount((int)ActionInfo.ExpanderUsageCount);
s_countLogAggregator.IncreaseCount(ActionInfo.ExpanderUsageCount);

internal static void LogGetDefaultsMatchTicksDataPoint(int count) =>
s_statisticLogAggregator.AddDataPoint((int)ActionInfo.GetDefaultsMatchTicks, count);
s_statisticLogAggregator.AddDataPoint(ActionInfo.GetDefaultsMatchTicks, count);

internal static void LogSourceInitializationTicksDataPoint(int count)
internal static void LogSourceInitializationTicksDataPoint(TimeSpan elapsed)
{
s_statisticLogAggregator.AddDataPoint((int)ActionInfo.SourceInitializationTicks, count);
s_histogramLogAggregator.IncreaseCount((int)ActionInfo.SourceInitializationTicks, count);
s_statisticLogAggregator.AddDataPoint(ActionInfo.SourceInitializationTicks, elapsed);
s_histogramLogAggregator.LogTime(ActionInfo.SourceInitializationTicks, elapsed);
}

internal static void LogSourceGetContextTicksDataPoint(int count, bool isCanceled)
internal static void LogSourceGetContextTicksDataPoint(TimeSpan elapsed, bool isCanceled)
{
var key = isCanceled
? ActionInfo.SourceGetContextCanceledTicks
: ActionInfo.SourceGetContextCompletedTicks;

s_statisticLogAggregator.AddDataPoint((int)key, count);
s_histogramLogAggregator.IncreaseCount((int)key, count);
s_statisticLogAggregator.AddDataPoint(key, elapsed);
s_histogramLogAggregator.LogTime(key, elapsed);
}

internal static void LogItemManagerSortTicksDataPoint(int count)
internal static void LogItemManagerSortTicksDataPoint(TimeSpan elapsed)
{
s_statisticLogAggregator.AddDataPoint((int)ActionInfo.ItemManagerSortTicks, count);
s_histogramLogAggregator.IncreaseCount((int)ActionInfo.ItemManagerSortTicks, count);
s_statisticLogAggregator.AddDataPoint(ActionInfo.ItemManagerSortTicks, elapsed);
s_histogramLogAggregator.LogTime(ActionInfo.ItemManagerSortTicks, elapsed);
}

internal static void LogItemManagerUpdateDataPoint(int count, bool isCanceled)
internal static void LogItemManagerUpdateDataPoint(TimeSpan elapsed, bool isCanceled)
{
var key = isCanceled
? ActionInfo.ItemManagerUpdateCanceledTicks
: ActionInfo.ItemManagerUpdateCompletedTicks;

s_statisticLogAggregator.AddDataPoint((int)key, count);
s_histogramLogAggregator.IncreaseCount((int)key, count);
s_statisticLogAggregator.AddDataPoint(key, elapsed);
s_histogramLogAggregator.LogTime(key, elapsed);
}

internal static void ReportTelemetry()
Expand All @@ -106,7 +107,7 @@ internal static void ReportTelemetry()
{
foreach (var kv in s_statisticLogAggregator)
{
var info = ((ActionInfo)kv.Key).ToString("f");
var info = kv.Key.ToString("f");
var statistics = kv.Value.GetStatisticResult();

m[CreateProperty(info, nameof(StatisticResult.Maximum))] = statistics.Maximum;
Expand All @@ -116,15 +117,15 @@ internal static void ReportTelemetry()
m[CreateProperty(info, nameof(StatisticResult.Count))] = statistics.Count;
}

foreach (var kv in s_logAggregator)
foreach (var kv in s_countLogAggregator)
{
var mergeInfo = ((ActionInfo)kv.Key).ToString("f");
var mergeInfo = kv.Key.ToString("f");
m[mergeInfo] = kv.Value.GetCount();
}

foreach (var kv in s_histogramLogAggregator)
{
var info = ((ActionInfo)kv.Key).ToString("f");
var info = kv.Key.ToString("f");
m[$"{info}.BucketSize"] = kv.Value.BucketSize;
m[$"{info}.MaxBucketValue"] = kv.Value.MaxBucketValue;
m[$"{info}.Buckets"] = kv.Value.GetBucketsAsString();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -143,7 +143,7 @@ public AsyncCompletionData.CompletionStartData InitializeCompletion(
}
finally
{
AsyncCompletionLogger.LogSourceInitializationTicksDataPoint((int)stopwatch.Elapsed.TotalMilliseconds);
AsyncCompletionLogger.LogSourceInitializationTicksDataPoint(stopwatch.Elapsed);
}
}

Expand Down Expand Up @@ -311,7 +311,7 @@ public async Task<VSCompletionContext> GetCompletionContextAsync(
// There could be a race around the usage of this stopwatch, I ignored it since we just need a rough idea:
// we always log the time even if the stopwatch's not started regardless of whether expand items are included intially
// (that number can be obtained via another property.)
AsyncCompletionLogger.LogAdditionalTicksToCompleteDelayedImportCompletionDataPoint((int)stopwatch.ElapsedMilliseconds);
AsyncCompletionLogger.LogAdditionalTicksToCompleteDelayedImportCompletionDataPoint(stopwatch.Elapsed);

return result;
}, cancellationToken);
Expand Down Expand Up @@ -346,7 +346,7 @@ public async Task<VSCompletionContext> GetCompletionContextAsync(
}
finally
{
AsyncCompletionLogger.LogSourceGetContextTicksDataPoint((int)totalStopWatch.Elapsed.TotalMilliseconds, isCanceled: cancellationToken.IsCancellationRequested);
AsyncCompletionLogger.LogSourceGetContextTicksDataPoint(totalStopWatch.Elapsed, isCanceled: cancellationToken.IsCancellationRequested);
}

static VSCompletionContext CombineCompletionContext(VSCompletionContext context1, VSCompletionContext context2)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ public Task<ImmutableArray<VSCompletionItem>> SortCompletionListAsync(

// Sort by default comparer of Roslyn CompletionItem
var sortedItems = data.InitialList.OrderBy(CompletionItemData.GetOrAddDummyRoslynItem).ToImmutableArray();
AsyncCompletionLogger.LogItemManagerSortTicksDataPoint((int)stopwatch.Elapsed.TotalMilliseconds);
AsyncCompletionLogger.LogItemManagerSortTicksDataPoint(stopwatch.Elapsed);
return Task.FromResult(sortedItems);
}

Expand Down Expand Up @@ -101,7 +101,7 @@ public Task<ImmutableArray<VSCompletionItem>> SortCompletionListAsync(
}
finally
{
AsyncCompletionLogger.LogItemManagerUpdateDataPoint((int)stopwatch.Elapsed.TotalMilliseconds, isCanceled: cancellationToken.IsCancellationRequested);
AsyncCompletionLogger.LogItemManagerUpdateDataPoint(stopwatch.Elapsed, isCanceled: cancellationToken.IsCancellationRequested);
}
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -427,7 +427,7 @@ private static async Task<ImmutableArray<ReferencedSymbol>> FindChangeSignatureR
}

telemetryTimer.Stop();
ChangeSignatureLogger.LogCommitInformation(telemetryNumberOfDeclarationsToUpdate, telemetryNumberOfReferencesToUpdate, (int)telemetryTimer.ElapsedMilliseconds);
ChangeSignatureLogger.LogCommitInformation(telemetryNumberOfDeclarationsToUpdate, telemetryNumberOfReferencesToUpdate, telemetryTimer.Elapsed);

return (currentSolution, confirmationMessage);
}
Expand Down
Loading

0 comments on commit 1c13b39

Please sign in to comment.