SQL Profiling: Network Time not assigned to SQL cost/time

dazbradbury commented 4 months ago

The only documentation I can see around profiling SQL is here: https://miniprofiler.com/dotnet/HowTo/ProfileEFCore, and here https://miniprofiler.com/dotnet/HowTo/ProfileSql. It's not clear if these two approaches are equivalent, but the following issue uses the former.

The documentation does not specify what to expect if you have a "fast" SQL query which spends a lot of time transferring data accross the network.

For example let's say we run:

SELECT *
FROM [Table]

Within a code block like:

using (Profiler.Step("Materialise Data"))
{
    unit.GetTable<Table>().Tolist();
}

This is a simple query, which SQL quickly runs, and Miniprofiler sat on an instance right next to the DB would show a total time close to the query time.

Now let's say we're hundreds of miles away from the DB. The time it takes to run the query on SQL server is still fast, but the overall query time including network transit is slow.

Where would you expect MiniProfiler to allocate that time? As far as I can tell, it does not appear in the SQL time, but makes it appear like the object materialisation is taking up the time:

If I run the exact same SQL query from SQL Server Management Studio, it takes several seconds (not 20ms).

Ideally we could separate out SQL query time from SQL network time, but failing that should the documentation be clearer on what time is being calculated and returned here?

dazbradbury commented 4 months ago

Just to note, that this information does exist, if TrackConnectionOpenClose is set to true, then the connection close event clearly happens after the sql - ExecuteReader. It's more that when you look at the aggregated view that context is loss / hard to interpret. Here is a more extreme example, where it takes 60s to transfer the data:

But you can see the aggregated view hides the fact the SQL call took 60s:

dazbradbury commented 4 months ago

So I just tested comparing ProfiledDbConnection (docs) vs. AddEntityFramework (docs) and it does seem they behave differently:

C# code for testing:

```c# using (profiler.Step("Using ProfiledDbConnection")) { using var connection = ServiceLocator.Get().CreateConnection(); var results = connection.Query($@" SELECT top 10000 * FROM [dbo].[Table] "); var output = results.ToList(); } using (profiler.Step("Using .AddEntityFramework()")) { var output = ServiceLocator.Get().GetTable() .Take(10000) .ToList(); } ```

You can see the difference in output from MiniProfiler here:

And looking at the detailed window:

So it does appear as though something is broken in the AddEntityFramework / RelationalDiagnosticListener.

dazbradbury commented 4 months ago

Debugging locally, it seems the issue is with line:

https://github.com/MiniProfiler/dotnet/blob/main/src/MiniProfiler.EntityFrameworkCore/RelationalDiagnosticListener.cs#L66

It seems data.Result is never a RelationalDataReader, but is always of type SqlDataReader (System.Data.Common.DbDataReader) in our configuration. A long shot, given how long ago this was written, but perhaps @NickCraver you might know whether that's a bug? If I change it to a logical OR allowing for SqlDataReader everything works, and we get some additional "First Result" feedback which is great!

Any chance of a fix here?

dazbradbury commented 4 months ago

Note: I've fixed this for us by using a custom version of RelationalDiagnostics.cs, which includes the small fix as mentioned above. All seems to be working fine, but it does mean we've diverged slightly from the main branch here.

The custom version can be injected in by replacing:

.AddEntityFramework();

With

.Services.AddSingleton<IMiniProfilerDiagnosticListener, RelationalDiagnosticListenerFixIssue671>();

MiniProfiler / dotnet

SQL Profiling: Network Time not assigned to SQL cost/time #671