Add interception event to be fired when EF has finished consuming a result set

[windhandel]

File a bug

It was suggested on an issue that a new issue be created for the issue I am experiencing. Here is the behavior.

I have attempted to build both an IDbConnectionInterceptor or IDbCommandInterceptor implementation that allows me to attach to the underlying SqlConnection's InfoMessage event in order to retrieve the messages created by running the command:

SET STATISTICS IO ON;

just prior to individual EF Core SQL command.

Initially, I attempted to do this within an IDbCommandInterceptor since I must modify the command text to include the prefixed statement. Although the IDbCommandInterceptor fired, no such event could be picked up, despite attaching to the event.

At @roji 's suggestion, I attempted to create an implementation of IDbConnectionInterceptor, but none of the events on the basic implementation are being fired.

Include your code

IDbConnectionInterceptor:

    public class BareDbConnectionInterceptor : DbConnectionInterceptor, IDbConnectionInterceptor
    {
        bool attached = false;

        public BareDbConnectionInterceptor()
        {
        }

        void InfoMessageHandler(object sender, SqlInfoMessageEventArgs args)
        {
            Debug.WriteLine(args.Message);
        }

        void attachStatisticsTracking(SqlConnection sqlConnection)
        {
            if (attached)
            {
                sqlConnection.InfoMessage += InfoMessageHandler;
                attached = true;
            }
        }

        public override InterceptionResult ConnectionOpening(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return result;
        }

        public override Task<InterceptionResult> ConnectionOpeningAsync(DbConnection connection, ConnectionEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override void ConnectionOpened(DbConnection connection, ConnectionEndEventData eventData)
        {
            attachStatisticsTracking(connection as SqlConnection);
        }

        public override Task ConnectionOpenedAsync(DbConnection connection, ConnectionEndEventData eventData, CancellationToken cancellationToken = default)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return Task.CompletedTask;
        }

        public override void ConnectionFailed(DbConnection connection, ConnectionErrorEventData eventData)
        {
            base.ConnectionFailed(connection, eventData);
        }
        public override Task ConnectionFailedAsync(DbConnection connection, ConnectionErrorEventData eventData, CancellationToken cancellationToken = default)
        {
            return base.ConnectionFailedAsync(connection, eventData, cancellationToken);
        }

        public override InterceptionResult ConnectionClosing(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            return base.ConnectionClosing(connection, eventData, result);
        }

        public override Task<InterceptionResult> ConnectionClosingAsync(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            return base.ConnectionClosingAsync(connection, eventData, result);
        }

        public override void ConnectionClosed(DbConnection connection, ConnectionEndEventData eventData)
        {
            base.ConnectionClosed(connection, eventData);
        }

        public override Task ConnectionClosedAsync(DbConnection connection, ConnectionEndEventData eventData)
        {
            return base.ConnectionClosedAsync(connection, eventData);
        }
    }

Adding Interceptors to the DbContext:

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        {
            if (!(_sharedConnectionFactory?.IsNull).GetValueOrDefault(true))
            {
                // Shared connections/transactions enable us to handle the entire test run under a single transaction within the database.
                optionsBuilder
                    .UseSqlServer(_sharedConnectionFactory.Connection)
                    .AddInterceptors(_interceptors);
            }

            base.OnConfiguring(optionsBuilder);
        }

NOTE: A SharedConnectionFactory is being utilized in order to facilitate handling transactions between context instances as part of the same ASP.NET request.

I can confirm the following with breakpoints and stepping over the respective lines of code:

1.) The constructor of the BareDbConnectionInterceptor is being executed.
2.) The IEnumerable (_interceptors, above) contains the BareDbConnectionInterceptor.
3.) That the .AddInterceptors method is being called with the IEnumerable.

However, none of the following methods of the BareDbConnectionInterceptor are being hit by breakpoint and breakpoints are attached correctly:

• ConnectionOpening
• ConnectionOpeningAsync
• ConnectionOpened
• ConnectionOpenedAsync
• ConnectionClosing
• ConnectionClosingAsync
• ConnectionClosed
• ConnectionClosedAsync
• ConnectionFailed
• ConnectionFailedAsync

Include stack traces

No exceptions, including any first-chance exceptions, are being thrown.

Include verbose output

