Skip to content

Commit 8d56d85

Browse files
bgraingerbgrainger
committed
Use higher-resolution durations for metrics. Fixes #1395 
1 parent 25106a5 commit 8d56d85

File tree

5 files changed

+55
-34
lines changed

5 files changed

+55
-34
lines changed

‎src/MySqlConnector/Core/ConnectionPool.cs

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ internal sealed class ConnectionPool : IDisposable
2020

2121
public SslProtocols SslProtocols { get; set; }
2222

23-
public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection, int startTickCount, int timeoutMilliseconds, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
23+
public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection, long startingTimestamp, int timeoutMilliseconds, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
2424
{
2525
cancellationToken.ThrowIfCancellationRequested();
2626

@@ -72,7 +72,7 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
7272
if (ConnectionSettings.ConnectionReset || session.DatabaseOverride is not null)
7373
{
7474
if (timeoutMilliseconds != 0)
75-
session.SetTimeout(Math.Max(1, timeoutMilliseconds - (Environment.TickCount - startTickCount)));
75+
session.SetTimeout(Math.Max(1, timeoutMilliseconds - (int) Utility.GetElapsedMilliseconds(startingTimestamp)));
7676
reuseSession = await session.TryResetConnectionAsync(ConnectionSettings, connection, ioBehavior, cancellationToken).ConfigureAwait(false);
7777
session.SetTimeout(Constants.InfiniteTimeout);
7878
}
@@ -103,14 +103,14 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
103103
ActivitySourceHelper.CopyTags(session.ActivityTags, activity);
104104
Log.ReturningPooledSession(m_logger, Id, session.Id, leasedSessionsCountPooled);
105105

106-
session.LastLeasedTicks = unchecked((uint) Environment.TickCount);
107-
MetricsReporter.RecordWaitTime(this, unchecked(session.LastLeasedTicks - (uint) startTickCount));
106+
session.LastLeasedTimestamp = Stopwatch.GetTimestamp();
107+
MetricsReporter.RecordWaitTime(this, Utility.GetElapsedMilliseconds(startingTimestamp, session.LastLeasedTimestamp));
108108
return session;
109109
}
110110
}
111111

