From 9e6924235ea9a21cc300eec4989301e45ce85281 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Wed, 31 Jul 2019 12:18:31 -0700 Subject: [PATCH] Add logging to RemoteRenderer to time a round-trip (#12638) --- ...rosoft.AspNetCore.Components.Server.csproj | 2 +- .../Server/src/Circuits/RemoteRenderer.cs | 32 ++++++++++++------- ...rosoft.AspNetCore.Components.Server.csproj | 5 +-- 3 files changed, 24 insertions(+), 15 deletions(-) diff --git a/src/Components/Server/ref/Microsoft.AspNetCore.Components.Server.csproj b/src/Components/Server/ref/Microsoft.AspNetCore.Components.Server.csproj index e27f07cc33..491c5b8cff 100644 --- a/src/Components/Server/ref/Microsoft.AspNetCore.Components.Server.csproj +++ b/src/Components/Server/ref/Microsoft.AspNetCore.Components.Server.csproj @@ -7,11 +7,11 @@ - + diff --git a/src/Components/Server/src/Circuits/RemoteRenderer.cs b/src/Components/Server/src/Circuits/RemoteRenderer.cs index 198780db22..8b9ebb341a 100644 --- a/src/Components/Server/src/Circuits/RemoteRenderer.cs +++ b/src/Components/Server/src/Circuits/RemoteRenderer.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Concurrent; +using System.Diagnostics; using System.Linq; using System.Text.Encodings.Web; using System.Threading; @@ -10,6 +11,7 @@ using System.Threading.Tasks; using Microsoft.AspNetCore.Components.Rendering; using Microsoft.AspNetCore.Components.Server.Circuits; using Microsoft.AspNetCore.SignalR; +using Microsoft.Extensions.Internal; using Microsoft.Extensions.Logging; using Microsoft.JSInterop; @@ -138,7 +140,8 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering pendingRender = new UnacknowledgedRenderBatch( renderId, arrayBuilder, - new TaskCompletionSource()); + new TaskCompletionSource(), + ValueStopwatch.StartNew()); // Buffer the rendered batches no matter what. We'll send it down immediately when the client // is connected or right after the client reconnects. @@ -256,13 +259,14 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering private void ProcessPendingBatch(string errorMessageOrNull, UnacknowledgedRenderBatch entry) { + var elapsedTime = entry.ValueStopwatch.GetElapsedTime(); if (errorMessageOrNull == null) { - Log.CompletingBatchWithoutError(_logger, entry.BatchId); + Log.CompletingBatchWithoutError(_logger, entry.BatchId, elapsedTime); } else { - Log.CompletingBatchWithError(_logger, entry.BatchId, errorMessageOrNull); + Log.CompletingBatchWithError(_logger, entry.BatchId, errorMessageOrNull, elapsedTime); } entry.Data.Dispose(); @@ -283,16 +287,18 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering internal readonly struct UnacknowledgedRenderBatch { - public UnacknowledgedRenderBatch(long batchId, ArrayBuilder data, TaskCompletionSource completionSource) + public UnacknowledgedRenderBatch(long batchId, ArrayBuilder data, TaskCompletionSource completionSource, ValueStopwatch valueStopwatch) { BatchId = batchId; Data = data; CompletionSource = completionSource; + ValueStopwatch = valueStopwatch; } public long BatchId { get; } public ArrayBuilder Data { get; } public TaskCompletionSource CompletionSource { get; } + public ValueStopwatch ValueStopwatch { get; } } private void CaptureAsyncExceptions(Task task) @@ -312,8 +318,8 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering private static readonly Action _beginUpdateDisplayAsync; private static readonly Action _bufferingRenderDisconnectedClient; private static readonly Action _sendBatchDataFailed; - private static readonly Action _completingBatchWithError; - private static readonly Action _completingBatchWithoutError; + private static readonly Action _completingBatchWithError; + private static readonly Action _completingBatchWithoutError; private static readonly Action _receivedDuplicateBatchAcknowledgement; private static class EventIds @@ -349,15 +355,15 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering EventIds.SendBatchDataFailed, "Sending data for batch failed: {Message}"); - _completingBatchWithError = LoggerMessage.Define( + _completingBatchWithError = LoggerMessage.Define( LogLevel.Debug, EventIds.CompletingBatchWithError, - "Completing batch {BatchId} with error: {ErrorMessage}"); + "Completing batch {BatchId} with error: {ErrorMessage} in {ElapsedMilliseconds}ms."); - _completingBatchWithoutError = LoggerMessage.Define( + _completingBatchWithoutError = LoggerMessage.Define( LogLevel.Debug, EventIds.CompletingBatchWithoutError, - "Completing batch {BatchId} without error"); + "Completing batch {BatchId} without error in {ElapsedMilliseconds}ms."); _receivedDuplicateBatchAcknowledgement = LoggerMessage.Define( LogLevel.Debug, @@ -396,20 +402,22 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering null); } - public static void CompletingBatchWithError(ILogger logger, long batchId, string errorMessage) + public static void CompletingBatchWithError(ILogger logger, long batchId, string errorMessage, TimeSpan elapsedTime) { _completingBatchWithError( logger, batchId, errorMessage, + elapsedTime.TotalMilliseconds, null); } - public static void CompletingBatchWithoutError(ILogger logger, long batchId) + public static void CompletingBatchWithoutError(ILogger logger, long batchId, TimeSpan elapsedTime) { _completingBatchWithoutError( logger, batchId, + elapsedTime.TotalMilliseconds, null); } diff --git a/src/Components/Server/src/Microsoft.AspNetCore.Components.Server.csproj b/src/Components/Server/src/Microsoft.AspNetCore.Components.Server.csproj index ffa9a5ffb4..3f87bd43af 100644 --- a/src/Components/Server/src/Microsoft.AspNetCore.Components.Server.csproj +++ b/src/Components/Server/src/Microsoft.AspNetCore.Components.Server.csproj @@ -1,4 +1,4 @@ - + netcoreapp3.0 @@ -14,12 +14,13 @@ - + +