I included what I believed to be the pertinent section, but removed customer-code-specific information

Using assembly '[Project].API'.
Using startup assembly '[Project].API'.
Using application base '[path]\[Project].API\bin\Debug\netcoreapp3.1'.
Using working directory '[path]\[Project].API'.
Using root namespace '[Project].API'.
Using project directory '[path]\[Project].API\'.
Remaining arguments: .
Finding DbContext classes...
Finding IDesignTimeDbContextFactory implementations...
Finding application service provider...
Finding Microsoft.Extensions.Hosting service provider...
Using environment 'Development'.
Using application service provider from Microsoft.Extensions.Hosting.
Found DbContext '[Project]Context'.
Finding DbContext classes in the project...

Include provider and version information

EF Core version:
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: 3.1.402 [C:\Program Files\dotnet\sdk]
Operating system: Windows 10 V1909
IDE: VS 2019 Version 16.7.3

Thanks for your assistance with this two-part issue.

[ajcvickers]

@windhandel These methods will only be called if EF opens/closes the connection for you. Is this happening, or are you opening the connection at the application level? Debug level logging should fire whenever EF opens and closes the connection--can you check for that?

[windhandel]

Ah, I see, @ajcvickers. My shared connection factory is currently handling the open/close of the connection in order to begin the transaction and carry that transaction through (as there's no easy way to get access to the currently opened transaction off of connection established on your behalf) to other future-connections.

Is there any reason why I shouldn't expect an InfoMessage event to be received back on my SqlConnection within this IDbCommandInterceptor?

    public class BareTrackingCommandInterceptor : DbCommandInterceptor, IDbCommandInterceptor
    {
        bool attached = false;

        public BareTrackingCommandInterceptor()
        {
        }

        void InfoMessageHandler(object sender, SqlInfoMessageEventArgs args)
        {
            Debug.WriteLine(args.Message);
        }

        void attachStatisticsTracking(SqlConnection sqlConnection)
        {
            if (!attached)
            {
                sqlConnection.InfoMessage += InfoMessageHandler;
                attached = true;
            }
        }

        void enableLogicalReads(SqlCommand command)
        {
            command.CommandText = "SET STATISTICS IO ON;" + command.CommandText;
        }

        public override DbCommand CommandCreated(CommandEndEventData eventData, DbCommand result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return base.CommandCreated(eventData, result);
        }

        public override InterceptionResult<DbDataReader> ReaderExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override InterceptionResult<object> ScalarExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<object> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override InterceptionResult<int> NonQueryExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<int> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override Task<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override Task<InterceptionResult<object>> ScalarExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<object> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override Task<InterceptionResult<int>> NonQueryExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<int> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }
    }

Should my shared connection factory be disposing and recreating the SqlConnection with the shared transaction for every connection? Maybe reusing the SqlConnection object has something to do with why the InfoMessage event may not be firing?

[ajcvickers]

@windhandel I don't know anything about the InfoMessage event; you'll probably want to follow up with the SqlClient team on that.

[windhandel]

Hmmmmm, @ajcvickers , I've dumbied up a simple prototype of the SqlConnection and confirmed the functionality works without EF Core. The reason I ask here is because it only seems not to work while using EF Core.

EDIT: It turns out it may not work as expected, see message below.

[windhandel]

Hi @ajcvickers,

Upon further investigation, I suspect I may know the cause of why EF Core may not be causing the InfoMessage event to fire based on this SO article.

Here is an example that may depict the source of the issue. If you set callNextResultAsync to true, then the loop at the bottom is called, which is required in order to get to the second result which contains the info messages.

If this is not being called by EF (even though a second result is not expected), the SQL Connection's InfoMessage event will not be fired.

Are you aware of whether NextResultAsync is being called, despite no additional results being expected by EF Core?

