From c2fd8bcd541c2b0ea4bd7759f2d9cff596e9dba7 Mon Sep 17 00:00:00 2001 From: Andrew Hall Date: Mon, 11 Nov 2024 20:43:40 -0800 Subject: [PATCH 1/5] Fix request duration logging --- .../Telemetry/AggregatingTelemetryLog.cs | 8 ++++---- .../Telemetry/TelemetryReporter.cs | 12 ++++++------ 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs index 1956d5e0853..dbf051fa84e 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs @@ -54,20 +54,20 @@ public AggregatingTelemetryLog(TelemetryReporter reporter, string name, double[] /// Adds aggregated information for the metric and value passed in via . The Name/Value properties /// are used as the metric name and value to record. /// - public void Log(string name, + public void Log(string keyName, int value, - string metricName, string method) { if (!IsEnabled) return; - (var histogram, _, var histogramLock) = ImmutableInterlocked.GetOrAdd(ref _histograms, name, name => + (var histogram, _, var histogramLock) = ImmutableInterlocked.GetOrAdd(ref _histograms, keyName, keyName => { var telemetryEvent = new TelemetryEvent(_eventName); + TelemetryReporter.AddToProperties(telemetryEvent.Properties, new Property("method", method)); - var histogram = _meter.CreateHistogram(metricName, _histogramConfiguration); + var histogram = _meter.CreateHistogram(keyName, _histogramConfiguration); var histogramLock = new object(); return (histogram, telemetryEvent, histogramLock); diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs index f7ba0c64b1c..f4c6cc576bc 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs @@ -475,13 +475,13 @@ private void Flush() public void LogRequestTelemetry(string name, string? language, TimeSpan queuedDuration, TimeSpan requestDuration, TelemetryResult result) { LogAggregated("LSP_TimeInQueue", + "", // All time in queue events use the same histogram, no need for separate keys (int)queuedDuration.TotalMilliseconds, - "TimeInQueue", name); LogAggregated("LSP_RequestDuration", + name, // RequestDuration requests are histogrammed by their unique name (int)requestDuration.TotalMilliseconds, - "RequestDuration", name); _requestCounters.GetOrAdd((name, language), (_) => new Counter()).IncrementCount(result); @@ -503,13 +503,13 @@ private void LogRequestCounters() } private void LogAggregated( - string name, + string eventName, + string keyName, int value, - string metricName, string method) { - var aggregatingLog = _aggregatingManager?.GetLog(name); - aggregatingLog?.Log(name, value, metricName, method); + var aggregatingLog = _aggregatingManager?.GetLog(eventName); + aggregatingLog?.Log(keyName, value, method); } private sealed class Counter From feab17aa4b9658827c078888b471e85b72a9a80a Mon Sep 17 00:00:00 2001 From: Andrew Hall Date: Mon, 11 Nov 2024 20:47:35 -0800 Subject: [PATCH 2/5] Naming --- .../Telemetry/AggregatingTelemetryLog.cs | 6 +++--- .../Telemetry/TelemetryReporter.cs | 8 ++++---- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs index dbf051fa84e..ec31fe5a81b 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs @@ -54,20 +54,20 @@ public AggregatingTelemetryLog(TelemetryReporter reporter, string name, double[] /// Adds aggregated information for the metric and value passed in via . The Name/Value properties /// are used as the metric name and value to record. /// - public void Log(string keyName, + public void Log(string histogramKey, int value, string method) { if (!IsEnabled) return; - (var histogram, _, var histogramLock) = ImmutableInterlocked.GetOrAdd(ref _histograms, keyName, keyName => + (var histogram, _, var histogramLock) = ImmutableInterlocked.GetOrAdd(ref _histograms, histogramKey, histogramKey => { var telemetryEvent = new TelemetryEvent(_eventName); TelemetryReporter.AddToProperties(telemetryEvent.Properties, new Property("method", method)); - var histogram = _meter.CreateHistogram(keyName, _histogramConfiguration); + var histogram = _meter.CreateHistogram(histogramKey, _histogramConfiguration); var histogramLock = new object(); return (histogram, telemetryEvent, histogramLock); diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs index f4c6cc576bc..37c7d2be6d2 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs @@ -503,13 +503,13 @@ private void LogRequestCounters() } private void LogAggregated( - string eventName, - string keyName, + string managerKey, + string histogramKey, int value, string method) { - var aggregatingLog = _aggregatingManager?.GetLog(eventName); - aggregatingLog?.Log(keyName, value, method); + var aggregatingLog = _aggregatingManager?.GetLog(managerKey); + aggregatingLog?.Log(histogramKey, value, method); } private sealed class Counter From 3ef4b5dedde132e7e03cac08e80f2e08084c3e57 Mon Sep 17 00:00:00 2001 From: Andrew Hall Date: Mon, 11 Nov 2024 21:06:05 -0800 Subject: [PATCH 3/5] Fix xml summary and some indendation --- .../Telemetry/AggregatingTelemetryLog.cs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs index ec31fe5a81b..8b1326daa8c 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/AggregatingTelemetryLog.cs @@ -51,10 +51,11 @@ public AggregatingTelemetryLog(TelemetryReporter reporter, string name, double[] } /// - /// Adds aggregated information for the metric and value passed in via . The Name/Value properties - /// are used as the metric name and value to record. + /// Adds aggregated information for the and . Method name is tacked onto + /// to the first used for convenience. /// - public void Log(string histogramKey, + public void Log( + string histogramKey, int value, string method) { From fb154ac5501362ee237294a66aa213d5af86eddd Mon Sep 17 00:00:00 2001 From: Andrew Hall Date: Tue, 12 Nov 2024 14:50:17 -0800 Subject: [PATCH 4/5] Unit testing doing unit testing things --- .../Telemetry/TelemetryReporterTests.cs | 64 ++++++++++++++++++- 1 file changed, 62 insertions(+), 2 deletions(-) diff --git a/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs b/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs index f718a5d4c8f..f3fcf2e270d 100644 --- a/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs +++ b/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs @@ -415,6 +415,27 @@ public void ReportHistogram() TimeSpan.FromMilliseconds(300), AspNetCore.Razor.Telemetry.TelemetryResult.Failed); + reporter.ReportRequestTiming( + Methods.TextDocumentCompletionName, + WellKnownLspServerKinds.RazorLspServer.GetContractName(), + TimeSpan.FromMilliseconds(100), + TimeSpan.FromMilliseconds(100), + AspNetCore.Razor.Telemetry.TelemetryResult.Succeeded); + + reporter.ReportRequestTiming( + Methods.TextDocumentCompletionName, + WellKnownLspServerKinds.RazorLspServer.GetContractName(), + TimeSpan.FromMilliseconds(200), + TimeSpan.FromMilliseconds(200), + AspNetCore.Razor.Telemetry.TelemetryResult.Cancelled); + + reporter.ReportRequestTiming( + Methods.TextDocumentCompletionName, + WellKnownLspServerKinds.RazorLspServer.GetContractName(), + TimeSpan.FromMilliseconds(300), + TimeSpan.FromMilliseconds(300), + AspNetCore.Razor.Telemetry.TelemetryResult.Failed); + reporter.Dispose(); // Assert @@ -422,7 +443,7 @@ public void ReportHistogram() static evt => { var histogram = Assert.IsAssignableFrom>(evt.Instrument); - Assert.Equal("TimeInQueue", histogram.Name); + Assert.Equal("", histogram.Name); var telemetryEvent = evt.Event; Assert.Equal("dotnet/razor/lsp_timeinqueue", telemetryEvent.Name); @@ -436,7 +457,7 @@ public void ReportHistogram() static evt => { var histogram = Assert.IsAssignableFrom>(evt.Instrument); - Assert.Equal("RequestDuration", histogram.Name); + Assert.Equal(Methods.TextDocumentCodeActionName, histogram.Name); var telemetryEvent = evt.Event; Assert.Equal("dotnet/razor/lsp_requestduration", telemetryEvent.Name); @@ -446,6 +467,20 @@ public void ReportHistogram() Assert.Equal("dotnet.razor.method", prop.Key); Assert.Equal(Methods.TextDocumentCodeActionName, prop.Value); }); + }, + static evt => + { + var histogram = Assert.IsAssignableFrom>(evt.Instrument); + Assert.Equal(Methods.TextDocumentCompletionName, histogram.Name); + + var telemetryEvent = evt.Event; + Assert.Equal("dotnet/razor/lsp_requestduration", telemetryEvent.Name); + Assert.Collection(telemetryEvent.Properties, + static prop => + { + Assert.Equal("dotnet.razor.method", prop.Key); + Assert.Equal(Methods.TextDocumentCompletionName, prop.Value); + }); }); Assert.Collection(reporter.Events, @@ -473,6 +508,31 @@ public void ReportHistogram() Assert.Equal("dotnet.razor.cancelled", prop.Key); Assert.Equal(1, prop.Value); }); + }, + static evt => + { + Assert.Equal("dotnet/razor/lsp_requestcounter", evt.Name); + Assert.Collection(evt.Properties, + static prop => + { + Assert.Equal("dotnet.razor.method", prop.Key); + Assert.Equal(Methods.TextDocumentCompletionName, prop.Value); + }, + static prop => + { + Assert.Equal("dotnet.razor.successful", prop.Key); + Assert.Equal(1, prop.Value); + }, + static prop => + { + Assert.Equal("dotnet.razor.failed", prop.Key); + Assert.Equal(1, prop.Value); + }, + static prop => + { + Assert.Equal("dotnet.razor.cancelled", prop.Key); + Assert.Equal(1, prop.Value); + }); }); } From ba0d158affe2234dfe1de3649b9c97d45ea4e080 Mon Sep 17 00:00:00 2001 From: Andrew Hall Date: Tue, 12 Nov 2024 15:02:30 -0800 Subject: [PATCH 5/5] Use a key for TimeInQueue instead of empty string. Just seems like the nicer thing to do --- .../Telemetry/TelemetryReporter.cs | 2 +- .../Telemetry/TelemetryReporterTests.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs index 37c7d2be6d2..2202ca002eb 100644 --- a/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs +++ b/src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/Telemetry/TelemetryReporter.cs @@ -475,7 +475,7 @@ private void Flush() public void LogRequestTelemetry(string name, string? language, TimeSpan queuedDuration, TimeSpan requestDuration, TelemetryResult result) { LogAggregated("LSP_TimeInQueue", - "", // All time in queue events use the same histogram, no need for separate keys + "TimeInQueue", // All time in queue events use the same histogram, no need for separate keys (int)queuedDuration.TotalMilliseconds, name); diff --git a/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs b/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs index f3fcf2e270d..6f803aa5b89 100644 --- a/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs +++ b/src/Razor/test/Microsoft.VisualStudio.LanguageServices.Razor.Test/Telemetry/TelemetryReporterTests.cs @@ -443,7 +443,7 @@ public void ReportHistogram() static evt => { var histogram = Assert.IsAssignableFrom>(evt.Instrument); - Assert.Equal("", histogram.Name); + Assert.Equal("TimeInQueue", histogram.Name); var telemetryEvent = evt.Event; Assert.Equal("dotnet/razor/lsp_timeinqueue", telemetryEvent.Name);