Running JDBC instrumentation causing delays in socket read from DB

[PaarthB]

Describe the bug
Running JDBC instrumentation causing large running times for threads wanting to socket read from DB . This causes application threads wanting to read from DB to taken longer , causing thread pool (Tomcat) starvation. This appears to be some sort of overhead introduced by the JDBC instrumentation running.

Steps to reproduce
Use the JDBC instrumentation in Java OpenTelemery agent and observe load on DB CPU and also Write IOPs and application thread running times

What did you expect to see?
The service runs as normal without any potential issues causing DB CPU to go up more than expected, or application threads (Tomcat) to start waiting more than often on socket read from DB.

What did you see instead?
The service started getting longer than running threads that read from DB, causing threadpool starvation in the web service.

What version and what artifacts are you using?
Artifacts: (opentelemetry-bom, opentelemetry-javaagent, opentelemetry-sdk , opentelemetry-api, zipkin exporter)
Version: (v1.21.0)
How did you reference these artifacts? (pom.xml)

Environment
Compiler: "Java 11 temurin11"
OS: "Debian 11.6"
Runtime (if different from JDK above):
OS (if different from OS compiled on):

Additional context
To confirm this, we found that the issue went away once we turned the JDBC instrumentation off.
The name of the instrumentation is otel.instrumentation.jdbc.enabled which is set to false when running the JAR. This can also be confirmed here: https://opentelemetry.io/docs/instrumentation/java/automatic/agent-config/#suppressing-specific-agent-instrumentation

[laurit]

Firstly this is the correct project for this issue not opentelemetry-java. You may wish to update this issue with the additional details you added in the other issue and close that one. Secondly in open-telemetry/opentelemetry-java#5386 you mentioned that you see thread stuck in Db​Request​.create, could you past the full stack trace here (at least starting from the first method your application code calls) so we could see what Db​Request​.create calls and what connection pool you are using.

[PaarthB]

Hi @laurit , here is the stacktrace (I have removed the filters and other stuff before the DB request for fetch is made, to keep it easier to focus on)

java.net.SocketInputStream.socketRead0
java.net.SocketInputStream.socketRead
java.net.SocketInputStream.read
org.postgresql.core.VisibleBufferedInputStream.readMore
org.postgresql.core.VisibleBufferedInputStream.ensureBytes
org.postgresql.core.VisibleBufferedInputStream.read
org.postgresql.core.PGStream.receiveChar
org.postgresql.core.v3.QueryExecutorImpl.processResults
org.postgresql.core.v3.QueryExecutorImpl.execute
org.postgresql.jdbc.PgStatement.executeInternal
org.postgresql.jdbc.PgStatement.execute
org.postgresql.jdbc.PgPreparedStatement.executeWithFlags
org.postgresql.jdbc.PgPreparedStatement.executeUpdate
org.postgresql.jdbc.PgConnection.isValid
org.vibur.dbcp.utils.JdbcUtils.validateOrInitialize
org.vibur.dbcp.pool.ConnectionFactory.readyToTake
org.vibur.objectpool.ConcurrentPool.prepareToTake
org.vibur.objectpool.ConcurrentPool.takeObject
org.vibur.objectpool.ConcurrentPool.tryTake
org.vibur.dbcp.pool.PoolOperations.getConnHolder
org.vibur.dbcp.pool.PoolOperations.getProxyConnection
org.vibur.dbcp.ViburDBCPDataSource.getConnection
io.github.resilience4j.circuitbreaker.CircuitBreakingConnectionSupplier$Lambda.call
io.github.resilience4j.circuitbreaker.CircuitBreaker.lambda$decorateCallable$3
io.github.resilience4j.circuitbreaker.CircuitBreaker$Lambda.call
io.github.resilience4j.circuitbreaker.CircuitBreaker.executeCallable
io​.opentelemetry​.javaagent​.shaded​.instrumentation​.jdbc​.internal​.JdbcUtils.computeInfo <----
io​.opentelemetry​.javaagent​.shaded​.instrumentation​.jdbc​.internal​.JdbcUtils.extractDbInfo <----
io​.opentelemetry​.javaagent​.shaded​.instrumentation​.jdbc​.internal​.DbRequest.create <----
java.sql.PreparedStatement.executeQuery
com.querydsl.sql.AbstractSQLQuery.fetch

The lines using OpenTelemetry JDBC instrumentation are marked with <----

the call doesn't block (or wait unusually long) at those lines, rather it blocks at the last one further down the stacktrace SocketInputStream.socketRead0

[laurit]

Could you add package names. Or provide a minimal application that reproduces the issue. Keep in mind that we probably need to reproduce this to fix it, or verify that the fix works. It is hard to guess what framework these classes could belong to based on just the class name.

[PaarthB]

I have updated the original message with the package names @laurit

[laurit]

@PaarthB io​.opentelemetry​.javaagent​.shaded​.instrumentation​.jdbc​.internal​.JdbcUtils.computeInfo does not call a method named executeCallable. Have you removed something from the stack trace?

[PaarthB]

Hi @laurit yes I have, as I didn't want to disclose internal details of our service. But to answer how that call to executeCallable happens, we've got an internal implementation of grabbing a connection with a circuit breaker in place in case it fails. The executeCallable is doing that "get connection" operation, between the computeInfo and executeCallable methods.

[laurit]

So you have implemented a wrapper for java.sql.Connection but you don't implement java.sql.Wrapper? Agent uses

if (connection.isWrapperFor(Connection.class)) {
  connection = connection.unwrap(Connection.class);
}

to unwrap the connection and caches JdbcUtils.computeInfo based on the unwrapped connection. If the unwrapping fails agent will execute JdbcUtils.computeInfo for each wrapped connection. You could try implementing the wrapper interface so that agent could get the underlying connection and see if this improves the situation.

[PaarthB]

Thanks, will try and report my findings here.

[github-actions]

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.

[PaarthB]

I am trying to set breakpoints for encountering the OpenTelemetry classes in the stacktrace but I don't encounter them at all when stepping through the breakpoints. I believe this is due to bytecode injection, also I can't find these classes downloaded locally in Jira maven dependencies, so I cannot specify breakpoints directly in those classes either.

Would you have a suggestion how I can debug this @laurit ?

[laurit]

Library instrumentation classes are shaded under a different package name in agent to avoid conflicts when application bundles the same library. In intellij you can set a method breakpoint based on the class name, you can use the shaded name there and don't need to have the source code for the class. It is possible to build the agent without shading, see https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/docs/contributing/debugging.md#shadow-renaming