class Program
    {
        static async System.Threading.Tasks.Task Main(string[] args)
        {
            bool callNextResultAsync = false;

            SqlConnection connection = new SqlConnection("connectionstring");
            connection.Open();
            var trans = connection.BeginTransaction();

            connection.InfoMessage += Connection_InfoMessage;
            
            SqlCommand cmd = new SqlCommand();
            cmd.Connection = connection;
            cmd.Transaction = trans;

            cmd.CommandText = "SET STATISTICS IO ON;SELECT * FROM sys.objects";
            using (var reader = await cmd.ExecuteReaderAsync())
            {
                var incr = 0;
                while (await reader.ReadAsync())
                {
                    //Statements to read data from Table1
                    Console.WriteLine(reader.GetString(0));
                    incr++;
                }

                while (callNextResultAsync && await reader.NextResultAsync())
                {
                    while (await reader.ReadAsync())
                    {
                        //Statements to read data from Table2
                        Console.WriteLine(reader.GetString(0));
                        incr++;
                    }
                }
            }
        }

        private static void Connection_InfoMessage(object sender, SqlInfoMessageEventArgs e)
        {
            Console.WriteLine(e.Message);
        }
    }

Thanks,
Jeff

[windhandel]

I've confirmed the fix to EF Core by making the additional call to NextResult which isn't being done.

I added this line into my IDbCommandInterceptor and now the InfoMessage event is being called correctly:

        public override Task<DbDataReader> ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default)
        {
            result.NextResult();

            return base.ReaderExecutedAsync(command, eventData, result, cancellationToken);
        }

[smitpatel]

Can you describe why does EF Core need to call NextResult? It certainly does not seem to cause any error in results/data read from server.

[windhandel]

Sure, @smitpatel , if you take a quick look at my SQL Server-agnostic example, above, and change the callNextResultAsync to true/false for different executions, it will become apparent.

False - SqlConnection's InfoMessage event is not fired
True - SqlConnection's InfoMessage event is fired

The call to NextResult does not determine result success or failure, but without calling NextResult, the expected side effect of firing the underlying connections InfoMessage event will not happen.

Note:

 connection.InfoMessage += Connection_InfoMessage;

[smitpatel]

So you are actually editing the SqlCommand we send and add statistics query in front of it. Yes, EF Core want call NextResult since we only sent one command to server. Interceptor decided to add another command in front of it. The interceptor should intercept the DbDataReader after it is opened, read the statistics data generated by first query, advance reader to NextResult before returning to EF Core. As you have shown here #23535 (comment)

There is nothing actionable on EF Core side. We are doing exact processing for the command we generated. Interceptor do whatever is required to process if they change the command text.

[windhandel]

You only offered one-such example that passes your statement, there are a few that do not pass your statement as true.

• A stored procedure that has informational messages
• A sql connection that previously fires any number of message outputting session-level statements, including:

SET STATISTICS IO ON;
SET STATISTICS TIME ON;

As it stands, if EF Core does not call NextResult, then the InfoMessage event will not be fired, which is not expected behavior.

[windhandel]

@ajcvickers, @roji, @AndriySvyryd - you were surprised by my prior response on #11564. The above response to an obvious bug in EF Core is the sort of thing that ends in the type of frustration I expressed previously.

[smitpatel]

Can please explain why EF Core need to call "NextResult" when EF Core does not send multiple commands in a batch?

[windhandel]

@smitpatel, because if EF Core doesn't call it, then expected side effects will not happen. Your team is (now) aware of the expected side effects.

Here's the question: Do you expect EF Core to fire the SqlConnection's InfoMessage event when there are informational messages consistently? If so, there's a bug - because they are in some circumstances and not in others.

IMO, those side effects are supposed to work no matter what because developers who are familiar with the underlying APIs should be able to do what @ajcvickers said in the other issue: "you can use the underlying SqlConnection object after SaveChanges to query the database for whatever is needed, so if you figure out how to do this outside of EF, then the same thing should work with EF."

[smitpatel]

There is no side-effect. EF Core does not call it because there are no multiple commands in the batch. If you are adding multiple commands then you are responsible to call the NextResult.
That is consistent with what @ajcvickers said. If you have figured out how to do it outside of EF, using SqlConnection where you call NextResult yourself, you should be able to do it with EF where you call NextResult yourself.

I am still missing what is the bug here. Can you provide a full repro code where bug represents without anything modified by developer? If developer modifies underlying SqlConnection in anyway then developer needs to do whatever is necessary.

[windhandel]

This bug repro is very, very simple. You can repro it with the following:

1.) Write a stored procedure which prints a message, here's one:

CREATE PROCEDURE dbo.TestMessage()
As
SELECT 1 as Column1;
PRINT 'Hello world'
GO

