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

This commit is contained in:
Pranav K 2019-07-31 12:18:31 -07:00 committed by GitHub
parent aab75e8dda
commit 9e6924235e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 24 additions and 15 deletions

View File

@ -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>

View File

@ -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<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 @@ 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<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 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering
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 @@ namespace Microsoft.AspNetCore.Components.Web.Rendering
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 @@ 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);
}

View File

@ -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>