Skip to content

Optimize LoggingStream. #142

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 4 commits into
base: main
Choose a base branch
from
Open

Optimize LoggingStream. #142

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
0def6fa
Optimize LoggingStream.
Feb 11, 2022
143a05a
Merge branch 'main' into OptimizeTheLogging
adamradocz Mar 15, 2022
32c9c9f
Update LoggingStream.cs
adamradocz May 9, 2022
f837443
Merge branch 'main' into OptimizeTheLogging
adamradocz Jun 6, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 18 additions & 5 deletions samples/ServerApplication/Program.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,12 +1,15 @@
using System;
using System.Net;
using System.Security.Cryptography.X509Certificates;
using System.Text;
using System.Threading.Tasks;
using Bedrock.Framework;
using Microsoft.AspNetCore.Connections;
using Microsoft.AspNetCore.SignalR;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.DependencyInjection.Extensions;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.ObjectPool;

namespace ServerApplication
{
Expand All @@ -24,26 +27,36 @@ public static async Task Main(string[] args)

services.AddSignalR();

services.TryAddSingleton<ObjectPoolProvider, DefaultObjectPoolProvider>();
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This feels like an unnecessary dependency

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mean using the String builder pool?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The LoggingStream creates two new StringBuilders for every message that it logs. Why wouldn't you optimized that?

services.TryAddSingleton<ObjectPool<StringBuilder>>(serviceProvider =>
{
var objectPoolProvider = serviceProvider.GetRequiredService<ObjectPoolProvider>();
var policy = new StringBuilderPooledObjectPolicy();
return objectPoolProvider.Create(policy);
});

var serviceProvider = services.BuildServiceProvider();

var server = new ServerBuilder(serviceProvider)
.UseSockets(sockets =>
{
var stringBuilderPool = serviceProvider.GetRequiredService<ObjectPool<StringBuilder>>();

// Echo server
sockets.ListenLocalhost(5000,
builder => builder.UseConnectionLogging().UseConnectionHandler<EchoServerApplication>());
builder => builder.UseConnectionLogging(stringBuilderPool: stringBuilderPool).UseConnectionHandler<EchoServerApplication>());

// HTTP/1.1 server
sockets.Listen(IPAddress.Loopback, 5001,
builder => builder.UseConnectionLogging().UseConnectionHandler<HttpApplication>());
builder => builder.UseConnectionLogging(stringBuilderPool: stringBuilderPool).UseConnectionHandler<HttpApplication>());

// SignalR Hub
sockets.Listen(IPAddress.Loopback, 5002,
builder => builder.UseConnectionLogging().UseHub<Chat>());
builder => builder.UseConnectionLogging(stringBuilderPool: stringBuilderPool).UseHub<Chat>());

// MQTT application
sockets.Listen(IPAddress.Loopback, 5003,
builder => builder.UseConnectionLogging().UseConnectionHandler<MqttApplication>());
builder => builder.UseConnectionLogging(stringBuilderPool: stringBuilderPool).UseConnectionHandler<MqttApplication>());

// Echo Server with TLS
sockets.Listen(IPAddress.Loopback, 5004,
Expand All @@ -54,7 +67,7 @@ public static async Task Main(string[] args)
// NOTE: Do not do this in a production environment
options.AllowAnyRemoteCertificate();
})
.UseConnectionLogging().UseConnectionHandler<EchoServerApplication>());
.UseConnectionLogging(stringBuilderPool: stringBuilderPool).UseConnectionHandler<EchoServerApplication>());

sockets.Listen(IPAddress.Loopback, 5005,
builder => builder.UseConnectionLogging().UseConnectionHandler<MyCustomProtocol>());
Expand Down
10 changes: 8 additions & 2 deletions src/Bedrock.Framework/Middleware/ConnectionBuilderExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.ObjectPool;

