Add Tracing in SqlClient

[saurabh500]

SqlClient doesn't have any tracing in .Net Core. All the Bid Tracing API calls were removed during the port to Core.
One of the options is to use EventSource to emit traces during runtime.
Something similar was done by @stephentoub in System.Data.Common .
Ref: https://github.com/dotnet/corefx/blob/master/src/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs

cc @corivera

[saurabh500]

I am adding the milestone of Future, however this needs re-triaging and should ideally happen by 2.1.

@divega , Will this be interesting from AppInsight perspective?

[divega]

@saurabh500 AFAIK, SqlClient was instrumented with diagnostic listener/source in dotnet/corefx@dbabd76. Assuming it all works ok, that should be enough for App Insights.

I am not sure if adding EventSource for out-of-proc tracing would be a good idea, also not sure about System.Data.Common carrying using EventSource and SqlClient using DiagnosticSource.

See https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md.

Also cc @vancem in case he provide more up to date guidance.

[divega]

I talked to @vancem and we believe we should standardize on DiagnosticSource rather than adding more EventSource. This is related to https://github.com/dotnet/corefx/issues/21160.

[divega]

As recently announced in the .NET Blog, focus on new SqlClient features an improvements is moving to the new Microsoft.Data.SqlClient package. For this reason, we are moving this issue to the new repo at https://github.com/dotnet/SqlClient. We will still use https://github.com/dotnet/corefx to track issues on other providers like System.Data.Odbc and System.Data.OleDB, and general ADO.NET and .NET data access issues.

[cheenamalhotra]

@saurabh500 @David-Engel @roji @danmosemsft @vancem

Would like to bring this topic to light again for Microsoft.Data.SqlClient.
For best user experience, what would you suggest we implement in both projects (NetFx and NetCore) that is easy to configure and integrates well with .NET ecosystem?

[roji]

@cheenamalhotra when I looked a couple years back, I think I saw that SqlClient was already generating events via DiagnosticSource, can you confirm? Would this be about generating EventSource events in addition to that?

Note that unrelated to tracing, there's also the question of the new .NET Core performance counters, which are yet another thing. I did this work for the recently-released Npgsql 4.1.0, and am planning to open a discussion issue for other providers as well.

[cheenamalhotra]

Hi @roji

'DaignosticSource` is in use for generating events in NetCore but its not as extensive as Bid Tracing in NetFx and its not applicable in NetFx too. NetFx used to have BID Tracing, but that's not possible to implement in NetCore for cross platform support.

Now in Microsoft.Data.SqlClient we are looking for a uniform solution that we can implement understanding what can be consumed for Application Insights and that can be made available from driver, irrespective of target framework.

[roji]

@cheenamalhotra I'm not super familiar with this domain... However, unless I'm mistaken EventSource exists in .NET Framework too, and could be the right thing if you need the same tech to support both Core and Framework. Both EventSource and DiagnosticSource exist on both Core and Framework. You may want to read this useful comment about DiagnosticSource vs. EventSource.

Note also https://github.com/dotnet/corefx/issues/21160, which is a stalled issue about standardizing DiagnosticListener for ADO.NET providers.

[saurabh500]

Based on the amount of tracing information that was being emitted by NetFx Event Source is the way to go. We are not looking to capture the whole application context, but the internal execution information during different API execution in SqlClient.

The usecase for BID tracing is that we capture BID traces for postmortems, to know what happened at granular level inside the driver, when problems occur at customer's end. CSS usually asks the customer to enable the tracing and analyses the traces or sends it to the Product team to take a look and explain the failure behaviors.

The addition of DiagnosticSource to SqlClient in .Net core can help application developers look inside the success or failures of SqlClient from the perspective of the applications. However for a deep dive into things like why did the client send out an attention packet after issuing a query, Event Source like tracing mechanism is what we are looking at.

FWIW, System.Data.Common uses EventSource as a replacement for BID as well. @stephentoub had done the migration for System.Data.Common when he brought in the code to provide parity with .Net framework.

Also SqlClient NetFx should have the same DiagnosticSource capabilities that .Net Core offers for parity.

[cheenamalhotra]

@roji @saurabh500

Thanks for details. So I believe we should be looking at "EventSource" in terms of replacement for BID tracing for High Volume traces that can apply to both .NET Framework and .NET Core, starting with replacing NetFx BID calls, porting over to NetCore. So that can be called as Deep Tracing.

