huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Added some kestrel event counters (#21649) 

* Added some kestrel event counters
- Connection queue length - This is the amount of connections accepted and queued in the thread pool.
- Connection count - The number of connections
- Total connections - The total number of connections ever connected.
- Connection Rate - Connections per second

* Added TLS counters
- Current TLS handshakes
- Total TLS handshakes
- Failed TLS handshakes
- TLS handshake per second

* Added HTTP/2 queue length counter

* Improve the event information
- Add TLS version to handshake events
- Add HTTP version to request queue events
- Renamed HTTP/2 request queue length to http request queue


Contributes to #4769
This commit is contained in:
David Fowler 2020-05-12 11:04:37 -07:00 committed by GitHub
parent dfb126da17
commit 5a0c097ad4
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 312 additions and 23 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs
View File

@ -61,6 +61,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
_transportConnectionManager.AddConnection(id, kestrelConnection);
Log.ConnectionAccepted(connection.ConnectionId);
KestrelEventSource.Log.ConnectionQueuedStart(connection);
ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false);
}

7
src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs
View File

@ -76,6 +76,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http
protected override void OnRequestProcessingEnded()
{
if (IsUpgraded)
{
KestrelEventSource.Log.RequestUpgradedStop(this);
ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
}
TimeoutControl.StartDrainTimeout(MinResponseDataRate, ServerOptions.Limits.MaxResponseBufferSize);
// Prevent RequestAborted from firing. Free up unneeded feature references.

2
src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.FeatureCollection.cs
View File

@ -293,6 +293,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http
IsUpgraded = true;
KestrelEventSource.Log.RequestUpgradedStart(this);
ConnectionFeatures.Get<IDecrementConcurrentConnectionCountFeature>()?.ReleaseConnection();
StatusCode = StatusCodes.Status101SwitchingProtocols;

1
src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs
View File

@ -136,6 +136,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http
public int LocalPort { get; set; }
public string Scheme { get; set; }
public HttpMethod Method { get; set; }
public string MethodText => ((IHttpRequestFeature)this).Method;
public string PathBase { get; set; }
public string Path { get; set; }

1
src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs
View File

@ -1002,6 +1002,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2
throw;
}
KestrelEventSource.Log.RequestQueuedStart(_currentHeadersStream, AspNetCore.Http.HttpProtocol.Http2);
// Must not allow app code to block the connection handling loop.
ThreadPool.UnsafeQueueUserWorkItem(_currentHeadersStream, preferLocal: false);
}

2
src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs
View File

@ -4,6 +4,7 @@
using Microsoft.AspNetCore.Hosting.Server;
using Microsoft.AspNetCore.Hosting.Server.Abstractions;
using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure;
namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2
{
@ -19,6 +20,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2
public override void Execute()
{
KestrelEventSource.Log.RequestQueuedStop(this, AspNetCore.Http.HttpProtocol.Http2);
// REVIEW: Should we store this in a field for easy debugging?
_ = ProcessRequestsAsync(_application);
}

1
src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs
View File

@ -243,6 +243,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
{
_streams[streamId] = http3Stream;
}
KestrelEventSource.Log.RequestQueuedStart(stream, AspNetCore.Http.HttpProtocol.Http3);
ThreadPool.UnsafeQueueUserWorkItem(stream, preferLocal: false);
}
}

3
src/Servers/Kestrel/Core/src/Internal/Http3/Http3StreamOfT.cs
View File

