I have recently upgraded a solution from .Net Core 3.1 to .Net 5. It is a simple WebAPI, that uses a MSSQL database.
Before returning a response to a request to the API, a record is saved in a table. A simple log of the request and response. It is a simple table with no foreign keys or anything. It usually takes around 5-10 ms to insert a row into this table, but after upgrading to .Net 5, I noticed that suddenly around 10% of the inserts are very slow, taking from 500-1500 ms to complete. The remaining 90% are still as fast as before.
The data is added to the database the usual way with EF Core, so no magic there:
await _dbContext.LogData.AddAsync(log);
await _dbContext.SaveChangesAsync();
After enabling debug logging in EF Core, it seems that the time is spent beginning the transaction:
Nov 4, 2021 @ 15:10:51.383 SaveChanges completed for '"ApplicationDbContext"' with 1 entities written to the database.
Nov 4, 2021 @ 15:10:51.383 An entity of type '"LogData"' tracked by '"ApplicationDbContext"' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
Nov 4, 2021 @ 15:10:51.383 Disposing transaction.
Nov 4, 2021 @ 15:10:51.383 Closed connection to database '"<DB Name>"' on server '"<Server Name>"'.
Nov 4, 2021 @ 15:10:51.383 Closing connection to database '"<DB Name>"' on server '"<Server Name>"'.
Nov 4, 2021 @ 15:10:51.383 Committed transaction.
Nov 4, 2021 @ 15:10:51.376 Committing transaction.
Nov 4, 2021 @ 15:10:51.376 A data reader was disposed.
Nov 4, 2021 @ 15:10:51.376 The foreign key property '"LogData"."Id"' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
Nov 4, 2021 @ 15:10:51.376 Executed DbCommand ("2"ms) <SQL COMMAND>
Nov 4, 2021 @ 15:10:51.374 Executing DbCommand <SQL COMMAND>
Nov 4, 2021 @ 15:10:51.374 Created DbCommand for '"ExecuteReader"' (0ms).
Nov 4, 2021 @ 15:10:51.374 Creating DbCommand for '"ExecuteReader"'.
Nov 4, 2021 @ 15:10:51.373 Began transaction with isolation level '"ReadCommitted"'.
Nov 4, 2021 @ 15:10:50.654 Beginning transaction with isolation level '"Unspecified"'.
Nov 4, 2021 @ 15:10:50.654 Opened connection to database '"<DB Name>"' on server '"<Server Name>"'.
Nov 4, 2021 @ 15:10:50.654 Opening connection to database '"<DB Name>"' on server '"<Server Name>"'.
Nov 4, 2021 @ 15:10:50.654 DetectChanges completed for '"ApplicationDbContext"'.
Nov 4, 2021 @ 15:10:50.654 DetectChanges starting for '"ApplicationDbContext"'.
Nov 4, 2021 @ 15:10:50.654 SaveChanges starting for '"ApplicationDbContext"'.
Nov 4, 2021 @ 15:10:50.654 Context '"ApplicationDbContext"' started tracking '"LogData"' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
Nov 4, 2021 @ 15:10:50.654 '"ApplicationDbContext"' generated a temporary value for the property '"Id"."LogData"'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
Nov 4, 2021 @ 15:10:50.654 Entity Framework Core "5.0.10" initialized '"ApplicationDbContext"' using provider '"Microsoft.EntityFrameworkCore.SqlServer"' with options: "None"
Any idea why it would suddenly take almost a second to begin a transaction?
The .Net and EF Core version is 5.0.10, and the API is running in OpenShift in a aspnet:5.0.10-buster-slim-amd64 image using a MSSQL Server 2017 cluster. As I said, the issue didn't exist in .Net Core 3.1, but we did have a similar issue in 2.2, which we didn't find the cause for as it disappeared when we moved to 3.1
EDIT: Added more of the logging. As you can see, the entire operation takes 729 ms, and the 719 ms is spent beginning the transaction.