.NET Profiler does not trace/show MySQL transactions

Hi,

I'm trying to get insights in our MySQL queries in our APM transactions.

I've been following this guide: Profiler Auto instrumentation | APM .NET Agent Reference [master] | Elastic
Our application is containerized (normally hosted in kubernetes, used local docker for this test).

The docker file I've created


FROM mcr.microsoft.com/dotnet/aspnet:6.0 as base
WORKDIR /app
EXPOSE 80

FROM mcr.microsoft.com/dotnet/sdk:6.0 AS build

ARG AGENT_VERSION=1.14.0

WORKDIR /src
COPY . .
WORKDIR /src/API

RUN apt-get -y update && apt-get -yq install unzip
RUN curl -L -o elastic_apm_profiler_${AGENT_VERSION}.zip https://github.com/elastic/apm-agent-dotnet/releases/download/${AGENT_VERSION}/ElasticApmAgent_${AGENT_VERSION}.zip  
RUN unzip elastic_apm_profiler_${AGENT_VERSION}.zip -d /elastic_apm_profiler_${AGENT_VERSION}

RUN dotnet publish API.csproj -c Release -o /app

FROM base AS final
WORKDIR /app

ARG AGENT_VERSION=1.14.0

COPY --from=build /app .
COPY --from=build /elastic_apm_profiler_${AGENT_VERSION} /elastic_apm_profiler
RUN mkdir /test

ENV CORECLR_ENABLE_PROFILING=1
ENV CORECLR_PROFILER={FA65FE15-F085-4681-9B20-95E04F6C03CC}
ENV CORECLR_PROFILER_PATH=/elastic_apm_profiler/libelastic_apm_profiler.so
ENV ELASTIC_APM_PROFILER_HOME=/elastic_apm_profiler
ENV ELASTIC_APM_PROFILER_INTEGRATIONS=/elastic_apm_profiler/integrations.yml

ENTRYPOINT ["dotnet", "API.dll"]

In the Startup.cs of the API project:

        Environment.SetEnvironmentVariable("ELASTIC_APM_ENVIRONMENT", "env.");
        Environment.SetEnvironmentVariable("ELASTIC_APM_SERVICE_NAME", "permission-api");
        Environment.SetEnvironmentVariable("ELASTIC_APM_SECRET_TOKEN", "##");
        Environment.SetEnvironmentVariable("ELASTIC_APM_SERVER_URL", "##");
        app.UseAllElasticApm();

And an example of a DB query in 1 of our repositories:

      using var connection = await _ConnectionFactory.CreateConnectionAsync();
      const string statement = "SELECT * FROM partner_permission WHERE ActorId = @actorId;";

      return await connection.QueryAsync<PartnerPermission>(statement, new { actorId });

Even tried adding a transaction:

      using var connection = await _ConnectionFactory.CreateConnectionAsync();
      using var transaction = connection.BeginTransaction();
      const string statement = "SELECT * FROM partner_permission WHERE ActorId = @actorId;";

      return await connection.QueryAsync<PartnerPermission>(statement, new { actorId }, transaction);

In the APM traces I still see a gap where the MySQL queries are being executed.

(relevant) Nuget packages used:
Elastic.Apm.NetCoreAll 1.14.0
MySql.Data 8.0.28
Dapper 2.0.123

What am I missing?

Thanks,
Danny

MySql commands are captured as APM spans, and spans are captured only if there is an active APM transaction.

In conjunction with other integrations, such as those for ASP.NET and ASP.NET Core for example, an APM transaction is started for the incoming request, so MySql spans would be captured inside of controller actions. If you're using the agent in a context where there isn't an active APM transaction, you can start one manually, then MySql commands will be captured as spans whilst the transaction is active.

It looks like you're using the ASP.NET Core integration too, so there should be transactions for incoming requests. Is it just the MySql spans that are missing?

Yes, only the MySql spans are missing. Any HTTP call made to other services are showing as expected.

Are you able to set the profiler log level to trace and IL logging, and share the profiler log? The following environment variables should be set

