Add logging to RemoteRenderer to time a round-trip (#12638)

Author: pranavkm

src/Components/Server/ref/Microsoft.AspNetCore.Components.Server.csproj

@@ -7,11 +7,11 @@
     <Compile Include="Microsoft.AspNetCore.Components.Server.netcoreapp3.0.cs" />
     <Reference Include="Microsoft.AspNetCore.Components.Web"  />
     <Reference Include="Microsoft.AspNetCore.DataProtection"  />
-    <Reference Include="Microsoft.Extensions.Logging"  />
     <Reference Include="Microsoft.AspNetCore.SignalR"  />
     <Reference Include="Microsoft.AspNetCore.StaticFiles"  />
     <Reference Include="Microsoft.Extensions.Caching.Memory"  />
     <Reference Include="Microsoft.Extensions.FileProviders.Composite"  />
     <Reference Include="Microsoft.Extensions.FileProviders.Embedded"  />
+    <Reference Include="Microsoft.Extensions.Logging"  />
   </ItemGroup>
 </Project>

src/Components/Server/src/Circuits/RemoteRenderer.cs

@@ -3,13 +3,15 @@
 
 using System;
 using System.Collections.Concurrent;
+using System.Diagnostics;
 using System.Linq;
 using System.Text.Encodings.Web;
 using System.Threading;
 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 @@ protected override Task UpdateDisplayAsync(in RenderBatch batch)
                 pendingRender = new UnacknowledgedRenderBatch(
                     renderId,
                     arrayBuilder,
-                    new TaskCompletionSource<object>());
+                    new TaskCompletionSource<object>(),
+                    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 @@ public void OnRenderCompleted(long incomingBatchId, string errorMessageOrNull)
 
         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 @@ private void CompleteRender(TaskCompletionSource<object> pendingRenderInfo, stri
 
         internal readonly struct UnacknowledgedRenderBatch
         {
-            public UnacknowledgedRenderBatch(long batchId, ArrayBuilder<byte> data, TaskCompletionSource<object> completionSource)
+            public UnacknowledgedRenderBatch(long batchId, ArrayBuilder<byte> data, TaskCompletionSource<object> completionSource, ValueStopwatch valueStopwatch)
             {
                 BatchId = batchId;
                 Data = data;
                 CompletionSource = completionSource;
+                ValueStopwatch = valueStopwatch;
             }
 
             public long BatchId { get; }
             public ArrayBuilder<byte> Data { get; }
             public TaskCompletionSource<object> CompletionSource { get; }
+            public ValueStopwatch ValueStopwatch { get; }
         }
 
         private void CaptureAsyncExceptions(Task task)
@@ -312,8 +318,8 @@ private static class Log
             private static readonly Action<ILogger, long, int, string, Exception> _beginUpdateDisplayAsync;
             private static readonly Action<ILogger, string, Exception> _bufferingRenderDisconnectedClient;
             private static readonly Action<ILogger, string, Exception> _sendBatchDataFailed;
-            private static readonly Action<ILogger, long, string, Exception> _completingBatchWithError;
-            private static readonly Action<ILogger, long, Exception> _completingBatchWithoutError;
+            private static readonly Action<ILogger, long, string, double, Exception> _completingBatchWithError;
+            private static readonly Action<ILogger, long, double, Exception> _completingBatchWithoutError;
             private static readonly Action<ILogger, long, Exception> _receivedDuplicateBatchAcknowledgement;
 
             private static class EventIds
@@ -349,15 +355,15 @@ static Log()
                     EventIds.SendBatchDataFailed,
                     "Sending data for batch failed: {Message}");
 
-                _completingBatchWithError = LoggerMessage.Define<long, string>(
+                _completingBatchWithError = LoggerMessage.Define<long, string, double>(
                     LogLevel.Debug,
                     EventIds.CompletingBatchWithError,
-                    "Completing batch {BatchId} with error: {ErrorMessage}");
+                    "Completing batch {BatchId} with error: {ErrorMessage} in {ElapsedMilliseconds}ms.");
 
-                _completingBatchWithoutError = LoggerMessage.Define<long>(
+                _completingBatchWithoutError = LoggerMessage.Define<long, double>(
                     LogLevel.Debug,
                     EventIds.CompletingBatchWithoutError,
-                    "Completing batch {BatchId} without error");
+                    "Completing batch {BatchId} without error in {ElapsedMilliseconds}ms.");
 
                 _receivedDuplicateBatchAcknowledgement = LoggerMessage.Define<long>(
                     LogLevel.Debug,
@@ -396,20 +402,22 @@ public static void BufferingRenderDisconnectedClient(ILogger logger, string conn
                     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);
             }
 

src/Components/Server/src/Microsoft.AspNetCore.Components.Server.csproj

@@ -1,4 +1,4 @@
-<Project Sdk="Microsoft.NET.Sdk">
+<Project Sdk="Microsoft.NET.Sdk">
 
   <PropertyGroup>
     <TargetFramework>netcoreapp3.0</TargetFramework>
@@ -14,12 +14,13 @@
   <ItemGroup>
     <Reference Include="Microsoft.AspNetCore.Components.Web" />
     <Reference Include="Microsoft.AspNetCore.DataProtection" />
-    <Reference Include="Microsoft.Extensions.Logging" />
     <Reference Include="Microsoft.AspNetCore.SignalR" />
     <Reference Include="Microsoft.AspNetCore.StaticFiles" />
     <Reference Include="Microsoft.Extensions.Caching.Memory" />
     <Reference Include="Microsoft.Extensions.FileProviders.Composite" />
     <Reference Include="Microsoft.Extensions.FileProviders.Embedded" />
+    <Reference Include="Microsoft.Extensions.Logging" />
+    <Reference Include="Microsoft.Extensions.ValueStopwatch.Sources" PrivateAssets="All" />
   </ItemGroup>
 
   <PropertyGroup>