Transaction can cause timeout, lost server connection, and connection pool saturation on SQL Server

[Arkatufus]

Version Information
Version of Akka.Persistence.Sql? dev branch

• This is a consolidated issue tracking Write journal throws a TimeoutException during persistence HandleDeleteMessagesTo execution #528 and Exception when deleting messages: SqlTransaction has completed; it is no longer usable #527
• A reproduction added in [DO NOT MERGE] Add transaction test app #529
• [DO NOT MERGE] CancellationToken API changes (v1.5.42) integration test #535 might help

Describe the bug
Transaction can cause timeout, zombie connection, and/or connection pool exhaustion on SQL Server during persistence HandleDeleteMessagesTo execution with high persistence activity. This seems to be caused by table/row lock and the complexity of the operation.

[Arkatufus]

We will need to analyze the operation complexity and find a more efficient way of doing bulk deletes

[Arkatufus]

Using Rider Dynamic Program Analysis (DPA), these issues were found:

[Arkatufus]

Looking at the "Average time" metrics, it is clear that the database queries themselves are quite simple and performant, ranging from 31ms to 400ms to execute.

But, looking at the "Max time among all execution", we're seeing some discrepancy. Some of these operations suddenly needs 5-6 seconds to execute, this suggests a table/row deadlock that stops the query execution entirely.

[Arkatufus]

So the error occurred here:

Akka.Persistence.Sql/src/Akka.Persistence.Sql/Extensions/ConnectionFactoryExtensions.cs

Lines 35 to 46 in 50c585d

	catch (Exception ex1)
	{
	try
	{
	await tx.RollbackAsync(token);
	}
	catch (Exception ex2)
	{
	throw new AggregateException("Exception thrown when rolling back database transaction", ex2, ex1);
	}
	throw;

We're missing the second inner exception, but the first one indicates to me that the transaction got disposed when it shouldn't have somehow.

[Arkatufus]

--> (Inner Exception #1) System.InvalidOperationException: This SqlTransaction has completed; it is no longer usable.
   at Microsoft.Data.SqlClient.SqlTransaction.ZombieCheck()
   at Microsoft.Data.SqlClient.SqlTransaction.Commit()
   at LinqToDB.Async.AsyncDbTransaction.CommitAsync(CancellationToken cancellationToken)
   at LinqToDB.Data.DataConnection.<>c.<<CommitTransactionAsync>b__3_1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at LinqToDB.Data.DataConnection.<TraceActionAsync>d__8`2.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at LinqToDB.Data.DataConnection.<CommitTransactionAsync>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at LinqToDB.Data.DataConnectionTransaction.<CommitAsync>d__7.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

looks like the transaction got hosed even before we tried to commit

[Arkatufus]

This is the zombie check that @Arkatufus noted in his logs:

https://github.com/dotnet/SqlClient/blob/b2ee4356eabff748b2e075cda70431d750725fdb/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlTransaction.cs#L455-L468

[Arkatufus]

Linq2Db transaction comitting code:

https://github.com/linq2db/linq2db/blob/bc50707294c09851487dd27406e27fb137a06521/Source/LinqToDB/DataContextTransaction.cs#L142-L164

Linq2Db transaction opening code:

https://github.com/linq2db/linq2db/blob/bc50707294c09851487dd27406e27fb137a06521/Source/LinqToDB/Data/DataConnection.Async.cs#L33-L72

This is where a second transaction can open on the same connection, aborting the original one in-progress

[Arkatufus]

Probable cause

Previous theory that this is caused by backpressure problem, we might be applying query limiter/throttler to the wrong database query that it throttles recovery. This is proven to be impossible, both ReplayMessagesAsync() and DeleteMessagesAsync() doesn't use ExecuteQueryWithTransactionAsync(), which rules out query throttling misuse possibility.

Static code analysis:

[Arkatufus]

Current Delete() operation flow:

VAR $persistenceId
VAR $maxSeqNo

Start Transaction

  SET j.Deleted = true
    FROM journal j
    WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber < $maxSeqNo

  VAR $maxDeleted = 
    TAKE 1 SELECT j.SequenceNumber
      FROM journal j
      WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber < $maxSeqNo
      ORDER BY DESC j.SequenceNumber

  DELETE FROM journal.j
    WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber < maxDeleted

  DELETE FROM tags t
    WHERE t.PersistenceId = $persistenceId AND t.SequenceNumber <= $maxSeqNo

End Transaction

[Arkatufus]

Fix attempt, optimize code:

VAR $persistenceId
VAR $maxSeqNo

VAR $maxDeleted = 
  TAKE 1 SELECT j.SequenceNumber
    FROM journal j
    WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber < $maxSeqNo
    ORDER BY DESC j.SequenceNumber

Start Transaction

  SET j.Deleted = true
    FROM journal j
    WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber = $maxDeleted

  DELETE FROM journal.j
    WHERE j.PersistenceId = $persistenceId AND j.SequenceNumber < $maxDeleted

  DELETE FROM tags t
    WHERE t.PersistenceId = $persistenceId AND t.SequenceNumber < $maxDeleted

End Transaction

• Can cause a connection pool exhaustion if it is set to use 2 connection object
• Using a single connection still causes timeout

[Arkatufus]

Note

It would be great to be able to profile the server itself and actually see the occurence of these table deadlocks. Does anyone know of any tools that can help with this?

[Arkatufus]

Note

Currently, Microsoft.Data.SqlClient does not support have any asynchronous transaction support,
it is using the default behavior of System.Data.Common which discards the CancellationToken
passed into the BeginDbTransactionAsync method call.

• Default behavior: https://github.com/dotnet/runtime/blob/ffcdaebe0ebfc20a3632538a983eb149bd7a4edc/src/libraries/System.Data.Common/src/System/Data/Common/DbConnection.cs#L67-L82
• Issue: Add missing async methods in System.Data.Common and implement IAsyncDisposable dotnet/runtime#28596
• Issue: Implement async transaction begin/commit/rollback methods dotnet/SqlClient#113