2.) Write a simple IDbCommandInterceptor that attaches to EF Core's SqlConnection.InfoMessage. No "modification of underlying SqlConnection" required.

3.) Ensure that the sproc is retrieved using a DbDataReader internally by EF Core.

Observe no such InfoMessage event will be fired.

If you are suggesting that the very act of attaching to an event of an existing SqlConnection of EF Core, now developers become responsible for the internal execution of EF Core, that seems unrealistic and unexpected.

[smitpatel]

Since the sproc has side effects, it is user responsibility to handle it accordingly.
If you are using query FromSql* API to invoke the sproc then task of query is to get the results from server and create client side objects any side-effect is irrelevant to query and there will not be anything additional done by query pipeline. Further, notice that EF Core has no knowledge that when to call NextResult since we don't parse user SQL.

If you are using any other api to get ExecuteReader then it is your responsibility to call NextResult on the underlying Data reader you get.

If you are suggesting that the very act of attaching to an event of an existing SqlConnection of EF Core, now developers become responsible for the internal execution of EF Core, that seems unrealistic and unexpected.

That is not expectation we have. But if you are executing a command which has side-effects then it is your responsibility to call NextResult. EF Core does not generate any command with such side-effect (without user provided SQL) so we don't call it.

[windhandel]

If you prefer to leave the InfoMessage event firing under some scenarios and not under others, that's your choice.

[windhandel]

So, I really couldn't understand why you were pushing back so hard on why this was a bug or not.

Now I see that my suggested solution doesn't even work because the EF Core hasn't read the result yet in IDbCommandInterceptor. It effectively breaks or requires an additional method on the IDbCommandInterceptor.

By pushing to the next result, I get no results from EF Core.

And you didn't return the IDbDataReader interface as the return type, so I can't really extend it to try and fix it myself further.

[smitpatel]

So, I really couldn't understand why you were pushing back so hard on why this was a bug or not.

InfoMessage firing is somewhat orthogonal. It fires only when NextResult is called. Certain very specific SQL requires calling NextResult. Whoever is owner of such SQL is required to call NextResult as needed to move to next result set. If EF Core generates such SQL it will call NextResult. If the SQL comes from outside of EF then the outside entity is the only entity aware that NextResult needs to be called and need to do so themselves. EF Core does not even know that NextResult needs to be called for such SQL since it did not generate it.

Now, if you are saying that without any user provided SQL in anyway, EF Core itself generated a SQL which requires calling NextResult and we are not calling it then, it would be bug. Though I doubt that is happening since without NextResult we wouldn't be able to consume results from next result set.

If your own result set is after the one generated by EF Core then probably you should intercept when EF Core disposes the reader. It would have consumed the expected result set by then fully.

[windhandel]

I had already tried the Disposing method. Unfortunately, the Reader is already closed by then. Shouldn't it be called Disposed instead?

I just tried to use reflection to create a DbDataReader from the existing one in order to enable me to call NextResult and still have the prior DbDataReader to return, but appears to not be implemented.

It's starting to appear there is no workaround outside of abandoning EF Core or my attempt at retrieving the statistics in order to measure performance.

[windhandel]

@roji here's an update:

As it stands, there appears to be no way to gather the table-level performance information for a given set of EF Queries because of this issue.

It's not possible, based on my above statements, to work around the issue. Neither is it possible to gather table-level statistics about the queries without being able to utilize the InfoMessage event - the table level information is not available via dynamic management views.

There appears to be no downside to calling the NextResult as it will simply return false, to my knowledge

I'm forced to resort to high-level (not table-specific) query statistics for test assertions against EF Core without this information.

If I'm able to find the time next month, I may submit a PR for this and I'll try to get to the prior LOH issue.

Thanks,
Jeff

[ajcvickers]

We discussed this and decided that it would be useful an additional hook that fires when EF has finished consuming the result set. This would allow calling of NextResult by application code and thereby trigger any side effects.

[SergeyToff]

if use in interception "suppressWithResult" on ReaderExecuting(not executed)

       public override InterceptionResult<DbDataReader> ReaderExecuting(
            DbCommand command,
            CommandEventData eventData,
            InterceptionResult<DbDataReader> result)
        {
            ManipulateCommand(command);
            using var rdr = command.ExecuteReader();
            using var dt = new DataTable();
            dt.Load(rdr);
            return InterceptionResult<DbDataReader>.SuppressWithResult(dt.CreateDataReader());
        }

