Missing Sql instrumentation.

[vuqtran88]

Description When customer switching from "System.Data.SqlClient" to "Microsoft.Data.SqlClient", they see less sql database instrumentation.

Looking at the sql wrapper instrumentation xml, I see the following:

      <!-- built in MS SQL driver (framework) -->
      <match assemblyName="System.Data" className="System.Data.SqlClient.SqlCommand">
        <exactMethodMatcher methodName="ExecuteReader" parameters="System.Data.CommandBehavior,System.String" />
        <exactMethodMatcher methodName="ExecuteNonQuery" />
        <exactMethodMatcher methodName="ExecuteScalar" />
        <exactMethodMatcher methodName="ExecuteXmlReader" />
      </match>

      <!-- built in MS SQL driver (core / nuget) -->
      <match assemblyName="System.Data.SqlClient" className="System.Data.SqlClient.SqlCommand">
        <exactMethodMatcher methodName="ExecuteReader" parameters="System.Data.CommandBehavior" />
        <exactMethodMatcher methodName="ExecuteNonQuery" />
        <exactMethodMatcher methodName="ExecuteScalar" />
        <exactMethodMatcher methodName="ExecuteXmlReader" />
      </match>

      <!-- MS SQL flagship data access driver -->
      <match assemblyName="Microsoft.Data.SqlClient" className="Microsoft.Data.SqlClient.SqlCommand">
        <exactMethodMatcher methodName="ExecuteReader" parameters="System.Data.CommandBehavior" />
        <exactMethodMatcher methodName="ExecuteNonQuery" />
        <exactMethodMatcher methodName="ExecuteScalar" />
        <exactMethodMatcher methodName="ExecuteXmlReader" />
      </match>

For the System.Data assembly, the agent instruments the private ExecuteReader(System.Data.CommandBehavior, System.String) which covers instrumenting the 2 public method overloads ExecuteReader() and ExecuteReader(System.Data.CommandBehavior). However, the agent doesn't do the same for the Microsoft.Data.SqlClient and System.Data.SqlClient assemblies. This explains missing instrumentation. It could be that the implementation of these assemblies have changed. These need to be carefully validated.

Expected Behavior Sql instrumentation should be consistent across these listed assemblies.

[JcolemanNR]

@vuqtran88 and I paired on this and were able to reproduce the issue.

The root cause is that ExecuteReader() in the Microsoft.Data.SqlClient assembly has different internal methods that are called between .NET Framework and .NET (standard/core).

Our existing instrumentation works properly for .NET Standard/Core, and does not work properly for .NET Framework.

If we change the instrumentation to work for .NET Framework, then the instrumentation for .NET Standard/Core stops working.

There is a branch pushed to origin (jcoleman/missing-sql-instrumentation) which updates the .net framework mssql unbounded integration tests to use Microsoft.Data.SqlClient which reproduces the issue. If you review the history you will see a reverted attempt to fix the missing sql instrumentation. This change (if toggled) will fix/break the .Net Framework/Core tests.

The challenge is that we don't want to double instrument calls to ExecuteReader(). Ideally there would be a way to select different instrumentation for .Net Framework and .Net Core, but this is not a part of the architecture currently.

Here is a what .net framework encounters when ExecuteReader() is called (and not instrumented):

[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader()
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717057359352
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717076291576
[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlClientEventSource.TryScopeEnterEvent(System.String,!!0)
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717076291576
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717057291440
[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlClientEventSource.IsScopeEnabled()
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717057291440
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717057358472
[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.get_Statistics()
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717057358472
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717057366616
[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlConnection.get_StatisticsEnabled()
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717057366616
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717057359416
[Trace] 2021-09-14 23:08:24 Possibly instrumenting: (Module: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\df5fc63c\6d2bf406\assembly\dl3\5aa2f58a\00516ed2_b55cd701\Microsoft.Data.SqlClient.dll, AppDomain: /LM/W3SVC/1/ROOT-1-132761344909078279)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior,System.String)
[Trace] 2021-09-14 23:08:24 JITCompilationStartedFinished. 140717057359416
[Trace] 2021-09-14 23:08:24 JITCompilationStarted. 140717057355032

Here is a what .NET Core encounters when ExecuteReader() is called (and is instrumented):

[Trace] 2021-09-14 22:46:29 Possibly instrumenting: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader()
[Trace] 2021-09-14 22:46:29 JITCompilationStartedFinished. 140714706194488
[Trace] 2021-09-14 22:46:29 GetReJITParameters called
[Trace] 2021-09-14 22:46:29 ReJIT 140714706194488
[Trace] 2021-09-14 22:46:29 Possibly instrumenting: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader()
[Trace] 2021-09-14 22:46:29 GetReJITParameters finished
[Trace] 2021-09-14 22:46:29 ReJITCompilationStarted. 140714706194488
[Trace] 2021-09-14 22:46:29 ReJITCompilationStartedFinished. 140714706194488
[Trace] 2021-09-14 22:46:29 JITCompilationStarted. 140714706193672
[Trace] 2021-09-14 22:46:29 Possibly instrumenting: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.get_Statistics()
[Trace] 2021-09-14 22:46:29 JITCompilationStartedFinished. 140714706193672
[Trace] 2021-09-14 22:46:29 JITCompilationStarted. 140714706194504
[Trace] 2021-09-14 22:46:29 Possibly instrumenting: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior)
[Debug] 2021-09-14 22:46:29 Request reJIT: [140714706194504] (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior)
[Trace] 2021-09-14 22:46:29 JITCompilationStartedFinished. 140714706194504
[Trace] 2021-09-14 22:46:29 GetReJITParameters called
[Trace] 2021-09-14 22:46:29 ReJIT 140714706194504
[Trace] 2021-09-14 22:46:29 Possibly instrumenting: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior)
[Info ] 2021-09-14 22:46:29 Instrumenting method: (Module: C:\IntegrationTestWorkingDirectory\MicrosoftDataSqlClientTests_ba421e47-2a04-404d-9c0f-6d74262f29cc\BasicMvcCoreApplication\Microsoft.Data.SqlClient.dll, AppDomain: clrhost)[Microsoft.Data.SqlClient]Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior)

[workato-integration[bot]]

https://issues.newrelic.com/browse/NEWRELIC-3624