namespace Bedrock.Framework
{
Expand All @@ -17,11 +18,16 @@ public static class ConnectionBuilderExtensions
/// <summary>
/// Emits verbose logs for bytes read from and written to the connection.
/// </summary>
public static TBuilder UseConnectionLogging<TBuilder>(this TBuilder builder, string loggerName = null, ILoggerFactory loggerFactory = null, LoggingFormatter loggingFormatter = null) where TBuilder : IConnectionBuilder
public static TBuilder UseConnectionLogging<TBuilder>(this TBuilder builder, string loggerName = null, ILoggerFactory loggerFactory = null, ObjectPool<StringBuilder> stringBuilderPool = null, LoggingFormatter loggingFormatter = null) where TBuilder : IConnectionBuilder
{
loggerFactory ??= builder.ApplicationServices.GetRequiredService<ILoggerFactory>();
var logger = loggerName == null ? loggerFactory.CreateLogger<LoggingConnectionMiddleware>() : loggerFactory.CreateLogger(loggerName);
builder.Use(next => new LoggingConnectionMiddleware(next, logger, loggingFormatter).OnConnectionAsync);
if (stringBuilderPool == null)
{
var objectPoolProvider = new DefaultObjectPoolProvider();
stringBuilderPool = objectPoolProvider.CreateStringBuilderPool();
}
builder.Use(next => new LoggingConnectionMiddleware(next, logger, stringBuilderPool, loggingFormatter).OnConnectionAsync);
return builder;
}

Expand Down
109 changes: 34 additions & 75 deletions src/Bedrock.Framework/Middleware/Internal/LoggingStream.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,76 +7,42 @@
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.ObjectPool;

namespace Bedrock.Framework.Infrastructure
{
internal sealed class LoggingStream : Stream
public sealed class LoggingStream : Stream
{
private readonly Stream _inner;
private readonly ILogger _logger;
private readonly ObjectPool<StringBuilder> _stringBuilderPool;
private readonly LoggingFormatter _logFormatter;

public LoggingStream(Stream inner, ILogger logger, LoggingFormatter logFormatter = null)
public LoggingStream(Stream inner, ILogger logger, ObjectPool<StringBuilder> stringBuilderPool, LoggingFormatter logFormatter = null)
{
_inner = inner;
_logger = logger;
_stringBuilderPool = stringBuilderPool;
_logFormatter = logFormatter;
}

public override bool CanRead
{
get
{
return _inner.CanRead;
}
}
public override bool CanRead => _inner.CanRead;

public override bool CanSeek
{
get
{
return _inner.CanSeek;
}
}
public override bool CanSeek => _inner.CanSeek;

public override bool CanWrite
{
get
{
return _inner.CanWrite;
}
}
public override bool CanWrite => _inner.CanWrite;

public override long Length
{
get
{
return _inner.Length;
}
}
public override long Length => _inner.Length;

public override long Position
{
get
{
return _inner.Position;
}

set
{
_inner.Position = value;
}
get => _inner.Position;
set => _inner.Position = value;
}

public override void Flush()
{
_inner.Flush();
}
public override void Flush() => _inner.Flush();

public override Task FlushAsync(CancellationToken cancellationToken)
{
return _inner.FlushAsync(cancellationToken);
}
public override Task FlushAsync(CancellationToken cancellationToken) => _inner.FlushAsync(cancellationToken);

public override int Read(byte[] buffer, int offset, int count)
{
Expand All @@ -92,7 +58,7 @@ public override int Read(Span<byte> destination)
return read;
}

public async override Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken)
public override async Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken)
{
int read = await _inner.ReadAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false);
Log("ReadAsync", new ReadOnlySpan<byte>(buffer, offset, read));
Expand Down Expand Up @@ -140,7 +106,7 @@ public override ValueTask WriteAsync(ReadOnlyMemory<byte> source, CancellationTo
return _inner.WriteAsync(source, cancellationToken);
}

private void Log(string method, ReadOnlySpan<byte> buffer)
private void Log(in string method, in ReadOnlySpan<byte> buffer)
{
if (_logFormatter != null)
{
Expand All @@ -153,20 +119,20 @@ private void Log(string method, ReadOnlySpan<byte> buffer)
return;
}

var builder = new StringBuilder();
var builder = _stringBuilderPool.Get();
builder.AppendLine($"{method}[{buffer.Length}]");
var charBuilder = new StringBuilder();
var charBuilder = _stringBuilderPool.Get();

// Write the hex
for (int i = 0; i < buffer.Length; i++)
{
builder.Append(buffer[i].ToString("X2"));
builder.Append(" ");
builder.Append(' ');

var bufferChar = (char)buffer[i];
if (char.IsControl(bufferChar))
{
charBuilder.Append(".");
charBuilder.Append('.');
}
else
{
Expand All @@ -175,15 +141,15 @@ private void Log(string method, ReadOnlySpan<byte> buffer)

if ((i + 1) % 16 == 0)
{
builder.Append(" ");
builder.Append(charBuilder.ToString());
builder.Append(' ', 2);
builder.Append(charBuilder);
builder.AppendLine();
charBuilder.Clear();
}
else if ((i + 1) % 8 == 0)
{
builder.Append(" ");
charBuilder.Append(" ");
builder.Append(' ');
charBuilder.Append(' ');
}
}

Expand All @@ -193,32 +159,25 @@ private void Log(string method, ReadOnlySpan<byte> buffer)
builder.Append(string.Empty.PadRight(2 + (3 * (16 - charBuilder.Length))));
// extra for space after 8th byte
if (charBuilder.Length < 8)
builder.Append(" ");
builder.Append(charBuilder.ToString());
{
builder.Append(' ');
}
builder.Append(charBuilder);
}

_logger.LogDebug(builder.ToString());

_stringBuilderPool.Return(builder);
_stringBuilderPool.Return(charBuilder);
}

// The below APM methods call the underlying Read/WriteAsync methods which will still be logged.
public override IAsyncResult BeginRead(byte[] buffer, int offset, int count, AsyncCallback callback, object state)
{
return TaskToApm.Begin(ReadAsync(buffer, offset, count), callback, state);
}
public override IAsyncResult BeginRead(byte[] buffer, int offset, int count, AsyncCallback callback, object state) => TaskToApm.Begin(ReadAsync(buffer, offset, count), callback, state);

public override int EndRead(IAsyncResult asyncResult)
{
return TaskToApm.End<int>(asyncResult);
}
public override int EndRead(IAsyncResult asyncResult) => TaskToApm.End<int>(asyncResult);

public override IAsyncResult BeginWrite(byte[] buffer, int offset, int count, AsyncCallback callback, object state)
{
return TaskToApm.Begin(WriteAsync(buffer, offset, count), callback, state);
}
public override IAsyncResult BeginWrite(byte[] buffer, int offset, int count, AsyncCallback callback, object state) => TaskToApm.Begin(WriteAsync(buffer, offset, count), callback, state);

public override void EndWrite(IAsyncResult asyncResult)
{
TaskToApm.End(asyncResult);
}
public override void EndWrite(IAsyncResult asyncResult) => TaskToApm.End(asyncResult);
}
}
12 changes: 8 additions & 4 deletions src/Bedrock.Framework/Middleware/LoggingConnectionMiddleware.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,10 +3,12 @@

