dotnet
ActivityIds missing from database profiler
Description
Raising this issue as recommended here https://developercommunity.visualstudio.com/t/Database-Profiler-is-completely-broken-1/10771227#T-ND10813008
".NET itself - both the VS profiling tools (the database tool in this case) and dotnet-trace end up being unable to collect ActivityIds for the Stop events despite them being marked as Activity events in both scenarios, making us unable to correlate the query start and stop events together when opening these files in Visual Studio."
Configuration
- Visual Studio 17.12.3 & .Net 9.0
- Windows 24H2
- x64
Regression?
Unknown
Other information
Relevant information provided in the linked bug report: https://developercommunity.visualstudio.com/t/Database-Profiler-is-completely-broken-1/10771227#T-ND10813008
Hi @timmac-qmc, to clarify, are you emitting these Activity2Start/Stop events from your program? Do you happen to have a simple repro that demonstrates the ActivtyId missing from the Activity2Stop event when collecting a trace with dotnet-trace?
I'm not very familiar with the Activity events, do you know if the ActivityId is present in the Activity2Stop events when using .NET 8.0 or any prior version of .NET?
Hi @timmac-qmc, to clarify, are you emitting these Activity2Start/Stop events from your program? Do you happen to have a simple repro that demonstrates the ActivtyId missing from the Activity2Stop event when collecting a trace with dotnet-trace?
I'm not very familiar with the Activity events, do you know if the ActivityId is present in the Activity2Stop events when using .NET 8.0 or any prior version of .NET?
Sorry, I don't have a public project to share. If you refer to the linked issue there is a trace log provided, I'm sure the other developer in that issue can provide more information.
I created a simple repro of this problem below. I have no way confirm it is the identical root cause, but it shows similar symptoms in the log where the ActivityStart events have ActivityIDs and the ActivityStop events do not.
Repro
- Write the following code into a new console app and add the relevant Microsoft.EntityFrameworkCore and Microsoft.EntityFrameworkCore.Sqlite NuGet packages so that it compiles.
using Microsoft.Data.Sqlite;
using Microsoft.EntityFrameworkCore;
using Microsoft.EntityFrameworkCore.Infrastructure;
using Microsoft.EntityFrameworkCore.Storage;
using System;
using System.Collections.Generic;
using System.Threading.Tasks;
public class SampleContext : DbContext
{
public DbSet<Item> Items { get; set; }
protected override void OnConfiguring(DbContextOptionsBuilder options)
=> options.UseSqlite("Data Source=:memory:");
}
public class Item
{
public int Id { get; set; }
public string Name { get; set; }
}
class Program
{
static async Task Main()
{
Console.WriteLine("Hit enter to start the transaction example...");
Console.ReadLine();
var options = new DbContextOptionsBuilder<SampleContext>()
.UseSqlite("Data Source=:memory:")
.Options;
await using var context = new SampleContext();
await context.Database.OpenConnectionAsync();
await context.Database.EnsureCreatedAsync();
var relationalConnection = (IRelationalConnection)context.Database.GetService<IRelationalConnection>();
await using var transaction = await relationalConnection.BeginTransactionAsync();
try
{
context.Items.Add(new Item { Name = "Test Item" });
await context.SaveChangesAsync();
await transaction.CommitAsync();
Console.WriteLine("Transaction committed.");
}
catch (Exception ex)
{
await transaction.RollbackAsync();
Console.WriteLine($"Transaction rolled back. Error: {ex.Message}");
}
// Verify
foreach (var item in context.Items)
{
Console.WriteLine($"Item: {item.Name}");
}
}
}
- Run the app and see the "Hit enter to start the transaction example..."
- Run dotnet-trace to collect a trace of this app the same as VS would. Substitute the process ID into the command line where indicated.
dotnet-trace collect -p <PROCESS_ID_OF_APP_HERE> --providers Microsoft-Diagnostics-DiagnosticSource:00000003:5:FilterAndPayloadSpecs=\"Microsoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Transaction.TransactionStarting@Activity1Start:-TransactionId;IsAsync\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Transaction.TransactionCommitted@Activity1Stop:\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Transaction.TransactionRolledBack@Activity1Stop:\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Transaction.TransactionDisposed@Activity1Stop:-TransactionId\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandExecuting@Activity2Start:-Command;Command.CommandText;ConnectionId;IsAsync;Command.Connection.ClientConnectionId;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource;Command.Connection.PacketSize\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.DataReaderDisposing@Activity2Stop:-CommandId;RecordsAffected;ReadCount\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandError@Activity2Stop:-Exception\r\nSqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandBefore:-OperationId;Command;Command.CommandText;ConnectionId;Operation;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource\r\nSqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandAfter:-OperationId\r\nSqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandError:-OperationId;Exception\r\nSqlClientDiagnosticListener/Microsoft.Data.SqlClient.WriteCommandBefore:-OperationId;Command;Command.CommandText;ConnectionId;Operation;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource\r\nSqlClientDiagnosticListener/Microsoft.Data.SqlClient.WriteCommandAfter:-OperationId\r\nSqlClientDiagnosticListener/Microsoft.Data.SqlClient.WriteCommandError:-OperationId;Exception\",System.Threading.Tasks.TplEventSource
- Hit enter to let the Sqlite demo app run its transaction
Result
When opening the trace in PerfView we can see in the Events view that the ActivityStart events have ActivityIDs but the ActivityStop events do not.
What causes this?
EventSource Start/Stop activity tracking uses AsyncLocals to store the ActivityID and async locals do not flow out of await points. As a simplified example consider some code that looks like this:
async void Main()
{
await BeginTransaction();
await CommitTransaction();
}
async void BeginTransaction()
{
MyEventSource.TransactionStart();
// do other work to start the transaction
}
async void CommitTransaction()
{
// do other work to stop the transaction
MyEventSource.TransactionStop();
}
The call to MyEventSource.TransactionStart() sets the async local ActivityID, but as soon as BeginTransaction returns back to its async caller Main the async local goes away. This is a basic design choice of AsyncLocal values that they don't flow from awaitee -> awaiter. This means the async local also isn't set during the call to CommitTransaction and so MyEventSource.TransactionStop() doesn't log any ActivityID.
Potential changes that could resolve this:
- VS could use the transaction Id to correlate the start stop events instead of the ActivityId.
- EFCore could change API/logging design so that the start EventSource event isn't invoked inside an async helper (given RelationalConnection.BeginTransactionAsync is a public API that seems hard)
- .NET could flow AsyncLocals from awaitee -> awaiter (this seems extremely unlikely, its a major design change)
Potential workarounds:
- If application code is calling the Async version of the EFCore APIs, change it to call the synchronous APIs instead. Of course the app may have particular reasons it was calling the async variations of the API before so this workaround isn't always going to be viable.
Going ahead and closing this. From the runtime side ActivityIDs depending on AsyncLocals to flow and AsyncLocals not flowing from awaitee->awaiter are both by design behaviors. On the EF side logging an EventSource Start event from inside an async method where the AsyncLocal won't be able to flow out is unforetunate but given its a public API that has already shipped presumably that is either 'by-design' or "Won't Fix" at this point. We could open a new issue in the EF repo if we wanted them to consider it but I'd be surprised if anything changed. I think the best option to resolve the overall scenario would be VS profiler using transaction id instead of Activity ID for correlating the start and stop events coming from EF.