EF6 StatisticsEnabled trickery + EF6 TagWith polyfill

[jzabroski]

Hi Jonathan,

When we use an EF6 DbCommandInterceptor to replicate the EFCore SET STATISTICS IO ON example, the behavior replication fails because Z.EntityFramework.EF6.Plus creates its own DbCommand and we end up only receiving the statistics from that table. Attached is a zip file containing a self-contained, mostly minimal repro that also includes/demonstrates composing tags with WhereBulkContains.

I've attached working code example for both the statistics issue and an EFCore TagWith polyfill. Run the program and it wil ask you for the license name and key; you can also set Z_EF_LICENSE_NAME and Z_EF_LICENSE_KEY environment variables to run it multiple times.

ZEfPlusStatsIoRepro.zip

[JonathanMagnan]

Hello @jzabroski,

Thank you for the project. It really helped us investigate this problem more deeply and better understand how the InfoMessage event works through a connection/command.

To better understand the behavior, let's take the following code:

using (var ctx = new SalesContext())
{
	var connection = (Microsoft.Data.SqlClient.SqlConnection)ctx.Database.Connection;

	connection.Open();

	using var setCommand = connection.CreateCommand();
	setCommand.CommandText = "SET STATISTICS IO ON;";
	setCommand.ExecuteNonQuery();

	connection.InfoMessage += (sender, e) =>
	{
		foreach (Microsoft.Data.SqlClient.SqlError error in e.Errors)
		{
			Console.WriteLine($"SQL Info/Warning: {error.Message}");
		}
	};

	// DOESN'T raise any message
	var rows = ctx.Orders.ToList();

	// Goes inside the InfoMessage
	var cmd = connection.CreateCommand();
	cmd.CommandText = "SELECT * FROM Orders;";
	using var reader = cmd.ExecuteReader();

	// DOESN'T raise any message
	while (reader.Read())
	{
	}

	// RAISES the message
	reader.NextResult();

	Console.WriteLine($"  -> {rows.Count} aggregate rows returned.");
}

The way EF6 executes a query is equivalent to the while (reader.Read()) loop. Neither of them raises any message:

var rows = ctx.Orders.ToList();

// and

while (reader.Read())
{
}

However, as soon as the reader.NextResult(); method is called, it raises the message for the currently executing query.

reader.NextResult();

On our side, the first time you access a table, we retrieve some information from the database. We perform 3 SELECT statements, and we need to call reader.NextResult(); to move to the next result.

It could have been implemented as 3 separate calls, but then we would have to hit the database 3 times instead of once, which is obviously not ideal.

There is also information retrieved by SqlBulkCopy that we don't control. I didn't investigate its implementation, but let's assume it also calls reader.NextResult();.

So all the STATISTICS IO information you currently receive is not coming from the query itself. Since the query is executed by Entity Framework, it never calls reader.NextResult();. Instead, the STATISTICS IO information comes from the queries we execute internally before running your actual query.

Let me know if this correctly explains the current behavior.

Also, let us know if there is something specific you're trying to achieve. I'm not exactly sure what you're looking for, but at least we now have a much better understanding of when this information is returned and when it is not.

Best Regards,

Jon

[jzabroski]

Hi Jonathan,

I acknowledge your comment about Entity Framework never calling reader.NextResult();; EF6 assumes only a single result set per batch, so it never checks for reader.NextResult() and relies on disposal to complete the connection request. The precise problem is that our flush never gets called; the StatisticsIoFlushingReader class has a public override bool NextResult() => _inner.NextResult(); exactly so that we can put a breakpoint there to see it is not called. After thinking about it, we can instrument Dispose so that reader.NextResult() is called. However, with this change, Z.EF's internal commands still bypass the interception pipeline, so the residual ask shrinks from "we can't get STATISTICS IO" to "per-command attribution would be nice" (and "are you interested in including a TagWith polyfill?").

I put together a more comprehensive demo, demonstrating how specifically the way Z.EF.Plus is dispatching commands is causing the bug we are seeing. StatsIoRepro.zip

The original ZEfPlusStatsIoRepo.csproj also gained a true/false flag to demonstrate how I was able to prove that Z.EF.Plus does not completely block me from tracking SET STATISTICS IO ON, it only stops me from per-command attribution.

Three places in the new InterceptionDispatchDemo.csproj demo I want to call to your attention:

1. StatisticsIoFlushingReader has now gained DrainRemainingResults() inside Dispose() - Read the version in InterceptionDispatchDemo for the comments I put there for you.
2. MiniBulkLib private static void Execute(SqlConnection connection, string sql) demonstrates on line 242 how Z.EF.Plus is calling commands, resulting in interceptors+Z.EF not working parsimoniously - interceptors run at the start of the "EF DbContext Batch", but not per DbCommand, so there is no way to tie the statistics IO output to each command.
3. MiniBulkLib UseSqlBulkCopy replicates Z.EF.Plus behavior and demonstrates how to attach InfoMessage to a connection - practically speaking, this can be done through DI by setting the DbContext as not owning the connection and letting DI clean up the InfoMessage details.