using System;
using System.IO.Pipelines;
using System.Text;
using System.Threading.Tasks;
using Bedrock.Framework.Infrastructure;
using Microsoft.AspNetCore.Connections;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.ObjectPool;

namespace Bedrock.Framework
{
Expand All @@ -15,11 +17,13 @@ internal class LoggingConnectionMiddleware
private readonly ConnectionDelegate _next;
private readonly ILogger _logger;
private readonly LoggingFormatter _loggingFormatter;
private readonly ObjectPool<StringBuilder> _stringBuilderPool;

public LoggingConnectionMiddleware(ConnectionDelegate next, ILogger logger, LoggingFormatter loggingFormatter = null)
public LoggingConnectionMiddleware(ConnectionDelegate next, ILogger logger, ObjectPool<StringBuilder> stringBuilderPool, LoggingFormatter loggingFormatter = null)
{
_next = next ?? throw new ArgumentNullException(nameof(next));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_stringBuilderPool = stringBuilderPool ?? throw new ArgumentNullException(nameof(stringBuilderPool));
_loggingFormatter = loggingFormatter;
}

Expand All @@ -29,7 +33,7 @@ public async Task OnConnectionAsync(ConnectionContext context)

try
{
await using (var loggingDuplexPipe = new LoggingDuplexPipe(context.Transport, _logger, _loggingFormatter))
await using (var loggingDuplexPipe = new LoggingDuplexPipe(context.Transport, _logger, _stringBuilderPool, _loggingFormatter))
{
context.Transport = loggingDuplexPipe;

Expand All @@ -44,8 +48,8 @@ public async Task OnConnectionAsync(ConnectionContext context)

private class LoggingDuplexPipe : DuplexPipeStreamAdapter<LoggingStream>
{
public LoggingDuplexPipe(IDuplexPipe transport, ILogger logger, LoggingFormatter loggingFormatter) :
base(transport, stream => new LoggingStream(stream, logger, loggingFormatter))
public LoggingDuplexPipe(IDuplexPipe transport, ILogger logger, ObjectPool<StringBuilder> stringBuilderPool, LoggingFormatter loggingFormatter) :
base(transport, stream => new LoggingStream(stream, logger, stringBuilderPool, loggingFormatter))
{
}
}
Expand Down