diff --git a/src/EFCore.Relational/Storage/RelationalCommand.cs b/src/EFCore.Relational/Storage/RelationalCommand.cs index 3b6322a76ca..e1556dca990 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,12 +80,12 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.Open(); + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = logger?.CommandNonQueryExecuting( connection, command, @@ -109,7 +108,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, nonQueryResult, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource) ?? nonQueryResult; } @@ -130,7 +129,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -144,7 +143,7 @@ public virtual int ExecuteNonQuery(RelationalCommandParameterObject parameterObj connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -183,12 +182,12 @@ public virtual async Task ExecuteNonQueryAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = logger == null ? default : await logger.CommandNonQueryExecutingAsync( @@ -216,7 +215,7 @@ public virtual async Task ExecuteNonQueryAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -243,7 +242,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -259,7 +258,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -295,12 +294,12 @@ await logger.CommandErrorAsync( connection.Open(); + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = logger?.CommandScalarExecuting( connection, command, @@ -323,7 +322,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource) ?? result; } @@ -344,7 +343,7 @@ await logger.CommandErrorAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -358,7 +357,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -397,12 +396,12 @@ await logger.CommandErrorAsync( await connection.OpenAsync(cancellationToken).ConfigureAwait(false); + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = logger == null ? default : await logger.CommandScalarExecutingAsync( @@ -430,7 +429,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, result, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken).ConfigureAwait(false); } @@ -456,7 +455,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -472,7 +471,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -515,12 +514,12 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje var readerOpen = false; DbDataReader reader; + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = logger!.CommandReaderExecuting( connection, command, @@ -542,7 +541,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, reader, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -562,7 +561,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -576,7 +575,7 @@ public virtual RelationalDataReader ExecuteReader(RelationalCommandParameterObje connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } @@ -643,12 +642,12 @@ public virtual async Task ExecuteReaderAsync( var readerOpen = false; DbDataReader reader; + var stopwatch = SharedStopwatch.StartNew(); + try { if (shouldLogCommandExecute) { - _stopwatch.Restart(); - var interceptionResult = await logger!.CommandReaderExecutingAsync( connection, command, @@ -672,7 +671,7 @@ public virtual async Task ExecuteReaderAsync( connection.ConnectionId, reader, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -696,7 +695,7 @@ await logger.CommandCanceledAsync( commandId, connection.ConnectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -712,7 +711,7 @@ await logger.CommandErrorAsync( connection.ConnectionId, exception, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource, cancellationToken) .ConfigureAwait(false); @@ -776,11 +775,11 @@ public virtual DbCommand CreateDbCommand( DbCommand command; + var stopwatch = SharedStopwatch.StartNew(); + var logCommandCreate = logger?.ShouldLogCommandCreate(startTime) == true; if (logCommandCreate) { - _stopwatch.Restart(); - var interceptionResult = logger!.CommandCreating( connection, commandMethod, context, commandId, connectionId, startTime, parameterObject.CommandSource); @@ -797,7 +796,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } else @@ -832,7 +831,7 @@ public virtual DbCommand CreateDbCommand( commandId, connectionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, parameterObject.CommandSource); } diff --git a/src/EFCore.Relational/Storage/RelationalConnection.cs b/src/EFCore.Relational/Storage/RelationalConnection.cs index b0aadea1a5a..ac16b432764 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 stopwatch = SharedStopwatch.StartNew(); 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.Elapsed); } else { @@ -340,7 +339,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe var transactionId = Guid.NewGuid(); var startTime = DateTimeOffset.UtcNow; - _stopwatch.Restart(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = Dependencies.TransactionLogger.TransactionStarting( this, @@ -357,7 +356,7 @@ public virtual IDbContextTransaction BeginTransaction(IsolationLevel isolationLe dbTransaction, transactionId, startTime, - _stopwatch.Elapsed); + stopwatch.Elapsed); 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 stopwatch = SharedStopwatch.StartNew(); var interceptionResult = await Dependencies.TransactionLogger.TransactionStartingAsync( this, @@ -410,7 +409,7 @@ public virtual async Task BeginTransactionAsync( dbTransaction, transactionId, startTime, - _stopwatch.Elapsed, + stopwatch.Elapsed, cancellationToken) .ConfigureAwait(false); @@ -711,12 +710,12 @@ private void OpenInternal(bool errorsExpected) var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + var stopwatch = SharedStopwatch.StartNew(); + try { if (logger.ShouldLogConnectionOpen(startTime)) { - _stopwatch.Restart(); - var interceptionResult = logger.ConnectionOpening(this, startTime); if (!interceptionResult.IsSuppressed) @@ -724,7 +723,7 @@ private void OpenInternal(bool errorsExpected) OpenDbConnection(errorsExpected); } - logger.ConnectionOpened(this, startTime, _stopwatch.Elapsed); + logger.ConnectionOpened(this, startTime, stopwatch.Elapsed); } else { @@ -733,7 +732,7 @@ private void OpenInternal(bool errorsExpected) } catch (Exception e) { - logger.ConnectionError(this, e, startTime, _stopwatch.Elapsed, errorsExpected); + logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, errorsExpected); throw; } @@ -756,13 +755,12 @@ private async Task OpenInternalAsync(bool errorsExpected, CancellationToken canc { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + var stopwatch = SharedStopwatch.StartNew(); try { if (logger.ShouldLogConnectionOpen(startTime)) { - _stopwatch.Restart(); - var interceptionResult = await logger.ConnectionOpeningAsync(this, startTime, cancellationToken).ConfigureAwait(false); @@ -771,7 +769,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.Elapsed, cancellationToken) + .ConfigureAwait(false); } else { @@ -784,7 +783,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - DateTimeOffset.UtcNow - startTime, + stopwatch.Elapsed, errorsExpected, cancellationToken) .ConfigureAwait(false); @@ -878,13 +877,12 @@ public virtual bool Close() { var logger = Dependencies.ConnectionLogger; var startTime = DateTimeOffset.UtcNow; + var stopwatch = SharedStopwatch.StartNew(); try { if (logger.ShouldLogConnectionClose(startTime)) { - _stopwatch.Restart(); - var interceptionResult = logger.ConnectionClosing(this, startTime); if (!interceptionResult.IsSuppressed) @@ -892,7 +890,7 @@ public virtual bool Close() CloseDbConnection(); } - logger.ConnectionClosed(this, startTime, _stopwatch.Elapsed); + logger.ConnectionClosed(this, startTime, stopwatch.Elapsed); } else { @@ -903,7 +901,7 @@ public virtual bool Close() } catch (Exception e) { - logger.ConnectionError(this, e, startTime, _stopwatch.Elapsed, false); + logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, false); throw; } @@ -942,6 +940,8 @@ public virtual async Task CloseAsync() ClearTransactions(clearAmbient: false); + var stopwatch = SharedStopwatch.StartNew(); + if (DbConnection.State != ConnectionState.Closed) { var logger = Dependencies.ConnectionLogger; @@ -951,8 +951,6 @@ public virtual async Task CloseAsync() { if (logger.ShouldLogConnectionClose(startTime)) { - _stopwatch.Restart(); - var interceptionResult = await logger.ConnectionClosingAsync(this, startTime) .ConfigureAwait(false); @@ -961,8 +959,7 @@ public virtual async Task CloseAsync() await CloseDbConnectionAsync().ConfigureAwait(false); } - await logger.ConnectionClosedAsync(this, startTime, _stopwatch.Elapsed) - .ConfigureAwait(false); + await logger.ConnectionClosedAsync(this, startTime, stopwatch.Elapsed).ConfigureAwait(false); } else { @@ -977,7 +974,7 @@ await logger.ConnectionErrorAsync( this, e, startTime, - DateTimeOffset.UtcNow - startTime, + stopwatch.Elapsed, false) .ConfigureAwait(false); @@ -1100,7 +1097,7 @@ protected virtual void DisposeDbConnection() if (logger.ShouldLogConnectionDispose(startTime)) { - _stopwatch.Restart(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = logger.ConnectionDisposing(this, startTime); @@ -1109,7 +1106,7 @@ protected virtual void DisposeDbConnection() DbConnection.Dispose(); } - logger.ConnectionDisposed(this, startTime, _stopwatch.Elapsed); + logger.ConnectionDisposed(this, startTime, stopwatch.Elapsed); } else { @@ -1128,7 +1125,7 @@ protected virtual async ValueTask DisposeDbConnectionAsync() if (logger.ShouldLogConnectionDispose(startTime)) { - _stopwatch.Restart(); + var stopwatch = SharedStopwatch.StartNew(); var interceptionResult = await logger.ConnectionDisposingAsync(this, startTime).ConfigureAwait(false); @@ -1137,7 +1134,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.Elapsed).ConfigureAwait(false); } else { diff --git a/src/EFCore.Relational/Storage/RelationalDataReader.cs b/src/EFCore.Relational/Storage/RelationalDataReader.cs index 3e1e25da6d5..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 readonly Stopwatch _stopwatch = new(); + private SharedStopwatch _stopwatch; private int _readCount; @@ -55,7 +55,7 @@ public virtual void Initialize( _closed = false; _disposed = false; _startTime = DateTimeOffset.UtcNow; - _stopwatch.Restart(); + _stopwatch = SharedStopwatch.StartNew(); } /// diff --git a/src/EFCore.Relational/Storage/RelationalTransaction.cs b/src/EFCore.Relational/Storage/RelationalTransaction.cs index d30a8aba31e..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 stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -117,7 +117,7 @@ public virtual void Commit() public virtual void Rollback() { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -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 stopwatch = SharedStopwatch.StartNew(); try { @@ -209,7 +209,7 @@ await Logger.TransactionErrorAsync( public virtual async Task RollbackAsync(CancellationToken cancellationToken = default) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -258,7 +258,7 @@ await Logger.TransactionErrorAsync( public virtual void CreateSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -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 stopwatch = SharedStopwatch.StartNew(); try { @@ -348,7 +348,7 @@ await Logger.TransactionErrorAsync( public virtual void RollbackToSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -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 stopwatch = SharedStopwatch.StartNew(); try { @@ -438,7 +438,7 @@ await Logger.TransactionErrorAsync( public virtual void ReleaseSavepoint(string name) { var startTime = DateTimeOffset.UtcNow; - var stopwatch = Stopwatch.StartNew(); + var stopwatch = SharedStopwatch.StartNew(); try { @@ -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 stopwatch = SharedStopwatch.StartNew(); try { diff --git a/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs b/src/Microsoft.Data.Sqlite.Core/SqliteCommand.cs index 7ea911ecb93..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; @@ -256,9 +257,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 +306,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 +464,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,18 +472,19 @@ public override void Cancel() var sql = new byte[byteCount + 1]; Encoding.UTF8.GetBytes(_commandText, 0, _commandText.Length, sql, 0); + var totalElapsedTime = TimeSpan.Zero; int rc; sqlite3_stmt stmt; var start = 0; do { - timer.Start(); + var timer = SharedStopwatch.StartNew(); ReadOnlySpan tail; while (IsBusy(rc = sqlite3_prepare_v2(_connection!.Handle, sql.AsSpan(start), out stmt, out tail))) { if (CommandTimeout != 0 - && timer.ElapsedMilliseconds >= CommandTimeout * 1000L) + && (totalElapsedTime + timer.Elapsed).TotalMilliseconds >= CommandTimeout * 1000L) { break; } @@ -493,7 +492,7 @@ public override void Cancel() Thread.Sleep(150); } - timer.Stop(); + 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 50031bc36f0..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 readonly Stopwatch _timer; + private TimeSpan _totalElapsedTime; private IEnumerator? _stmtEnumerator; private SqliteDataRecord? _record; private bool _closed; @@ -33,12 +34,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 +154,12 @@ public override bool NextResult() { stmt = _stmtEnumerator.Current; - _timer.Start(); + var timer = SharedStopwatch.StartNew(); while (IsBusy(rc = sqlite3_step(stmt))) { if (_command.CommandTimeout != 0 - && _timer.ElapsedMilliseconds >= _command.CommandTimeout * 1000L) + && (_totalElapsedTime + timer.Elapsed).TotalMilliseconds >= _command.CommandTimeout * 1000L) { break; } @@ -171,7 +170,7 @@ public override bool NextResult() Thread.Sleep(150); } - _timer.Stop(); + _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/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); +}