From b5b3e1679abc7b9b1229bf9a6a8e77206ec40517 Mon Sep 17 00:00:00 2001 From: Shay Rojansky Date: Tue, 25 Jul 2023 12:04:52 +0200 Subject: [PATCH 1/2] Stop instantiating Stopwatch Closes #26295 --- .../Storage/RelationalCommand.cs | 81 ++++++++++++------- .../Storage/RelationalConnection.cs | 56 +++++++------ .../Storage/RelationalDataReader.cs | 8 +- .../Storage/RelationalTransaction.cs | 48 +++++------ .../SqliteCommand.cs | 24 +++--- .../SqliteDataReader.cs | 14 ++-- .../Utilities/StopwatchUtils.cs | 23 ++++++ 7 files changed, 158 insertions(+), 96 deletions(-) create mode 100644 src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs diff --git a/src/EFCore.Relational/Storage/RelationalCommand.cs b/src/EFCore.Relational/Storage/RelationalCommand.cs index 3b6322a76ca..c21735ab320 100644 --- a/src/EFCore.Relational/Storage/RelationalCommand.cs +++ b/src/EFCore.Relational/Storage/RelationalCommand.cs @@ -21,7 +21,6 @@ namespace Microsoft.EntityFrameworkCore.Storage; public class RelationalCommand : IRelationalCommand { private RelationalDataReader? _relationalReader; - private readonly Stopwatch _stopwatch = new(); /// /// @@ -81,11 +80,13 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.Open(); + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger?.CommandNonQueryExecuting( connection, @@ -109,7 +110,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, nonQueryResult, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource) ?? nonQueryResult; } @@ -120,6 +121,8 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -130,7 +133,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } else @@ -144,7 +147,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } @@ -183,11 +186,13 @@ public virtual async Task ExecuteNonQueryAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger == null ? default @@ -216,7 +221,7 @@ public virtual async Task ExecuteNonQueryAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -231,6 +236,8 @@ public virtual async Task ExecuteNonQueryAsync( } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -243,7 +250,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -259,7 +266,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -295,11 +302,13 @@ await logger.CommandErrorAsync( connection.Open(); + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger?.CommandScalarExecuting( connection, @@ -323,7 +332,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource) ?? result; } @@ -334,6 +343,8 @@ await logger.CommandErrorAsync( } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -344,7 +355,7 @@ await logger.CommandErrorAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } else @@ -358,7 +369,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } @@ -397,11 +408,13 @@ await logger.CommandErrorAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger == null ? default @@ -430,7 +443,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource, cancellationToken).ConfigureAwait(false); } @@ -444,6 +457,8 @@ await logger.CommandErrorAsync( } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -456,7 +471,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -472,7 +487,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -515,11 +530,13 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje var readerOpen = false; DbDataReader reader; + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger!.CommandReaderExecuting( connection, @@ -542,7 +559,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, reader, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource); } else @@ -552,6 +569,8 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -562,7 +581,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } else @@ -576,7 +595,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource); } @@ -643,11 +662,13 @@ public virtual async Task ExecuteReaderAsync( var readerOpen = false; DbDataReader reader; + long startTimestamp = 0; + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = await logger!.CommandReaderExecutingAsync( connection, @@ -672,7 +693,7 @@ public virtual async Task ExecuteReaderAsync( connection.ConnectionId, reader, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -684,6 +705,8 @@ public virtual async Task ExecuteReaderAsync( } catch (Exception exception) { + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -696,7 +719,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -712,7 +735,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + elapsedTime, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -776,10 +799,12 @@ public virtual DbCommand CreateDbCommand( DbCommand command; + long startTimestamp = 0; + var logCommandCreate = logger?.ShouldLogCommandCreate(startTime) == true; if (logCommandCreate) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger!.CommandCreating( connection, commandMethod, context, commandId, connectionId, startTime, @@ -797,7 +822,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource); } else @@ -832,7 +857,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), parameterObject.CommandSource); } diff --git a/src/EFCore.Relational/Storage/RelationalConnection.cs b/src/EFCore.Relational/Storage/RelationalConnection.cs index b0aadea1a5a..62095665cbf 100644 --- a/src/EFCore.Relational/Storage/RelationalConnection.cs +++ b/src/EFCore.Relational/Storage/RelationalConnection.cs @@ -43,7 +43,6 @@ public abstract class RelationalConnection : IRelationalConnection, ITransaction private DbConnection? _connection; private readonly IRelationalCommandBuilder _relationalCommandBuilder; private IRelationalCommand? _cachedRelationalCommand; - private readonly Stopwatch _stopwatch = new(); /// /// Initializes a new instance of the class. @@ -153,7 +152,7 @@ public virtual DbConnection DbConnection if (logger.ShouldLogConnectionCreate(startTime)) { - _stopwatch.Restart(); + var startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger.ConnectionCreating(this, startTime); @@ -161,7 +160,7 @@ public virtual DbConnection DbConnection ? interceptionResult.Result : CreateDbConnection(); - _connection = logger.ConnectionCreated(this, startTime, _stopwatch.Elapsed); + _connection = logger.ConnectionCreated(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); } else { @@ -340,7 +339,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe var transactionId = Guid.NewGuid(); var startTime = DateTimeOffset.UtcNow; - _stopwatch.Restart(); + var startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = Dependencies.TransactionLogger.TransactionStarting( this, @@ -357,7 +356,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe dbTransaction, transactionId, startTime, - _stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); return CreateRelationalTransaction(dbTransaction, transactionId, true); } @@ -391,7 +390,7 @@ public virtual async Task BeginTransactionAsync( var transactionId = Guid.NewGuid(); var startTime = DateTimeOffset.UtcNow; - _stopwatch.Restart(); + var startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = await Dependencies.TransactionLogger.TransactionStartingAsync( this, @@ -410,7 +409,7 @@ public virtual async Task BeginTransactionAsync( dbTransaction, transactionId, startTime, - _stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) .ConfigureAwait(false); @@ -711,11 +710,13 @@ private void OpenInternal(bool errorsExpected) var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + long startTimestamp = 0; + try { if (logger.ShouldLogConnectionOpen(startTime)) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger.ConnectionOpening(this, startTime); @@ -724,7 +725,7 @@ private void OpenInternal(bool errorsExpected) OpenDbConnection(errorsExpected); } - logger.ConnectionOpened(this, startTime, _stopwatch.Elapsed); + logger.ConnectionOpened(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); } else { @@ -733,7 +734,9 @@ private void OpenInternal(bool errorsExpected) } catch (Exception e) { - logger.ConnectionError(this, e, startTime, _stopwatch.Elapsed, errorsExpected); + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + + logger.ConnectionError(this, e, startTime, elapsedTime, errorsExpected); throw; } @@ -756,12 +759,13 @@ private async Task OpenInternalAsync(bool errorsExpected, CancellationToken canc { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + long startTimestamp = 0; try { if (logger.ShouldLogConnectionOpen(startTime)) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = await logger.ConnectionOpeningAsync(this, startTime, cancellationToken).ConfigureAwait(false); @@ -771,7 +775,8 @@ var interceptionResult await OpenDbConnectionAsync(errorsExpected, cancellationToken).ConfigureAwait(false); } - await logger.ConnectionOpenedAsync(this, startTime, _stopwatch.Elapsed, cancellationToken).ConfigureAwait(false); + await logger.ConnectionOpenedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) + .ConfigureAwait(false); } else { @@ -784,7 +789,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - DateTimeOffset.UtcNow - startTime, + startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero, errorsExpected, cancellationToken) .ConfigureAwait(false); @@ -878,12 +883,13 @@ public virtual bool Close() { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + long startTimestamp = 0; try { if (logger.ShouldLogConnectionClose(startTime)) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger.ConnectionClosing(this, startTime); @@ -892,7 +898,7 @@ public virtual bool Close() CloseDbConnection(); } - logger.ConnectionClosed(this, startTime, _stopwatch.Elapsed); + logger.ConnectionClosed(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); } else { @@ -903,7 +909,9 @@ public virtual bool Close() } catch (Exception e) { - logger.ConnectionError(this, e, startTime, _stopwatch.Elapsed, false); + var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; + + logger.ConnectionError(this, e, startTime, elapsedTime, false); throw; } @@ -942,6 +950,8 @@ public virtual async Task CloseAsync() ClearTransactions(clearAmbient: false); + long startTimestamp = 0; + if (DbConnection.State != ConnectionState.Closed) { var logger = Dependencies.ConnectionLogger; @@ -951,7 +961,7 @@ public virtual async Task CloseAsync() { if (logger.ShouldLogConnectionClose(startTime)) { - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = await logger.ConnectionClosingAsync(this, startTime) .ConfigureAwait(false); @@ -961,7 +971,7 @@ public virtual async Task CloseAsync() await CloseDbConnectionAsync().ConfigureAwait(false); } - await logger.ConnectionClosedAsync(this, startTime, _stopwatch.Elapsed) + await logger.ConnectionClosedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)) .ConfigureAwait(false); } else @@ -977,7 +987,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - DateTimeOffset.UtcNow - startTime, + startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero, false) .ConfigureAwait(false); @@ -1100,7 +1110,7 @@ protected virtual void DisposeDbConnection() if (logger.ShouldLogConnectionDispose(startTime)) { - _stopwatch.Restart(); + var startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = logger.ConnectionDisposing(this, startTime); @@ -1109,7 +1119,7 @@ protected virtual void DisposeDbConnection() DbConnection.Dispose(); } - logger.ConnectionDisposed(this, startTime, _stopwatch.Elapsed); + logger.ConnectionDisposed(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); } else { @@ -1128,7 +1138,7 @@ protected virtual async ValueTask DisposeDbConnectionAsync() if (logger.ShouldLogConnectionDispose(startTime)) { - _stopwatch.Restart(); + var startTimestamp = Stopwatch.GetTimestamp(); var interceptionResult = await logger.ConnectionDisposingAsync(this, startTime).ConfigureAwait(false); @@ -1137,7 +1147,7 @@ protected virtual async ValueTask DisposeDbConnectionAsync() await DbConnection.DisposeAsync().ConfigureAwait(false); } - await logger.ConnectionDisposedAsync(this, startTime, _stopwatch.Elapsed).ConfigureAwait(false); + await logger.ConnectionDisposedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)).ConfigureAwait(false); } else { diff --git a/src/EFCore.Relational/Storage/RelationalDataReader.cs b/src/EFCore.Relational/Storage/RelationalDataReader.cs index 3e1e25da6d5..065c38c5e68 100644 --- a/src/EFCore.Relational/Storage/RelationalDataReader.cs +++ b/src/EFCore.Relational/Storage/RelationalDataReader.cs @@ -24,7 +24,7 @@ public class RelationalDataReader : IDisposable, IAsyncDisposable private Guid _commandId; private IRelationalCommandDiagnosticsLogger? _logger; private DateTimeOffset _startTime; - private readonly Stopwatch _stopwatch = new(); + private long startTimestamp; private int _readCount; @@ -55,7 +55,7 @@ public virtual void Initialize( _closed = false; _disposed = false; _startTime = DateTimeOffset.UtcNow; - _stopwatch.Restart(); + startTimestamp = Stopwatch.GetTimestamp(); } /// @@ -166,7 +166,7 @@ public virtual void Dispose() _reader.RecordsAffected, _readCount, _startTime, - _stopwatch.Elapsed); // can throw + Stopwatch.GetElapsedTime(startTimestamp)); } } finally @@ -262,7 +262,7 @@ public virtual async ValueTask DisposeAsync() _reader.RecordsAffected, _readCount, _startTime, - _stopwatch.Elapsed); // can throw + Stopwatch.GetElapsedTime(startTimestamp)); } } finally diff --git a/src/EFCore.Relational/Storage/RelationalTransaction.cs b/src/EFCore.Relational/Storage/RelationalTransaction.cs index d30a8aba31e..b75e8bf3253 100644 --- a/src/EFCore.Relational/Storage/RelationalTransaction.cs +++ b/src/EFCore.Relational/Storage/RelationalTransaction.cs @@ -74,7 +74,7 @@ public RelationalTransaction( public virtual void Commit() { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -94,7 +94,7 @@ public virtual void Commit() _dbTransaction, TransactionId, startTime, - stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); } catch (Exception e) { @@ -105,7 +105,7 @@ public virtual void Commit() "Commit", e, startTime, - stopwatch.Elapsed); + startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero); throw; } @@ -117,7 +117,7 @@ public virtual void Commit() public virtual void Rollback() { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -137,7 +137,7 @@ public virtual void Rollback() _dbTransaction, TransactionId, startTime, - stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); } catch (Exception e) { @@ -148,7 +148,7 @@ public virtual void Rollback() "Rollback", e, startTime, - stopwatch.Elapsed); + startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero); throw; } @@ -160,7 +160,7 @@ public virtual void Rollback() public virtual async Task CommitAsync(CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -182,7 +182,7 @@ await Logger.TransactionCommittedAsync( _dbTransaction, TransactionId, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) .ConfigureAwait(false); } @@ -195,7 +195,7 @@ await Logger.TransactionErrorAsync( "Commit", e, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) .ConfigureAwait(false); @@ -209,7 +209,7 @@ await Logger.TransactionErrorAsync( public virtual async Task RollbackAsync(CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -231,7 +231,7 @@ await Logger.TransactionRolledBackAsync( _dbTransaction, TransactionId, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) .ConfigureAwait(false); } @@ -244,7 +244,7 @@ await Logger.TransactionErrorAsync( "Rollback", e, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) .ConfigureAwait(false); @@ -258,7 +258,7 @@ await Logger.TransactionErrorAsync( public virtual void CreateSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -291,7 +291,7 @@ public virtual void CreateSavepoint(string name) "CreateSavepoint", e, startTime, - stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); throw; } @@ -301,7 +301,7 @@ public virtual void CreateSavepoint(string name) public virtual async Task CreateSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -337,7 +337,7 @@ await Logger.TransactionErrorAsync( "CreateSavepoint", e, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken).ConfigureAwait(false); throw; @@ -348,7 +348,7 @@ await Logger.TransactionErrorAsync( public virtual void RollbackToSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -381,7 +381,7 @@ public virtual void RollbackToSavepoint(string name) "RollbackToSavepoint", e, startTime, - stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); throw; } @@ -391,7 +391,7 @@ public virtual void RollbackToSavepoint(string name) public virtual async Task RollbackToSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -427,7 +427,7 @@ await Logger.TransactionErrorAsync( "RollbackToSavepoint", e, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken).ConfigureAwait(false); throw; @@ -438,7 +438,7 @@ await Logger.TransactionErrorAsync( public virtual void ReleaseSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -471,7 +471,7 @@ public virtual void ReleaseSavepoint(string name) "ReleaseSavepoint", e, startTime, - stopwatch.Elapsed); + Stopwatch.GetElapsedTime(startTimestamp)); throw; } @@ -481,7 +481,7 @@ public virtual void ReleaseSavepoint(string name) public virtual async Task ReleaseSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var startTimestamp = Stopwatch.GetTimestamp(); try { @@ -517,7 +517,7 @@ await Logger.TransactionErrorAsync( "ReleaseSavepoint", e, startTime, - stopwatch.Elapsed, + Stopwatch.GetElapsedTime(startTimestamp), cancellationToken).ConfigureAwait(false); throw; diff --git a/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs b/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs index 7ea911ecb93..2c3fc515651 100644 --- a/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs +++ b/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs @@ -256,9 +256,7 @@ public override void Prepare() return; } - var timer = new Stopwatch(); - - using var enumerator = PrepareAndEnumerateStatements(timer).GetEnumerator(); + using var enumerator = PrepareAndEnumerateStatements().GetEnumerator(); while (enumerator.MoveNext()) { } @@ -307,19 +305,18 @@ public override void Prepare() throw new InvalidOperationException(Resources.TransactionCompleted); } - var timer = new Stopwatch(); var closeConnection = behavior.HasFlag(CommandBehavior.CloseConnection); - var dataReader = new SqliteDataReader(this, timer, GetStatements(timer), closeConnection); + var dataReader = new SqliteDataReader(this, GetStatements(), closeConnection); dataReader.NextResult(); return DataReader = dataReader; } - private IEnumerable GetStatements(Stopwatch timer) + private IEnumerable GetStatements() { foreach ((var stmt, var expectedParams) in !_prepared - ? PrepareAndEnumerateStatements(timer) + ? PrepareAndEnumerateStatements() : _preparedStatements) { var boundParams = _parameters?.Bind(stmt) ?? 0; @@ -466,7 +463,7 @@ public override void Cancel() { } - private IEnumerable<(sqlite3_stmt Statement, int ParamCount)> PrepareAndEnumerateStatements(Stopwatch timer) + private IEnumerable<(sqlite3_stmt Statement, int ParamCount)> PrepareAndEnumerateStatements() { DisposePreparedStatements(disposing: false); @@ -474,26 +471,31 @@ public override void Cancel() var sql = new byte[byteCount + 1]; Encoding.UTF8.GetBytes(_commandText, 0, _commandText.Length, sql, 0); + var elapsedTime = TimeSpan.Zero; int rc; sqlite3_stmt stmt; var start = 0; do { - timer.Start(); + var startTimestamp = Stopwatch.GetTimestamp(); ReadOnlySpan tail; while (IsBusy(rc = sqlite3_prepare_v2(_connection!.Handle, sql.AsSpan(start), out stmt, out tail))) { if (CommandTimeout != 0 - && timer.ElapsedMilliseconds >= CommandTimeout * 1000L) + && elapsedTime.TotalMilliseconds >= CommandTimeout * 1000L) { break; } Thread.Sleep(150); + + if (CommandTimeout != 0) + { + elapsedTime += StopwatchUtils.GetElapsedTime(startTimestamp); + } } - timer.Stop(); start = sql.Length - tail.Length; SqliteException.ThrowExceptionForRC(rc, _connection.Handle); diff --git a/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs b/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs index 50031bc36f0..1737586c990 100644 --- a/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs +++ b/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs @@ -25,7 +25,7 @@ public class SqliteDataReader : DbDataReader { private readonly SqliteCommand _command; private readonly bool _closeConnection; - private readonly Stopwatch _timer; + private TimeSpan _elapsedTime; private IEnumerator? _stmtEnumerator; private SqliteDataRecord? _record; private bool _closed; @@ -33,12 +33,10 @@ public class SqliteDataReader : DbDataReader internal SqliteDataReader( SqliteCommand command, - Stopwatch timer, IEnumerable stmts, bool closeConnection) { _command = command; - _timer = timer; _stmtEnumerator = stmts.GetEnumerator(); _closeConnection = closeConnection; } @@ -155,12 +153,12 @@ public override bool NextResult() { stmt = _stmtEnumerator.Current; - _timer.Start(); + var startTimestamp = Stopwatch.GetTimestamp(); while (IsBusy(rc = sqlite3_step(stmt))) { if (_command.CommandTimeout != 0 - && _timer.ElapsedMilliseconds >= _command.CommandTimeout * 1000L) + && _elapsedTime.TotalMilliseconds >= _command.CommandTimeout * 1000L) { break; } @@ -169,9 +167,13 @@ public override bool NextResult() // TODO: Consider having an async path that uses Task.Delay() Thread.Sleep(150); + + if (_command.CommandTimeout != 0) + { + _elapsedTime += StopwatchUtils.GetElapsedTime(startTimestamp); + } } - _timer.Stop(); SqliteException.ThrowExceptionForRC(rc, _command.Connection!.Handle); diff --git a/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs b/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs new file mode 100644 index 00000000000..374a76c3667 --- /dev/null +++ b/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs @@ -0,0 +1,23 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; + +// ReSharper disable once CheckNamespace +namespace Microsoft.Data.Sqlite; + +internal static class StopwatchUtils +{ + internal static TimeSpan GetElapsedTime(long startTimestamp) +#if NET7_0_OR_GREATER + => Stopwatch.GetElapsedTime(startTimestamp); +#else + => new((long)((Stopwatch.GetTimestamp() - startTimestamp) * StopWatchTickFrequency)); + + private const long TicksPerMicrosecond = 10; + private const long TicksPerMillisecond = TicksPerMicrosecond * 1000; + private const long TicksPerSecond = TicksPerMillisecond * 1000; // 10,000,000 + private static readonly double StopWatchTickFrequency = (double)TicksPerSecond / Stopwatch.Frequency; +#endif +} From 8627125eafe1a057dede8537be2d0acb5352bfcf Mon Sep 17 00:00:00 2001 From: Shay Rojansky Date: Wed, 26 Jul 2023 16:22:06 +0200 Subject: [PATCH 2/2] Switch to using SharedStopwatch --- .../Storage/RelationalCommand.cs | 80 +++++++------------ .../Storage/RelationalConnection.cs | 57 +++++-------- .../Storage/RelationalDataReader.cs | 8 +- .../Storage/RelationalTransaction.cs | 48 +++++------ .../SqliteCommand.cs | 13 ++- .../SqliteDataReader.cs | 13 ++- .../Utilities/SharedStopwatch.cs | 41 ++++++++++ .../Utilities/StopwatchUtils.cs | 23 ------ src/Shared/SharedStopwatch.cs | 38 +++++++++ 9 files changed, 166 insertions(+), 155 deletions(-) create mode 100644 src/Microsoft.Data.Sqlite.Core/Utilities/SharedStopwatch.cs delete mode 100644 src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs create mode 100644 src/Shared/SharedStopwatch.cs diff --git a/src/EFCore.Relational/Storage/RelationalCommand.cs b/src/EFCore.Relational/Storage/RelationalCommand.cs index c21735ab320..e1556dca990 100644 --- a/src/EFCore.Relational/Storage/RelationalCommand.cs +++ b/src/EFCore.Relational/Storage/RelationalCommand.cs @@ -80,14 +80,12 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.Open(); - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger?.CommandNonQueryExecuting( connection, command, @@ -110,7 +108,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, nonQueryResult, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource) ?? nonQueryResult; } @@ -121,8 +119,6 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -133,7 +129,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -147,7 +143,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -186,14 +182,12 @@ public virtual async Task ExecuteNonQueryAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger == null ? default : await logger.CommandNonQueryExecutingAsync( @@ -221,7 +215,7 @@ public virtual async Task ExecuteNonQueryAsync( connection.ConnectionId, result, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -236,8 +230,6 @@ public virtual async Task ExecuteNonQueryAsync( } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -250,7 +242,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -266,7 +258,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -302,14 +294,12 @@ await logger.CommandErrorAsync( connection.Open(); - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger?.CommandScalarExecuting( connection, command, @@ -332,7 +322,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource) ?? result; } @@ -343,8 +333,6 @@ await logger.CommandErrorAsync( } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -355,7 +343,7 @@ await logger.CommandErrorAsync( commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -369,7 +357,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -408,14 +396,12 @@ await logger.CommandErrorAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger == null ? default : await logger.CommandScalarExecutingAsync( @@ -443,7 +429,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken).ConfigureAwait(false); } @@ -457,8 +443,6 @@ await logger.CommandErrorAsync( } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -471,7 +455,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -487,7 +471,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -530,14 +514,12 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje var readerOpen = false; DbDataReader reader; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger!.CommandReaderExecuting( connection, command, @@ -559,7 +541,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, reader, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -569,8 +551,6 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (Dependencies.ExceptionDetector.IsCancellation(exception)) { logger?.CommandCanceled( @@ -581,7 +561,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -595,7 +575,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -662,14 +642,12 @@ public virtual async Task ExecuteReaderAsync( var readerOpen = false; DbDataReader reader; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (shouldLogCommandExecute) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = await logger!.CommandReaderExecutingAsync( connection, command, @@ -693,7 +671,7 @@ public virtual async Task ExecuteReaderAsync( connection.ConnectionId, reader, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -705,8 +683,6 @@ public virtual async Task ExecuteReaderAsync( } catch (Exception exception) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - if (logger != null) { if (Dependencies.ExceptionDetector.IsCancellation(exception, cancellationToken)) @@ -719,7 +695,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -735,7 +711,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - elapsedTime, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -799,13 +775,11 @@ public virtual DbCommand CreateDbCommand( DbCommand command; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); var logCommandCreate = logger?.ShouldLogCommandCreate(startTime) == true; if (logCommandCreate) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger!.CommandCreating( connection, commandMethod, context, commandId, connectionId, startTime, parameterObject.CommandSource); @@ -822,7 +796,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -857,7 +831,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, parameterObject.CommandSource); } diff --git a/src/EFCore.Relational/Storage/RelationalConnection.cs b/src/EFCore.Relational/Storage/RelationalConnection.cs index 62095665cbf..ac16b432764 100644 --- a/src/EFCore.Relational/Storage/RelationalConnection.cs +++ b/src/EFCore.Relational/Storage/RelationalConnection.cs @@ -152,7 +152,7 @@ public virtual DbConnection DbConnection if (logger.ShouldLogConnectionCreate(startTime)) { - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = logger.ConnectionCreating(this, startTime); @@ -160,7 +160,7 @@ public virtual DbConnection DbConnection ? interceptionResult.Result : CreateDbConnection(); - _connection = logger.ConnectionCreated(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); + _connection = logger.ConnectionCreated(this, startTime, stopwatch.Elapsed); } else { @@ -339,7 +339,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe var transactionId = Guid.NewGuid(); var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = Dependencies.TransactionLogger.TransactionStarting( this, @@ -356,7 +356,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe dbTransaction, transactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); return CreateRelationalTransaction(dbTransaction, transactionId, true); } @@ -390,7 +390,7 @@ public virtual async Task BeginTransactionAsync( var transactionId = Guid.NewGuid(); var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = await Dependencies.TransactionLogger.TransactionStartingAsync( this, @@ -409,7 +409,7 @@ public virtual async Task BeginTransactionAsync( dbTransaction, transactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); @@ -710,14 +710,12 @@ private void OpenInternal(bool errorsExpected) var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (logger.ShouldLogConnectionOpen(startTime)) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger.ConnectionOpening(this, startTime); if (!interceptionResult.IsSuppressed) @@ -725,7 +723,7 @@ private void OpenInternal(bool errorsExpected) OpenDbConnection(errorsExpected); } - logger.ConnectionOpened(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); + logger.ConnectionOpened(this, startTime, stopwatch.Elapsed); } else { @@ -734,9 +732,7 @@ private void OpenInternal(bool errorsExpected) } catch (Exception e) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - - logger.ConnectionError(this, e, startTime, elapsedTime, errorsExpected); + logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, errorsExpected); throw; } @@ -759,14 +755,12 @@ private async Task OpenInternalAsync(bool errorsExpected, CancellationToken canc { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (logger.ShouldLogConnectionOpen(startTime)) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = await logger.ConnectionOpeningAsync(this, startTime, cancellationToken).ConfigureAwait(false); @@ -775,7 +769,7 @@ var interceptionResult await OpenDbConnectionAsync(errorsExpected, cancellationToken).ConfigureAwait(false); } - await logger.ConnectionOpenedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp), cancellationToken) + await logger.ConnectionOpenedAsync(this, startTime, stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); } else @@ -789,7 +783,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero, + stopwatch.Elapsed, errorsExpected, cancellationToken) .ConfigureAwait(false); @@ -883,14 +877,12 @@ public virtual bool Close() { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); try { if (logger.ShouldLogConnectionClose(startTime)) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = logger.ConnectionClosing(this, startTime); if (!interceptionResult.IsSuppressed) @@ -898,7 +890,7 @@ public virtual bool Close() CloseDbConnection(); } - logger.ConnectionClosed(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); + logger.ConnectionClosed(this, startTime, stopwatch.Elapsed); } else { @@ -909,9 +901,7 @@ public virtual bool Close() } catch (Exception e) { - var elapsedTime = startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero; - - logger.ConnectionError(this, e, startTime, elapsedTime, false); + logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, false); throw; } @@ -950,7 +940,7 @@ public virtual async Task CloseAsync() ClearTransactions(clearAmbient: false); - long startTimestamp = 0; + var stopwatch = SharedStopwatch.StartNew(); if (DbConnection.State != ConnectionState.Closed) { @@ -961,8 +951,6 @@ public virtual async Task CloseAsync() { if (logger.ShouldLogConnectionClose(startTime)) { - startTimestamp = Stopwatch.GetTimestamp(); - var interceptionResult = await logger.ConnectionClosingAsync(this, startTime) .ConfigureAwait(false); @@ -971,8 +959,7 @@ public virtual async Task CloseAsync() await CloseDbConnectionAsync().ConfigureAwait(false); } - await logger.ConnectionClosedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)) - .ConfigureAwait(false); + await logger.ConnectionClosedAsync(this, startTime, stopwatch.Elapsed).ConfigureAwait(false); } else { @@ -987,7 +974,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero, + stopwatch.Elapsed, false) .ConfigureAwait(false); @@ -1110,7 +1097,7 @@ protected virtual void DisposeDbConnection() if (logger.ShouldLogConnectionDispose(startTime)) { - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = logger.ConnectionDisposing(this, startTime); @@ -1119,7 +1106,7 @@ protected virtual void DisposeDbConnection() DbConnection.Dispose(); } - logger.ConnectionDisposed(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)); + logger.ConnectionDisposed(this, startTime, stopwatch.Elapsed); } else { @@ -1138,7 +1125,7 @@ protected virtual async ValueTask DisposeDbConnectionAsync() if (logger.ShouldLogConnectionDispose(startTime)) { - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = await logger.ConnectionDisposingAsync(this, startTime).ConfigureAwait(false); @@ -1147,7 +1134,7 @@ protected virtual async ValueTask DisposeDbConnectionAsync() await DbConnection.DisposeAsync().ConfigureAwait(false); } - await logger.ConnectionDisposedAsync(this, startTime, Stopwatch.GetElapsedTime(startTimestamp)).ConfigureAwait(false); + await logger.ConnectionDisposedAsync(this, startTime, stopwatch.Elapsed).ConfigureAwait(false); } else { diff --git a/src/EFCore.Relational/Storage/RelationalDataReader.cs b/src/EFCore.Relational/Storage/RelationalDataReader.cs index 065c38c5e68..619790f85cf 100644 --- a/src/EFCore.Relational/Storage/RelationalDataReader.cs +++ b/src/EFCore.Relational/Storage/RelationalDataReader.cs @@ -24,7 +24,7 @@ public class RelationalDataReader : IDisposable, IAsyncDisposable private Guid _commandId; private IRelationalCommandDiagnosticsLogger? _logger; private DateTimeOffset _startTime; - private long startTimestamp; + private SharedStopwatch _stopwatch; private int _readCount; @@ -55,7 +55,7 @@ public virtual void Initialize( _closed = false; _disposed = false; _startTime = DateTimeOffset.UtcNow; - startTimestamp = Stopwatch.GetTimestamp(); + _stopwatch = SharedStopwatch.StartNew(); } /// @@ -166,7 +166,7 @@ public virtual void Dispose() _reader.RecordsAffected, _readCount, _startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + _stopwatch.Elapsed); // can throw } } finally @@ -262,7 +262,7 @@ public virtual async ValueTask DisposeAsync() _reader.RecordsAffected, _readCount, _startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + _stopwatch.Elapsed); // can throw } } finally diff --git a/src/EFCore.Relational/Storage/RelationalTransaction.cs b/src/EFCore.Relational/Storage/RelationalTransaction.cs index b75e8bf3253..780d3028559 100644 --- a/src/EFCore.Relational/Storage/RelationalTransaction.cs +++ b/src/EFCore.Relational/Storage/RelationalTransaction.cs @@ -74,7 +74,7 @@ public RelationalTransaction( public virtual void Commit() { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -94,7 +94,7 @@ public virtual void Commit() _dbTransaction, TransactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); } catch (Exception e) { @@ -105,7 +105,7 @@ public virtual void Commit() "Commit", e, startTime, - startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero); + stopwatch.Elapsed); throw; } @@ -117,7 +117,7 @@ public virtual void Commit() public virtual void Rollback() { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -137,7 +137,7 @@ public virtual void Rollback() _dbTransaction, TransactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); } catch (Exception e) { @@ -148,7 +148,7 @@ public virtual void Rollback() "Rollback", e, startTime, - startTimestamp > 0 ? Stopwatch.GetElapsedTime(startTimestamp) : TimeSpan.Zero); + stopwatch.Elapsed); throw; } @@ -160,7 +160,7 @@ public virtual void Rollback() public virtual async Task CommitAsync(CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -182,7 +182,7 @@ await Logger.TransactionCommittedAsync( _dbTransaction, TransactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); } @@ -195,7 +195,7 @@ await Logger.TransactionErrorAsync( "Commit", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); @@ -209,7 +209,7 @@ await Logger.TransactionErrorAsync( public virtual async Task RollbackAsync(CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -231,7 +231,7 @@ await Logger.TransactionRolledBackAsync( _dbTransaction, TransactionId, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); } @@ -244,7 +244,7 @@ await Logger.TransactionErrorAsync( "Rollback", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); @@ -258,7 +258,7 @@ await Logger.TransactionErrorAsync( public virtual void CreateSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -291,7 +291,7 @@ public virtual void CreateSavepoint(string name) "CreateSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); throw; } @@ -301,7 +301,7 @@ public virtual void CreateSavepoint(string name) public virtual async Task CreateSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -337,7 +337,7 @@ await Logger.TransactionErrorAsync( "CreateSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken).ConfigureAwait(false); throw; @@ -348,7 +348,7 @@ await Logger.TransactionErrorAsync( public virtual void RollbackToSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -381,7 +381,7 @@ public virtual void RollbackToSavepoint(string name) "RollbackToSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); throw; } @@ -391,7 +391,7 @@ public virtual void RollbackToSavepoint(string name) public virtual async Task RollbackToSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -427,7 +427,7 @@ await Logger.TransactionErrorAsync( "RollbackToSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken).ConfigureAwait(false); throw; @@ -438,7 +438,7 @@ await Logger.TransactionErrorAsync( public virtual void ReleaseSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -471,7 +471,7 @@ public virtual void ReleaseSavepoint(string name) "ReleaseSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp)); + stopwatch.Elapsed); throw; } @@ -481,7 +481,7 @@ public virtual void ReleaseSavepoint(string name) public virtual async Task ReleaseSavepointAsync(string name, CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var startTimestamp = Stopwatch.GetTimestamp(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -517,7 +517,7 @@ await Logger.TransactionErrorAsync( "ReleaseSavepoint", e, startTime, - Stopwatch.GetElapsedTime(startTimestamp), + stopwatch.Elapsed, cancellationToken).ConfigureAwait(false); throw; diff --git a/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs b/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs index 2c3fc515651..bbeb7ff3724 100644 --- a/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs +++ b/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs @@ -12,6 +12,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Data.Sqlite.Properties; +using Microsoft.Data.Sqlite.Utilities; using SQLitePCL; using static SQLitePCL.raw; @@ -471,31 +472,27 @@ public override void Cancel() var sql = new byte[byteCount + 1]; Encoding.UTF8.GetBytes(_commandText, 0, _commandText.Length, sql, 0); - var elapsedTime = TimeSpan.Zero; + var totalElapsedTime = TimeSpan.Zero; int rc; sqlite3_stmt stmt; var start = 0; do { - var startTimestamp = Stopwatch.GetTimestamp(); + var timer = SharedStopwatch.StartNew(); ReadOnlySpan tail; while (IsBusy(rc = sqlite3_prepare_v2(_connection!.Handle, sql.AsSpan(start), out stmt, out tail))) { if (CommandTimeout != 0 - && elapsedTime.TotalMilliseconds >= CommandTimeout * 1000L) + && (totalElapsedTime + timer.Elapsed).TotalMilliseconds >= CommandTimeout * 1000L) { break; } Thread.Sleep(150); - - if (CommandTimeout != 0) - { - elapsedTime += StopwatchUtils.GetElapsedTime(startTimestamp); - } } + totalElapsedTime += timer.Elapsed; start = sql.Length - tail.Length; SqliteException.ThrowExceptionForRC(rc, _connection.Handle); diff --git a/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs b/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs index 1737586c990..30c0a5115c2 100644 --- a/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs +++ b/src/Microsoft.Data.Sqlite.Core/SqliteDataReader.cs @@ -12,6 +12,7 @@ using System.Text; using System.Threading; using Microsoft.Data.Sqlite.Properties; +using Microsoft.Data.Sqlite.Utilities; using SQLitePCL; using static SQLitePCL.raw; @@ -25,7 +26,7 @@ public class SqliteDataReader : DbDataReader { private readonly SqliteCommand _command; private readonly bool _closeConnection; - private TimeSpan _elapsedTime; + private TimeSpan _totalElapsedTime; private IEnumerator? _stmtEnumerator; private SqliteDataRecord? _record; private bool _closed; @@ -153,12 +154,12 @@ public override bool NextResult() { stmt = _stmtEnumerator.Current; - var startTimestamp = Stopwatch.GetTimestamp(); + var timer = SharedStopwatch.StartNew(); while (IsBusy(rc = sqlite3_step(stmt))) { if (_command.CommandTimeout != 0 - && _elapsedTime.TotalMilliseconds >= _command.CommandTimeout * 1000L) + && (_totalElapsedTime + timer.Elapsed).TotalMilliseconds >= _command.CommandTimeout * 1000L) { break; } @@ -167,13 +168,9 @@ public override bool NextResult() // TODO: Consider having an async path that uses Task.Delay() Thread.Sleep(150); - - if (_command.CommandTimeout != 0) - { - _elapsedTime += StopwatchUtils.GetElapsedTime(startTimestamp); - } } + _totalElapsedTime += timer.Elapsed; SqliteException.ThrowExceptionForRC(rc, _command.Connection!.Handle); diff --git a/src/Microsoft.Data.Sqlite.Core/Utilities/SharedStopwatch.cs b/src/Microsoft.Data.Sqlite.Core/Utilities/SharedStopwatch.cs new file mode 100644 index 00000000000..26d769e1eed --- /dev/null +++ b/src/Microsoft.Data.Sqlite.Core/Utilities/SharedStopwatch.cs @@ -0,0 +1,41 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; + +namespace Microsoft.Data.Sqlite.Utilities; + +// Copied from https://github.com/dotnet/roslyn/blob/main/src/Compilers/Core/Portable/InternalUtilities/SharedStopwatch.cs +internal readonly struct SharedStopwatch +{ + private static readonly Stopwatch Stopwatch = Stopwatch.StartNew(); + + private readonly TimeSpan _started; + + private SharedStopwatch(TimeSpan started) + { + _started = started; + } + + public TimeSpan Elapsed => Stopwatch.Elapsed - _started; + + public static SharedStopwatch StartNew() + { + // This call to StartNewCore isn't required, but is included to avoid measurement errors + // which can occur during periods of high allocation activity. In some cases, calls to Stopwatch + // operations can block at their return point on the completion of a background GC operation. When + // this occurs, the GC wait time ends up included in the measured time span. In the event the first + // call to StartNewCore blocked on a GC operation, the second call will most likely occur when the + // GC is no longer active. In practice, a substantial improvement to the consistency of analyzer + // timing data was observed. + // + // Note that the call to SharedStopwatch.Elapsed is not affected, because the GC wait will occur + // after the timer has already recorded its stop time. + _ = StartNewCore(); + return StartNewCore(); + } + + private static SharedStopwatch StartNewCore() + => new SharedStopwatch(Stopwatch.Elapsed); +} diff --git a/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs b/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs deleted file mode 100644 index 374a76c3667..00000000000 --- a/src/Microsoft.Data.Sqlite.Core/Utilities/StopwatchUtils.cs +++ /dev/null @@ -1,23 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Diagnostics; - -// ReSharper disable once CheckNamespace -namespace Microsoft.Data.Sqlite; - -internal static class StopwatchUtils -{ - internal static TimeSpan GetElapsedTime(long startTimestamp) -#if NET7_0_OR_GREATER - => Stopwatch.GetElapsedTime(startTimestamp); -#else - => new((long)((Stopwatch.GetTimestamp() - startTimestamp) * StopWatchTickFrequency)); - - private const long TicksPerMicrosecond = 10; - private const long TicksPerMillisecond = TicksPerMicrosecond * 1000; - private const long TicksPerSecond = TicksPerMillisecond * 1000; // 10,000,000 - private static readonly double StopWatchTickFrequency = (double)TicksPerSecond / Stopwatch.Frequency; -#endif -} diff --git a/src/Shared/SharedStopwatch.cs b/src/Shared/SharedStopwatch.cs new file mode 100644 index 00000000000..a1d2395d42d --- /dev/null +++ b/src/Shared/SharedStopwatch.cs @@ -0,0 +1,38 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.EntityFrameworkCore.Utilities; + +// Copied from https://github.com/dotnet/roslyn/blob/main/src/Compilers/Core/Portable/InternalUtilities/SharedStopwatch.cs +internal readonly struct SharedStopwatch +{ + private static readonly Stopwatch Stopwatch = Stopwatch.StartNew(); + + private readonly TimeSpan _started; + + private SharedStopwatch(TimeSpan started) + { + _started = started; + } + + public TimeSpan Elapsed => Stopwatch.Elapsed - _started; + + public static SharedStopwatch StartNew() + { + // This call to StartNewCore isn't required, but is included to avoid measurement errors + // which can occur during periods of high allocation activity. In some cases, calls to Stopwatch + // operations can block at their return point on the completion of a background GC operation. When + // this occurs, the GC wait time ends up included in the measured time span. In the event the first + // call to StartNewCore blocked on a GC operation, the second call will most likely occur when the + // GC is no longer active. In practice, a substantial improvement to the consistency of analyzer + // timing data was observed. + // + // Note that the call to SharedStopwatch.Elapsed is not affected, because the GC wait will occur + // after the timer has already recorded its stop time. + _ = StartNewCore(); + return StartNewCore(); + } + + private static SharedStopwatch StartNewCore() + => new SharedStopwatch(Stopwatch.Elapsed); +}