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 +}