"DiagnosticSource" on the other hand can be labelled as Shallow Tracing, to provide logging capabilities for Application Developers and App Insights, as currently implemented in NetCore to be ported over to NetFx.

I do see both are useful and have their own purpose and benefits, but looking at the amount of work this will bring, it seems unlikely to complete in 1.1.

Please confirm if we all agree on implementing both styles of tracing for SqlClient drivers (NetFx and NetCore), and we shall accommodate this in next release plan.

[roji]

It does seem that both styles of tracing may be relevant, although it also seems that there is considerable overlap in what they provide, and I personally still don't have a 100% clear picture of which should be used for what.

Regardless, what would be really great is some sort of quick spec/writeup on which events you're planning to emit and when, before implementation. That would allow us to have a more concrete conversation about it possibly align across different ADO providers.

Note: in addition to https://github.com/dotnet/corefx/issues/21160, https://github.com/dotnet/corefx/issues/29534 is an additional issue I filed at the time. tl;dr SqlCient's current implementation of DiagnosticSource seems like it doesn't really follow best practices. I understand that the priority here is to bring over what exists from Core to Framework and not to change things, but this could also be a good moment to rethink the DiagnosticSource support itself. If you're willing to do this, I'd be happy to work together and produce a spec.

[cheenamalhotra]

Hi @roji

It would be great if you can send us a spec/writeup for the same.
We'd also like to address this nicely with best practices.

[jwooley]

It seems that the focus here is on app insights. I want to make sure that the Visual Studio Diagnostic Tools are not ignored as they are more helpful before the app is deployed.

[cheenamalhotra]

Hi @jwooley

Could you please elaborate a bit about how Visual Studio Diagnostic Tools pick Diagnostic Logs from library and if "EventSource" and "DiagnosticSource" would suffice the requirement?

If not, then what is the desired logging/tracing that can be implemented in SqlClient uniformly for .NET Framework, .Net Core, and .NET Standard targeting applications?

[jwooley]

I'm not sure what triggers items to appear in the Diagnostic tools internally, but liked the ability that we had with .Net to see the ADO requests in there. This ability seems to have been lost in Core. Assuming adding back in proper source calls would fix this issue, I'm fine with the change. The conversation was primarily around supporting App Insights and I wanted to make sure that the Diagnostic tools weren't forgotten about.

[Wraith2]

There is an open PR to add EventSource based tracing to the netfx version of the library and it would make sense to do the same to the netcore version of the library in the same release if possible to give consumers a consistant experience, we can say "it will work from version 2.0.0 onwards".

There is already diagnostics tracing in place using DiagnosticSource but I can't find any examples or direction on how to consume this from out of process. EventSource is almost entirely out of process though and as @cheenamalhotra has mentioned above if the data rate is high it would be beneficial to use the strongly typed manifested approach it has to avoid perf issues.

So I think we should mirror the EventSource implementation into core if we can and have it complement rather than replace the existing DiagnosticSource events. The only question I have on this is will this work for consumers like app insights and visual studio? Is this what they need to reach feature parity with the original netfx implementation so they can report command information and timings? Can someone on the MS side do a little internal outreach to those groups and get their requirements?

[cheenamalhotra]

Request from @davidmikh [dotnet/runtime#32774]:

When using the WriteCommandBefore and WriteCommandAfter DiagnosticSource events defined in this file it doesn't seem like there's a way to associate commands with the transactions they were a part of. In the WriteCommand events you're able to tell if the command was part of a transaction based on the Transaction property of the SQLCommand being not null, however it doesn't seem like there's a way to tell which transaction the command was a part of since the transaction object itself doesn't have any public properties to help identify it from other transactions using the same connection. As a result you can't tell which commands were grouped together in which transaction, you can only tell if a command was part of a transaction at all. Would it be possible to add a property to the transaction object itself or to one of the WriteCommand DiagnosticSource events so that you can associate which commands were part of the same transaction together?

It would also be ideal if there was a way to associate the WriteCommand events with the WriteTransaction events for the queries that are part of a transaction, however I'd be happy with just being able to tell which commands are part of the same transaction.

[cheenamalhotra]

Closing issue since EventSource tracing is now added to SqlClient.