@ -3,6 +3,7 @@
using Microsoft.AspNetCore.Hosting.Server;
using Microsoft.AspNetCore.Hosting.Server.Abstractions;
using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure;
namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
{
@ -17,6 +18,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
public override void Execute()
{
KestrelEventSource.Log.RequestQueuedStop(this, AspNetCore.Http.HttpProtocol.Http3);
if (_requestHeaderParsingState == Http3Stream.RequestHeaderParsingState.Ready)
{
_ = ProcessRequestAsync(_application);

7
src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs
View File

@ -107,13 +107,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
{
Log.LogCritical(0, ex, $"Unexpected exception in {nameof(HttpConnection)}.{nameof(ProcessRequestsAsync)}.");
}
finally
{
if (_http1Connection?.IsUpgraded == true)
{
_context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
}
}
}
// For testing only

2
src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs
View File

@ -40,6 +40,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
try
{
KestrelEventSource.Log.ConnectionQueuedStop(connectionContext);
Logger.ConnectionStart(connectionContext.ConnectionId);
KestrelEventSource.Log.ConnectionStart(connectionContext);

290
src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs
View File

@ -1,8 +1,12 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System;
using System.Diagnostics.Tracing;
using System.Net.Security;
using System.Runtime.CompilerServices;
using System.Text;
using System.Threading;
using Microsoft.AspNetCore.Connections;
using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http;
@ -13,6 +17,26 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
{
public static readonly KestrelEventSource Log = new KestrelEventSource();
private IncrementingPollingCounter _connectionsPerSecondCounter;
private IncrementingPollingCounter _tlsHandshakesPerSecondCounter;
private PollingCounter _totalConnectionsCounter;
private PollingCounter _currentConnectionsCounter;
private PollingCounter _totalTlsHandshakesCounter;
private PollingCounter _currentTlsHandshakesCounter;
private PollingCounter _failedTlsHandshakesCounter;
private PollingCounter _connectionQueueLengthCounter;
private PollingCounter _httpRequestQueueLengthCounter;
private PollingCounter _currrentUpgradedHttpRequestsCounter;
private long _totalConnections;
private long _currentConnections;
private long _connectionQueueLength;
private long _totalTlsHandshakes;
private long _currentTlsHandshakes;
private long _failedTlsHandshakes;
private long _httpRequestQueueLength;
private long _currentUpgradedHttpRequests;
private KestrelEventSource()
{
}
@ -29,6 +53,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
public void ConnectionStart(BaseConnectionContext connection)
{
// avoid allocating strings unless this event source is enabled
Interlocked.Increment(ref _totalConnections);
Interlocked.Increment(ref _currentConnections);
if (IsEnabled())
{
ConnectionStart(
@ -39,7 +66,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(1, Level = EventLevel.Verbose)]
[Event(1, Level = EventLevel.Informational)]
private void ConnectionStart(string connectionId,
string localEndPoint,
string remoteEndPoint)
@ -55,6 +82,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
[NonEvent]
public void ConnectionStop(BaseConnectionContext connection)
{
Interlocked.Decrement(ref _currentConnections);
if (IsEnabled())
{
ConnectionStop(connection.ConnectionId);
@ -62,14 +90,48 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(2, Level = EventLevel.Verbose)]
[Event(2, Level = EventLevel.Informational)]
private void ConnectionStop(string connectionId)
{
WriteEvent(2, connectionId);
}
[NonEvent]
public void RequestStart(HttpProtocol httpProtocol)
{
// avoid allocating the trace identifier unless logging is enabled
if (IsEnabled())
{
RequestStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(5, Level = EventLevel.Verbose)]
[Event(3, Level = EventLevel.Informational)]
private void RequestStart(string connectionId, string requestId, string httpVersion, string path, string method)
{
WriteEvent(3, connectionId, requestId, httpVersion, path, method);
}
[NonEvent]
public void RequestStop(HttpProtocol httpProtocol)
{
// avoid allocating the trace identifier unless logging is enabled
if (IsEnabled())
{
RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(4, Level = EventLevel.Informational)]
private void RequestStop(string connectionId, string requestId, string httpVersion, string path, string method)
{
WriteEvent(4, connectionId, requestId, httpVersion, path, method);
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(5, Level = EventLevel.Informational)]
public void ConnectionRejected(string connectionId)
{
if (IsEnabled())
@ -79,37 +141,235 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
}
[NonEvent]
public void RequestStart(HttpProtocol httpProtocol)
public void ConnectionQueuedStart(BaseConnectionContext connection)
{
// avoid allocating the trace identifier unless logging is enabled
Interlocked.Increment(ref _connectionQueueLength);
if (IsEnabled())
{
RequestStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier);
ConnectionQueuedStart(
connection.ConnectionId,
connection.LocalEndPoint?.ToString(),
connection.RemoteEndPoint?.ToString());
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(3, Level = EventLevel.Verbose)]
private void RequestStart(string connectionId, string requestId)
[Event(6, Level = EventLevel.Informational)]
private void ConnectionQueuedStart(string connectionId,
string localEndPoint,
string remoteEndPoint)
{
WriteEvent(3, connectionId, requestId);
WriteEvent(
6,
connectionId,
localEndPoint,
remoteEndPoint
);
}
[NonEvent]
public void RequestStop(HttpProtocol httpProtocol)
public void ConnectionQueuedStop(BaseConnectionContext connection)
{
// avoid allocating the trace identifier unless logging is enabled
Interlocked.Decrement(ref _connectionQueueLength);
if (IsEnabled())
{
RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier);
ConnectionQueuedStop(
connection.ConnectionId,
connection.LocalEndPoint?.ToString(),
connection.RemoteEndPoint?.ToString());
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(4, Level = EventLevel.Verbose)]
private void RequestStop(string connectionId, string requestId)
[Event(7, Level = EventLevel.Informational)]
private void ConnectionQueuedStop(string connectionId,
string localEndPoint,
string remoteEndPoint)
{
WriteEvent(4, connectionId, requestId);
WriteEvent(
7,
connectionId,
localEndPoint,
remoteEndPoint
);
}
[NonEvent]
public void TlsHandshakeStart(BaseConnectionContext connectionContext, SslServerAuthenticationOptions sslOptions)
{
Interlocked.Increment(ref _currentTlsHandshakes);
Interlocked.Increment(ref _totalTlsHandshakes);
if (IsEnabled())
{
TlsHandshakeStart(connectionContext.ConnectionId, sslOptions.EnabledSslProtocols.ToString());
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(8, Level = EventLevel.Informational)]
private void TlsHandshakeStart(string connectionId, string sslProtocols)
{
WriteEvent(8, connectionId, sslProtocols);
}
[NonEvent]
public void TlsHandshakeStop(BaseConnectionContext connectionContext, TlsConnectionFeature feature)
{
Interlocked.Decrement(ref _currentTlsHandshakes);
if (IsEnabled())
{
// TODO: Write this without a string allocation using WriteEventData
var applicationProtocol = feature == null ? string.Empty : Encoding.UTF8.GetString(feature.ApplicationProtocol.Span);
var sslProtocols = feature?.Protocol.ToString() ?? string.Empty;
var hostName = feature?.HostName ?? string.Empty;
TlsHandshakeStop(connectionContext.ConnectionId, sslProtocols, applicationProtocol, hostName);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(9, Level = EventLevel.Informational)]
private void TlsHandshakeStop(string connectionId, string sslProtocols, string applicationProtocol, string hostName)
{
WriteEvent(9, connectionId, sslProtocols, applicationProtocol, hostName);
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(10, Level = EventLevel.Error)]
public void TlsHandshakeFailed(string connectionId)
{
Interlocked.Increment(ref _failedTlsHandshakes);
WriteEvent(10, connectionId);
}
[NonEvent]
public void RequestQueuedStart(HttpProtocol httpProtocol, string httpVersion)
{
Interlocked.Increment(ref _httpRequestQueueLength);
// avoid allocating the trace identifier unless logging is enabled
if (IsEnabled())
{
RequestQueuedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(11, Level = EventLevel.Informational)]
private void RequestQueuedStart(string connectionId, string requestId, string httpVersion)
{
WriteEvent(11, connectionId, requestId, httpVersion);
}
[NonEvent]
public void RequestQueuedStop(HttpProtocol httpProtocol, string httpVersion)
{
Interlocked.Decrement(ref _httpRequestQueueLength);
// avoid allocating the trace identifier unless logging is enabled
if (IsEnabled())
{
RequestQueuedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(12, Level = EventLevel.Informational)]
private void RequestQueuedStop(string connectionId, string requestId, string httpVersion)
{
WriteEvent(12, connectionId, requestId, httpVersion);
}
[NonEvent]
public void RequestUpgradedStart(HttpProtocol httpProtocol)
{
Interlocked.Increment(ref _currentUpgradedHttpRequests);
if (IsEnabled())
{
RequestUpgradedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(13, Level = EventLevel.Informational)]
private void RequestUpgradedStart(string connectionId, string requestId, string httpVersion, string path, string method)
{
WriteEvent(13, connectionId, requestId, httpVersion, path, method);
}
[NonEvent]
public void RequestUpgradedStop(HttpProtocol httpProtocol)
{
Interlocked.Decrement(ref _currentUpgradedHttpRequests);
if (IsEnabled())
{
RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText);
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
[Event(14, Level = EventLevel.Informational)]
private void RequestUpgradedStop(string connectionId, string requestId, string httpVersion, string path, string method)
{
WriteEvent(14, connectionId, requestId, httpVersion, path, method);
}
protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command == EventCommand.Enable)
{
// This is the convention for initializing counters in the RuntimeEventSource (lazily on the first enable command).
// They aren't disabled afterwards...
_connectionsPerSecondCounter ??= new IncrementingPollingCounter("connections-per-second", this, () => _totalConnections)
{
DisplayName = "Connection Rate",
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
};
_totalConnectionsCounter ??= new PollingCounter("total-connections", this, () => _totalConnections)
{
DisplayName = "Total Connections",
};
_tlsHandshakesPerSecondCounter ??= new IncrementingPollingCounter("tls-handshakes-per-second", this, () => _totalTlsHandshakes)
{
DisplayName = "TLS Handshake Rate",
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
};
_totalTlsHandshakesCounter ??= new PollingCounter("total-tls-handshakes", this, () => _totalTlsHandshakes)
{
DisplayName = "Total TLS Handshakes",
};
_currentTlsHandshakesCounter ??= new PollingCounter("current-tls-handshakes", this, () => _currentTlsHandshakes)
{
DisplayName = "Current TLS Handshakes"
};
_failedTlsHandshakesCounter ??= new PollingCounter("failed-tls-handshakes", this, () => _failedTlsHandshakes)
{
DisplayName = "Failed TLS Handshakes"
};
_currentConnectionsCounter ??= new PollingCounter("current-connections", this, () => _currentConnections)
{
DisplayName = "Current Connections"
};
_connectionQueueLengthCounter ??= new PollingCounter("connection-queue-length", this, () => _connectionQueueLength)
{
DisplayName = "Connection Queue Length"
};
_httpRequestQueueLengthCounter ??= new PollingCounter("request-queue-length", this, () => _httpRequestQueueLength)
{
DisplayName = "Request Queue Length"
};
_currrentUpgradedHttpRequestsCounter ??= new PollingCounter("current-upgraded-requests", this, () => _currentUpgradedHttpRequests)
{
DisplayName = "Current Upgraded Requests (WebSockets)"
};
}
}
}
}

2
src/Servers/Kestrel/Core/src/Internal/TlsConnectionFeature.cs
View File

@ -16,6 +16,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
{
public X509Certificate2 ClientCertificate { get; set; }
public string HostName { get; set; }
public ReadOnlyMemory<byte> ApplicationProtocol { get; set; }
public SslProtocols Protocol { get; set; }

16
src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs
View File

@ -11,13 +11,13 @@ using System.Security.Authentication;
using System.Security.Cryptography.X509Certificates;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Certificates.Generation;
using Microsoft.AspNetCore.Connections;
using Microsoft.AspNetCore.Connections.Features;
using Microsoft.AspNetCore.Http.Features;
using Microsoft.AspNetCore.Server.Kestrel.Core;
using Microsoft.AspNetCore.Server.Kestrel.Core.Features;
using Microsoft.AspNetCore.Server.Kestrel.Core.Internal;
using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
@ -169,6 +169,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https.Internal
{
selector = (sender, name) =>
{
feature.HostName = name;
context.Features.Set(sslStream);
var cert = _serverCertificateSelector(context, name);
if (cert != null)
@ -204,22 +205,33 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https.Internal
_options.OnAuthenticate?.Invoke(context, sslOptions);
KestrelEventSource.Log.TlsHandshakeStart(context, sslOptions);
await sslStream.AuthenticateAsServerAsync(sslOptions, cancellationTokeSource.Token);
}
catch (OperationCanceledException)
{
KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId);
KestrelEventSource.Log.TlsHandshakeStop(context, null);
_logger.LogDebug(2, CoreStrings.AuthenticationTimedOut);
await sslStream.DisposeAsync();
return;
}
catch (IOException ex)
{
KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId);
KestrelEventSource.Log.TlsHandshakeStop(context, null);
_logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed);
await sslStream.DisposeAsync();
return;
}
catch (AuthenticationException ex)
{
KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId);
KestrelEventSource.Log.TlsHandshakeStop(context, null);
_logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed);
await sslStream.DisposeAsync();
@ -238,6 +250,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https.Internal
feature.KeyExchangeStrength = sslStream.KeyExchangeStrength;
feature.Protocol = sslStream.SslProtocol;
KestrelEventSource.Log.TlsHandshakeStop(context, feature);
var originalTransport = context.Transport;
try