Elastic_apm_profiler System.Data.SqlClient.SqlCommand ERROR

Elastic Observability APM
1

L.s.

Where using elastic_apm_profiler version 1.19.0 to collect APM data from our IIS app pool (Windows server 2016, IIS 10.0.14393.0). Most of the data seems to arrive at our elastic deployment. But some SQL query data seems to be missing.

The data is delivert to an elastic cloud deployment (version 8.6.1)

Our config looks as followes:

$appcmd = "$($env:systemroot)\system32\inetsrv\AppCmd.exe"
$profilerHomeDir = "D:\Elastic\elastic-apm-profiler"
$appPool = "OutSystemsApplications"
$ApmUrl = "https://*.apm.westeurope.azure.elastic-cloud.com"
$ApmToken = "*"
$ApmEnvironment = "ZZZ"

$environment = @{
  # config profiler
  COR_ENABLE_PROFILING = "1"
  COR_PROFILER_PATH = "$profilerHomeDir\elastic_apm_profiler.dll"
  COR_PROFILER = "{FA65FE15-F085-4681-9B20-95E04F6C03CC}"
  COMPlus_LoaderOptimization = "1" 
  ELASTIC_APM_PROFILER_HOME = "$profilerHomeDir\"
  ELASTIC_APM_PROFILER_INTEGRATIONS = "$profilerHomeDir\integrations.yml"
  ELASTIC_APM_PROFILER_LOG_DIR="$profilerHomeDir\logs"
  ELASTIC_APM_PROFILER_LOG="none"
  ELASTIC_APM_PROFILER_LOG_IL="1"
  
  # Init Agent
  ELASTIC_APM_SERVER_URL="$ApmUrl"
  ELASTIC_APM_SECRET_TOKEN="$ApmToken" 
  ELASTIC_APM_ENVIRONMENT="$ApmEnvironment"
  ELASTIC_APM_SERVICE_NAME="$appPool"
  ELASTIC_APM_CENTRAL_CONFIG="true"
  ELASTIC_APM_METRICS_INTERVAL="30000"
}

# add entry
$environment.Keys | ForEach-Object {
  write-output "[name='$appPool'].environmentVariables.[name='$_',value='$($environment[$_])']"
  & $appcmd set config -section:system.applicationHost/applicationPools /+"[name='$appPool'].environmentVariables.[name='$_',value='$($environment[$_])']" 
}

The error we get (in high volume) is:
//
[2023-01-30T14:30:17.8818747+01:00] [ERROR] exception whilst instrumenting integration <Elastic.Apm.Profiler.Managed.Integrations.AdoNet.CommandExecuteReaderWithBehaviorIntegration, System.Data.SqlClient.SqlCommand>
System.NullReferenceException: Object reference not set to an instance of an object.
at Elastic.Apm.Model.Span.TryToCompressRegular(Span sibling) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm\Model\Span.cs:line 613
at Elastic.Apm.Model.Span.TryToCompress(Span sibling) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm\Model\Span.cs:line 573
at Elastic.Apm.Model.Span.End() in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm\Model\Span.cs:line 504
at Elastic.Apm.Model.DbSpanCommon.EndSpan(ISpan span, IDbCommand dbCommand, Outcome outcome, Nullable1 duration) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm\Model\DbSpanCommon.cs:line 77 at Elastic.Apm.Profiler.Managed.Integrations.AdoNet.DbSpanFactory1.EndSpan(ApmAgent agent, IDbCommand command, ISpan span, Exception exception) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm.Profiler.Managed\Integrations\AdoNet\DbSpanFactory.cs:line 56
at Elastic.Apm.Profiler.Managed.Integrations.AdoNet.CommandExecuteReaderWithBehaviorIntegration.OnMethodEnd[TTarget,TReturn](TTarget instance, TReturn returnValue, Exception exception, CallTargetState state) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm.Profiler.Managed\Integrations\AdoNet\CommandExecuteReaderWithBehaviorIntegration.cs:line 70
at CommandExecuteReaderWithBehaviorIntegration.OnMethodEnd.SqlCommand.DbDataReader(SqlCommand , DbDataReader , Exception , CallTargetState )
at Elastic.Apm.Profiler.Managed.CallTarget.Handlers.EndMethodHandler3.Invoke(TTarget instance, TReturn returnValue, Exception exception, CallTargetState state) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_v1.19.0\apm-agent-dotnet\src\Elastic.Apm.Profiler.Managed\CallTarget\Handlers\EndMethodHandler1.cs:line 100
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
//

Does anyone know what this means and how to fix it?

Thanks a lot!

Regards,
Alexander

2

Hi @avanlieshout,

based on the stack trace you pasted, the bug seems to be in span compression. In some scenarios you can end up with a high amount of very similar spans (in this case lots of similar database calls) and the agent tries to compress those spans into a single span which essentially aggregates multiple similar spans as a single span. Now - from what I see, this seems to go wrong and causing the issue.

As a workaround, could you please try to turn off span compression and see if that makes the error go away and also if by turning it off, you see those db statements? Docs on it can be found here: Core configuration options | APM .NET Agent Reference [1.x] | Elastic tldr: just set ELASTIC_APM_SPAN_COMPRESSION_ENABLED to false.

Sorry about the trouble!

I also opened a bug about this in the agent repo: NullReferenceException in span compression · Issue #1999 · elastic/apm-agent-dotnet · GitHub

3

Hi @GregKalapos,

Thanks for the quick response, I will try this share the results.

4

The spans are indeed the problem. The work-around worked.

5

Thanks for the feedback @avanlieshout.

You can follow the linked GitHub issue for a longer term solution.

6

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.