112112
// create a new session
113-
session = await ConnectSessionAsync(connection, s_createdNewSession, startTickCount, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
113+
session = await ConnectSessionAsync(connection, s_createdNewSession, startingTimestamp, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
114114
AdjustHostConnectionCount(session, 1);
115115
session.OwningConnection = new(connection);
116116
int leasedSessionsCountNew;
@@ -122,8 +122,8 @@ public async ValueTask<ServerSession> GetSessionAsync(MySqlConnection connection
122122
MetricsReporter.AddUsed(this);
123123
Log.ReturningNewSession(m_logger, Id, session.Id, leasedSessionsCountNew);
124124

125-
session.LastLeasedTicks = unchecked((uint) Environment.TickCount);
126-
MetricsReporter.RecordCreateTime(this, unchecked(session.LastLeasedTicks - (uint) startTickCount));
125+
session.LastLeasedTimestamp = Stopwatch.GetTimestamp();
126+
MetricsReporter.RecordCreateTime(this, Utility.GetElapsedMilliseconds(startingTimestamp, session.LastLeasedTimestamp));
127127
return session;
128128
}
129129
catch (Exception ex)
@@ -161,7 +161,7 @@ private int GetSessionHealth(ServerSession session)
161161
if (session.PoolGeneration != m_generation)
162162
return 2;
163163
if (ConnectionSettings.ConnectionLifeTime > 0
164-
&& unchecked((uint) Environment.TickCount) - session.CreatedTicks >= ConnectionSettings.ConnectionLifeTime)
164+
&& Utility.GetElapsedMilliseconds(session.CreatedTimestamp) >= ConnectionSettings.ConnectionLifeTime)
165165
return 3;
166166

167167
return 0;
@@ -214,7 +214,7 @@ public async Task ReapAsync(IOBehavior ioBehavior, CancellationToken cancellatio
214214
{
215215
Log.ReapingConnectionPool(m_logger, Id);
216216
await RecoverLeakedSessionsAsync(ioBehavior).ConfigureAwait(false);
217-
await CleanPoolAsync(ioBehavior, session => (unchecked((uint) Environment.TickCount) - session.LastReturnedTicks) / 1000 >= ConnectionSettings.ConnectionIdleTimeout, true, cancellationToken).ConfigureAwait(false);
217+
await CleanPoolAsync(ioBehavior, session => Utility.GetElapsedMilliseconds(session.LastReturnedTimestamp) / 1000 >= ConnectionSettings.ConnectionIdleTimeout, true, cancellationToken).ConfigureAwait(false);
218218
}
219219

220220
/// <summary>
@@ -403,7 +403,7 @@ private async Task CreateMinimumPooledSessions(MySqlConnection connection, IOBeh
403403

404404
try
405405
{
406-
var session = await ConnectSessionAsync(connection, s_createdToReachMinimumPoolSize, Environment.TickCount, null, ioBehavior, cancellationToken).ConfigureAwait(false);
406+
var session = await ConnectSessionAsync(connection, s_createdToReachMinimumPoolSize, Stopwatch.GetTimestamp(), null, ioBehavior, cancellationToken).ConfigureAwait(false);
407407
AdjustHostConnectionCount(session, 1);
408408
lock (m_sessions)
409409
m_sessions.AddFirst(session);
@@ -417,15 +417,15 @@ private async Task CreateMinimumPooledSessions(MySqlConnection connection, IOBeh
417417
}
418418
}
419419

420-
private async ValueTask<ServerSession> ConnectSessionAsync(MySqlConnection connection, Action<ILogger, int, string, Exception?> logMessage, int startTickCount, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
420+
private async ValueTask<ServerSession> ConnectSessionAsync(MySqlConnection connection, Action<ILogger, int, string, Exception?> logMessage, long startingTimestamp, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
421421
{
422422
var session = new ServerSession(m_connectionLogger, this, m_generation, Interlocked.Increment(ref m_lastSessionId));
423423
if (m_logger.IsEnabled(LogLevel.Debug))
424424
logMessage(m_logger, Id, session.Id, null);
425425
string? statusInfo;
426426
try
427427
{
428-
statusInfo = await session.ConnectAsync(ConnectionSettings, connection, startTickCount, m_loadBalancer, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
428+
statusInfo = await session.ConnectAsync(ConnectionSettings, connection, startingTimestamp, m_loadBalancer, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
429429
}
430430
catch (Exception)
431431
{
@@ -452,7 +452,7 @@ private async ValueTask<ServerSession> ConnectSessionAsync(MySqlConnection conne
452452
var redirectedSession = new ServerSession(m_connectionLogger, this, m_generation, Interlocked.Increment(ref m_lastSessionId));
453453
try
454454
{
455-
await redirectedSession.ConnectAsync(redirectedSettings, connection, startTickCount, m_loadBalancer, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
455+
await redirectedSession.ConnectAsync(redirectedSettings, connection, startingTimestamp, m_loadBalancer, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
456456
}
457457
catch (Exception ex)
458458
{

‎src/MySqlConnector/Core/MetricsReporter.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -9,9 +9,9 @@ internal static class MetricsReporter
99
public static void RemoveIdle(ConnectionPool pool) => s_connectionsUsageCounter.Add(-1, pool.IdleStateTagList);
1010
public static void AddUsed(ConnectionPool pool) => s_connectionsUsageCounter.Add(1, pool.UsedStateTagList);
1111
public static void RemoveUsed(ConnectionPool pool) => s_connectionsUsageCounter.Add(-1, pool.UsedStateTagList);
12-
public static void RecordCreateTime(ConnectionPool pool, uint ticks) => s_createTimeHistory.Record(ticks, pool.PoolNameTagList);
13-
public static void RecordUseTime(ConnectionPool pool, uint ticks) => s_useTimeHistory.Record(ticks, pool.PoolNameTagList);
14-
public static void RecordWaitTime(ConnectionPool pool, uint ticks) => s_waitTimeHistory.Record(ticks, pool.PoolNameTagList);
12+
public static void RecordCreateTime(ConnectionPool pool, float milliseconds) => s_createTimeHistory.Record(milliseconds, pool.PoolNameTagList);
13+
public static void RecordUseTime(ConnectionPool pool, float milliseconds) => s_useTimeHistory.Record(milliseconds, pool.PoolNameTagList);
14+
public static void RecordWaitTime(ConnectionPool pool, float milliseconds) => s_waitTimeHistory.Record(milliseconds, pool.PoolNameTagList);
1515

1616
public static void AddPendingRequest(ConnectionPool? pool)
1717
{

‎src/MySqlConnector/Core/ServerSession.cs

Lines changed: 12 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ public ServerSession(ILogger logger, ConnectionPool? pool, int poolGeneration, i
3838
m_payloadCache = new();
3939
Id = (pool?.Id ?? 0) + "." + id;
4040
ServerVersion = ServerVersion.Empty;
41-
CreatedTicks = unchecked((uint) Environment.TickCount);
41+
CreatedTimestamp = Stopwatch.GetTimestamp();
4242
Pool = pool;
4343
PoolGeneration = poolGeneration;
4444
HostName = "";
@@ -54,11 +54,11 @@ public ServerSession(ILogger logger, ConnectionPool? pool, int poolGeneration, i
5454
public int CancellationTimeout { get; private set; }
5555
public int ConnectionId { get; set; }
5656
public byte[]? AuthPluginData { get; set; }
57-
public uint CreatedTicks { get; }
57+
public long CreatedTimestamp { get; }
5858
public ConnectionPool? Pool { get; }
5959
public int PoolGeneration { get; }
60-
public uint LastLeasedTicks { get; set; }
61-
public uint LastReturnedTicks { get; private set; }
60+
public long LastLeasedTimestamp { get; set; }
61+
public long LastReturnedTimestamp { get; private set; }
6262
public string? DatabaseOverride { get; set; }
6363
public string HostName { get; private set; }
6464
public IPEndPoint? IPEndPoint => m_tcpClient?.Client.RemoteEndPoint as IPEndPoint;
@@ -75,11 +75,11 @@ public ServerSession(ILogger logger, ConnectionPool? pool, int poolGeneration, i
7575
public ValueTask ReturnToPoolAsync(IOBehavior ioBehavior, MySqlConnection? owningConnection)
7676
{
7777
Log.ReturningToPool(m_logger, Id, Pool?.Id ?? 0);
78-
LastReturnedTicks = unchecked((uint) Environment.TickCount);
78+
LastReturnedTimestamp = Stopwatch.GetTimestamp();
7979
if (Pool is null)
8080
return default;
81-
MetricsReporter.RecordUseTime(Pool, unchecked(LastReturnedTicks - LastLeasedTicks));
82-
LastLeasedTicks = 0;
81+
MetricsReporter.RecordUseTime(Pool, Utility.GetElapsedMilliseconds(LastLeasedTimestamp, LastReturnedTimestamp));
82+
LastLeasedTimestamp = 0;
8383
return Pool.ReturnAsync(ioBehavior, this);
8484
}
8585

@@ -392,7 +392,7 @@ public async Task DisposeAsync(IOBehavior ioBehavior, CancellationToken cancella
392392
m_state = State.Closed;
393393
}
394394

395-
public async Task<string?> ConnectAsync(ConnectionSettings cs, MySqlConnection connection, int startTickCount, ILoadBalancer? loadBalancer, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
395+
public async Task<string?> ConnectAsync(ConnectionSettings cs, MySqlConnection connection, long startingTimestamp, ILoadBalancer? loadBalancer, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
396396
{
397397
string? statusInfo = null;
398398

@@ -445,7 +445,7 @@ public async Task DisposeAsync(IOBehavior ioBehavior, CancellationToken cancella
445445
else if (cs.ConnectionProtocol == MySqlConnectionProtocol.UnixSocket)
446446
connected = await OpenUnixSocketAsync(cs, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
447447
else if (cs.ConnectionProtocol == MySqlConnectionProtocol.NamedPipe)
448-
connected = await OpenNamedPipeAsync(cs, startTickCount, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
448+
connected = await OpenNamedPipeAsync(cs, startingTimestamp, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
449449
if (!connected)
450450
{
451451
lock (m_lock)
@@ -456,7 +456,7 @@ public async Task DisposeAsync(IOBehavior ioBehavior, CancellationToken cancella
456456

457457
var byteHandler = m_socket is null ? new StreamByteHandler(m_stream!) : (IByteHandler) new SocketByteHandler(m_socket);
458458
if (cs.ConnectionTimeout != 0)
459-
byteHandler.RemainingTimeout = Math.Max(1, cs.ConnectionTimeoutMilliseconds - unchecked(Environment.TickCount - startTickCount));
459+
byteHandler.RemainingTimeout = Math.Max(1, cs.ConnectionTimeoutMilliseconds - (int) Utility.GetElapsedMilliseconds(startingTimestamp));
460460
m_payloadHandler = new StandardPayloadHandler(byteHandler);
461461

462462
payload = await ReceiveAsync(ioBehavior, cancellationToken).ConfigureAwait(false);
@@ -1200,7 +1200,7 @@ private async Task<bool> OpenUnixSocketAsync(ConnectionSettings cs, Activity? ac
12001200
return false;
12011201
}
12021202

1203-
private async Task<bool> OpenNamedPipeAsync(ConnectionSettings cs, int startTickCount, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
1203+
private async Task<bool> OpenNamedPipeAsync(ConnectionSettings cs, long startingTimestamp, Activity? activity, IOBehavior ioBehavior, CancellationToken cancellationToken)
12041204
{
12051205
Log.ConnectingToNamedPipe(m_logger, Id, cs.PipeName, cs.HostNames![0]);
12061206

@@ -1218,7 +1218,7 @@ private async Task<bool> OpenNamedPipeAsync(ConnectionSettings cs, int startTick
12181218
}
12191219

12201220
var namedPipeStream = new NamedPipeClientStream(cs.HostNames![0], cs.PipeName, PipeDirection.InOut, PipeOptions.Asynchronous);
1221-
var timeout = Math.Max(1, cs.ConnectionTimeoutMilliseconds - unchecked(Environment.TickCount - startTickCount));
1221+
var timeout = Math.Max(1, cs.ConnectionTimeoutMilliseconds - (int) Utility.GetElapsedMilliseconds(startingTimestamp));
12221222
try
12231223
{
12241224
using (cancellationToken.Register(namedPipeStream.Dispose))

‎src/MySqlConnector/MySqlConnection.cs

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -384,7 +384,7 @@ private async ValueTask<bool> PingAsync(IOBehavior ioBehavior, CancellationToken
384384

385385
internal async Task OpenAsync(IOBehavior? ioBehavior, CancellationToken cancellationToken)
386386
{
387-
var openStartTickCount = Environment.TickCount;
387+
var openStartingTimestamp = Stopwatch.GetTimestamp();
388388

389389
VerifyNotDisposed();
390390
cancellationToken.ThrowIfCancellationRequested();
@@ -416,7 +416,7 @@ internal async Task OpenAsync(IOBehavior? ioBehavior, CancellationToken cancella
416416

417417
try
418418
{
419-
m_session = await CreateSessionAsync(pool, openStartTickCount, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
419+
m_session = await CreateSessionAsync(pool, openStartingTimestamp, activity, ioBehavior, cancellationToken).ConfigureAwait(false);
420420
m_hasBeenOpened = true;
421421
SetState(ConnectionState.Open);
422422
}
@@ -894,7 +894,7 @@ internal void FinishQuerying(bool hasWarnings)
894894
}
895895
}
896896

897-
private async ValueTask<ServerSession> CreateSessionAsync(ConnectionPool? pool, int startTickCount, Activity? activity, IOBehavior? ioBehavior, CancellationToken cancellationToken)
897+
private async ValueTask<ServerSession> CreateSessionAsync(ConnectionPool? pool, long startingTimestamp, Activity? activity, IOBehavior? ioBehavior, CancellationToken cancellationToken)
898898
{
899899
MetricsReporter.AddPendingRequest(pool);
900900
var connectionSettings = GetInitializedConnectionSettings();
@@ -907,7 +907,7 @@ private async ValueTask<ServerSession> CreateSessionAsync(ConnectionPool? pool,
907907
// the cancellation token for connection is controlled by 'cancellationToken' (if it can be cancelled), ConnectionTimeout
908908
// (from the connection string, if non-zero), or a combination of both
909909
if (connectionSettings.ConnectionTimeout != 0)
910-
timeoutSource = new CancellationTokenSource(TimeSpan.FromMilliseconds(Math.Max(1, connectionSettings.ConnectionTimeoutMilliseconds - unchecked(Environment.TickCount - startTickCount))));
910+
timeoutSource = new CancellationTokenSource(TimeSpan.FromMilliseconds(Math.Max(1, connectionSettings.ConnectionTimeoutMilliseconds - (int) Utility.GetElapsedMilliseconds(startingTimestamp))));
911911
if (cancellationToken.CanBeCanceled && timeoutSource is not null)
912912
linkedSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken, timeoutSource.Token);
913913
var connectToken = linkedSource?.Token ?? timeoutSource?.Token ?? cancellationToken;
@@ -916,7 +916,7 @@ private async ValueTask<ServerSession> CreateSessionAsync(ConnectionPool? pool,
916916
if (pool is not null)
917917
{
918918
// this returns an open session
919-
return await pool.GetSessionAsync(this, startTickCount, connectionSettings.ConnectionTimeoutMilliseconds, activity, actualIOBehavior, connectToken).ConfigureAwait(false);
919+
return await pool.GetSessionAsync(this, startingTimestamp, connectionSettings.ConnectionTimeoutMilliseconds, activity, actualIOBehavior, connectToken).ConfigureAwait(false);
920920
}
921921
else
922922
{
@@ -929,7 +929,7 @@ private async ValueTask<ServerSession> CreateSessionAsync(ConnectionPool? pool,
929929
Log.CreatedNonPooledSession(m_logger, session.Id);
930930
try
931931
{
932-
await session.ConnectAsync(connectionSettings, this, startTickCount, loadBalancer, activity, actualIOBehavior, connectToken).ConfigureAwait(false);
932+
await session.ConnectAsync(connectionSettings, this, startingTimestamp, loadBalancer, activity, actualIOBehavior, connectToken).ConfigureAwait(false);
933933
return session;
934934
}
935935
catch (Exception)

‎src/MySqlConnector/Utilities/Utility.cs

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
using System.Buffers;
22
using System.Buffers.Text;
3+
using System.Diagnostics;
34
using System.Diagnostics.CodeAnalysis;
45
using System.Net;
56
using System.Reflection;
@@ -564,6 +565,26 @@ public static void GetOSDetails(out string? os, out string osDescription, out st
564565
}
565566
#endif
566567

568+
/// <summary>
569+
/// Gets the elapsed time (in milliseconds) since the specified <paramref name="startingTimestamp"/> (which must be a value returned from <see cref="Stopwatch.GetTimestamp"/>.
570+
/// </summary>
571+
public static float GetElapsedMilliseconds(long startingTimestamp) =>
572+
#if NET7_0_OR_GREATER
573+
(float) Stopwatch.GetElapsedTime(startingTimestamp).TotalMilliseconds;
574+
#else
575+
GetElapsedMilliseconds(startingTimestamp, Stopwatch.GetTimestamp());
576+
#endif
577+
578+
/// <summary>
579+
/// Gets the elapsed time (in milliseconds) between the specified <paramref name="startingTimestamp"/> and <paramref name="endingTimestamp"/>. (These must be values returned from <see cref="Stopwatch.GetTimestamp"/>.)
580+
/// </summary>
581+
public static float GetElapsedMilliseconds(long startingTimestamp, long endingTimestamp) =>
582+
#if NET7_0_OR_GREATER
583+
(float) Stopwatch.GetElapsedTime(startingTimestamp, endingTimestamp).TotalMilliseconds;
584+
#else
585+
(endingTimestamp - startingTimestamp) * 1000.0f / Stopwatch.Frequency;
586+
#endif
587+
567588
#if NET462
568589
public static SslProtocols GetDefaultSslProtocols()
569590
{

0 commit comments

Comments
 (0)