ELASTIC_APM_PROFILER_LOG_DIR="<log dir>"
ELASTIC_APM_PROFILER_LOG="trace"
ELASTIC_APM_PROFILER_LOG_IL="1"

Set <log dir> to a directory that the profiler will have access to write logs to.

Sorry for the late reply, somehow I dont receive email updates.

I've added the following to my dockerfile

RUN mkdir /apm_logs
RUN chmod 777 /apm_logs
ENV ELASTIC_APM_PROFILER_LOG_DIR="/apm_logs"
ENV ELASTIC_APM_PROFILER_LOG="trace"
ENV ELASTIC_APM_PROFILER_LOG_IL="1"

The logs directory remains empty though.

The fact we're not seeing a log file indicates to me that the profiler is not running. Looking at the Dockerfile, the command to download the profiler isn't for the right release artifact- it's downloading the startup hooks instead of the profiler.

I've put together an example app that demonstrates ASP.NET Core instrumented with the profiler.

  1. clone the repository at GitHub - russcam/ProfilerExample: ASP.NET Core application instrumented with Elastic APM profiler

  2. clone GitHub - elastic/apm-integration-testing: APM Integration Testing, which is an easy way to spin up Kibana, Elasticsearch and APM server with docker.

  3. Start docker 7.16.0 Elastic stack from the apm-integration-testing local directory

    python .\scripts\compose.py start 7.16.0
    
  4. Start mysql docker container on the same docker network as the stack

    docker run --name some-mysql -e MYSQL_ROOT_PASSWORD=my-secret-pw -e MYSQL_USER=dbuser -e MYSQL_PASSWORD=my-secret-pw -e MYSQL_DATABASE=test -p 3306:3306 --name mysql --network apm-integration-testing -d mysql
    
  5. Build the example application from the repository local directory

    docker build -t profilerexample .
    
  6. Run application on same docker network as the stack

    docker run -p 5000:80 profilerexample
    
  7. Open app on http://localhost:5000. Observe that there are MySql version details on the landing page.

  8. Open Kibana at http://localhost:5601 and log in with admin and password changeme

  9. Navigate to the APM UI and observe that the transaction contains MySql spans

Thanks a lot for this example!

I'll try it out, but might take a week or two. I'll get back to you to let you know if it worked out.

Thanks
Danny

Hi Russ,

So I managed to get it working (kind of). Also in the program/startup of the API there were a few minor differences.

The only issue I'm having now, is that the first API call is fully traced (including the mysql queries), but in all subsequent calls they are partially or fully missing again.

Both images below are the same call to the example you provided, where the first call has a lot more details.

In our application, after the first call the MySQL traces are missing in total.

Can you please show exactly how the agent configuration is performed in startup. The differences mentioned may explain the behaviour you're seeing

The shots were from the ProfilerExample repository. The only thing changes in there was the ELASTIC_APM_SERVER_URL variable to point to our production environment instead of the local docker one.

In our application, the startup is not really similiar to your example (we're still using the older .NET's Program/Startup one), but in Startup.cs in the Configure method I changed

        app.UseAllElasticApm();

to

        Agent.Subscribe(new AspNetCoreDiagnosticSubscriber());
        Agent.Subscribe(new AspNetCoreErrorDiagnosticsSubscriber());
        Agent.Subscribe(new HttpDiagnosticsSubscriber());

I've looked at the screenshots again, and what you're seeing between the first trace and subsequent traces is the correct behaviour of MySql.Data; the driver collects information on the first connection

So, this the expected behaviour of the MySql.Data driver and profiler auto instrumentation.

Good to know that part is expected behavior.

Then I'll I just need to find out why traces are nog being logged at all for subsequent calls in our application.

Is it possible to debug step through the subscribers? Specifically, the AspNetCoreDiagnosticSubscriber, which creates transactions for incoming requests.

Is there anything in the agent log or profiler logs that might provide more details? The agent log level can be in increased to trace to log a verbose amount of agent operation.

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