and use DbConnectionInterceptor on Open connection

 public override void ConnectionOpened(DbConnection connection, ConnectionEndEventData eventData)
        {
            if (connection is SqlConnection sqlConnection)
            {
                    sqlConnection.InfoMessage += (s, e) =>
                    {
                        if (e.Errors[0].Number == 3615)
                        {
                            _queryResultDto.Statistics = e.Message;
                        }
                    };
            }
            base.ConnectionOpened(connection, eventData);
        }

all fine :)

[alexandis]

Could you please suggest how to make interceptor affect the generated migration script? I need to strip quotes around generated DB objects, but cannot find the way to do that. The Db context is traditionally created inside IDesignTimeDbContextFactory implementation.

[ajcvickers]

@alexandis Interceptors cannot, by their nature, affect a migration script. Interceptors like this kick in when interacting with the database. EF does not interact with the database when generating a script.

[windhandel]

Hey @ajcvickers is there an easy way to get the entity associated with a currently executing DbCommandInterceptor? I'm trying to gather this for logging purposes and not seeing via docs, api or search. Kind regards.

[ajcvickers]

@windhandel What do you mean by, "the entity associated with a currently executing DbCommandInterceptor?"

[windhandel]

Well, I'm making some assumptions regarding the design based on a lack of understanding, but I'm assuming the overall gist is something like this:

1.) You new up a context.
2.) You perform an action on a given entity.
3.) This results in an DbCommand being created.
4.) This results in an Interceptor being executed.

I'm wanting to gather the information from #2 within #4 and I'm struggling to do so.

await dbContext.Set<TModel>().AddAsync(model, cancellationToken.Value);

In other words, how do I gather TModel and AddAsync, above, from within a DbCommandInterceptor?

[roji]

@windhandel command interceptors work at the lower SQL/ADO.NET layer, intercepting a DbCommand. A single DbCommand can be associated with any number of entity (e.g. fetch both Blogs and Posts in the same command), or with none at all (e.g. a query projecting out some column of some entity somewhere).

For us to be able to help, could you please give some context on what exactly you're trying to do, and why you're trying to know about an associated entity in a command interceptor?

[windhandel]

Thanks @roji . It's an extension of the OP. I'm trying to identify the total quantity of logical reads a given action against a dbcontext object yields for performance sake. Which is why I'm trying to correlate the two. I want to be able to surface up, as instrumentation, this information to developers in a meaningful way so that they know the impact individual context actions have.

To clarify, I'm mainly looking for the "root" or entry entity. Not any navigation properties, etc.

[roji]

@windhandel the problem here isn't just navigation properties: consider also set operations and joins... For example, in the query ctx.Blogs.Join(ctx.Posts, ...), I'm assuming your "root" entity type is Blogs; but you can switch this around to ctx.Posts.Join(ctx.Blogs, ...). This query is conceptually the same thing and can yield the same results, but the "root" entity type is now Posts. So I'd think carefully about what it is exactly that you're trying to track/count here and why. If you're trying to analyze query performance per table, that's something that I'd advise tackling in the database rather than via EF query interception; databases already include powerful tools for analyzing which queries are slow and why - that's the right place to do this kind of thing.

Regardless of the why, if you want to implement something like this, a command interceptor isn't the right extension point, since it works at the low-level SQL command level, which is unaware of higher-level details like entities being queried. I don't think EF has a built-in extension point for implementing something like this. Since EF has an open DI-based design, you can always insert an expression tree visitor that would find the root DbSet; but this would need to be inserted at the very beginning of the query pipeline, to avoid EF's internal query caching (since you want to count for every execution). Since this would visit the tree on every single invocation, that would impose a perf penalty (and also is incompatible with compiled queries).

As a possible alternative, a far simpler approach would simply be for your DbContext implementation to expose DbSet properties which, when read, increment your counters. This doesn't require any interceptor or expression tree visitation; note that in the Join examples above, it would increment the counter for both Blogs and Posts (I have no idea whether that's desirable).

But once again, I'd recommend thinking about what exactly you're trying to achieve and if it's a good idea to do it within EF.