Below is a summary of various modes in the InterceptionDispatchDemo demo, and also explained further in SUMMARY.md I had AI generate.

Mode	Who executes	Who materializes	Drain sensitivity	Result
A	library, raw Execute*()	library, raw reader	n/a — no command intercepted, so no handler armed, no wrapper, nothing to flush	command interceptors blind; in this pure mode nothing collects stats (but see Z.EF row — "unobtainable" would be an overstatement)
B	library, via Dispatch	library, via wrapped reader	yes — flush fires at wrapper Close. Drain on: deterministic. Drain off: final query's trailing stats appear only if Close happens to drain rather than cancel	per-command stats captured on the final query (deterministically, only with drain on)
C	EF6 itself	EF6 itself, via wrapped reader	yes — same wrapper. EF fully materializes before disposing, so drain-off usually "happens to work" here — the false confidence that hid the bug	identical to B
D	library, raw + SqlBulkCopy (no DbCommand exists)	library, raw reader	no — session bucket flushed at connection close, after the stream is long since consumed; no wrapper involved	command interceptors blind, but pre-attached session InfoMessage handler + one SET STATISTICS IO ON collects everything — one bucket, no per-command attribution
E	EF6 (LINQ) and library (raw + SqlBulkCopy) on the context's connection	each its own reader (EF's wrapped; library's raw)	mixed — the EF query's per-command capture is drain-sensitive; the session bucket is not	IDbConnectionInterceptor.Opened attaches the handler on every EF-opened connection; one session capture at Closed covers both; works today against unmodified Z.EF.Plus
Z.EF actual (repro Scenario 2/2b)	one final command via Dispatch ([INTERCEPTED] × 1) + ~six raw roundtrips (temp-table create/populate, catalog reads; ServerRoundtrips: 7)	Z.EF/EF via wrapped reader for the final command	yes — this is the row the flag decides. Drain on (Scenario 2, observed): full capture incl. Orders / Customers / #ZZZProjects…. Drain off (Scenario 2b, predicted¹): raw commands' ExecuteNonQuery DONE tokens always parse → temp-table stats reliably present; final SELECT's trailing tokens parse only if Close drains → the production "only that table's stats" signature	one bucket attributed to the single intercepted command, spanning all roundtrips (duration / provider statistics include Z.EF's overhead); per-command attribution still requires Dispatch

Two clarifying notes:

1. The executes/materializes columns lose a little precision for D and E because those modes vary a third axis the original table didn't have — where the InfoMessage handler lives (per-command interceptor arming in A–C vs. connection/session scope in D–E).
2. In Mode E specifically, the EF query is double-covered (its command still goes through the Mode C path and lands in the session bucket), while the library's work is covered only by the session bucket — which is the concise way to state the conclusion: session-level capture is the floor that works today; Dispatch remains the ask for per-command attribution and reader-timed flushing.

[JonathanMagnan]

Hello @jzabroski,

I will provide a partial answer to ensure we try to progress on this request (my developer struggled a little bit with this request), but I believe we might still have an answer you are looking for.

Z.EF's internal commands still bypass the interception pipeline

Indeed, this decision was initially made because there is no built-in interception pipeline for SqlBulkCopy, only for DbCommand.

So what can you do?

When logging is enabled, we have an AddLogExecuting event that is called before is executed:

context.BulkMerge(list, options =>
{
	options.UseLogDump = true;
	options.AddLogExecuting = (command, log) =>
	{
		if (command is SqlBulkCopy)
		{

		}
		else if (command is SqlCommand)
		{

		}
	};
});

It is possible for you to catch the command through this event and do whatever you need with it. Could this help you? It might currently be the only possible way to achieve what you are looking for.

We are currently looking to add the AddLogExecuted event that will be called after a command is executed. So this is the one you will want to use.

NOTE 1: It should also be possible to configure this globally using EntityFrameworkManager.BulkOperationBuilder.

Let me know if this is a solution that is worth investigating or we need to better understand your current problem.

Best Regards,

Jon

[JonathanMagnan]

Hello @jzabroski ,

Just to let you know that the new AddLogExecuted option will be release around August 11.

Best Regards,

Jon

[jzabroski]

Thank you. I plan to pick this back up around then as well.

For context this will allow me to use AI to auto detect granular regression reasons upgrading from EF6 to EFCore. I thought through in detail all the inputs to the llm including a set of skills.

[JonathanMagnan]

Hello @jzabroski ,

Due to another pending feature, we pushed the release to August 18.

So it is coming very soon ;) But unfortunately not this week.

Best Regards,

Jon