Add a span when waiting for an available database connection from a pool #9251
Conversation
deejgregor
force-pushed
the
hikaricp-blocked-tracking
branch
from
df910b9 to
fec7eac
Compare
|
Also: see support case 2199108 |
|
Thanks for the contribution @deejgregor! |
|
I've done a little bit more experimenting and I've found a few things along the way, so I wanted to provide an update and ask a few questions. First, my update: I simplified (I think) My questions:
Configuration options and tracingTodayjdbc-datasource not enabled (default)Database pool and database driver connection operations are not visible: no jdbc-datasource enabled
FutureI wanted to propose an option or two of how to configure this, but I haven't been terribly happy with anything I came up with. Here are my main thoughts:
That combination gets me three things:
One option could be to just enable the |
deejgregor
force-pushed
the
hikaricp-blocked-tracking
branch
2 times, most recently
from
9515216 to
a9a65c0
Compare
|
Thanks a lot for this contribution - the pool.waiting span is a very valuable addition and helps explain connection pool exhaustion delays much more clearly. A few comments:
I really like your vision for future improvements - especially the idea of adding more pool-level metrics (e.g. provider, max size, active usage). That would make the traces much more insightful. I also share your concern about generating a large number of short spans in high-traffic systems. Sampling or aggregating metrics instead of emitting every single pool.waiting span could be a good direction. One question for you: do you prefer to merge the current changes as they are (so we can start getting value from |
- Use dd.trace.experimental.jdbc.pool.waiting.enabled=true to enable.
- Change instrumentation name from jdbc-datasource to jdbc.
- Record exceptions.
- Use default instrumentation name (jdbc).
- Set resource name to {dbcp2,hikari}.waiting
Also add PoolWaitingDecorator.
deejgregor
force-pushed
the
hikaricp-blocked-tracking
branch
from
a9a65c0 to
b5e714a
Compare
|
I just pushed updates that I think should address the first two items below.
Done.
Done.
Good news!
The more that I think of it, I've gotten to be pretty unconcerned about creating |
...rc/main/java/datadog/trace/instrumentation/jdbc/Dbcp2LinkedBlockingDequeInstrumentation.java
Outdated
Show resolved
Hide resolved
.../src/main/java/datadog/trace/instrumentation/jdbc/Dbcp2ManagedConnectionInstrumentation.java
Outdated
Show resolved
Hide resolved
.../main/java/datadog/trace/instrumentation/jdbc/Dbcp2PerUserPoolDataSourceInstrumentation.java
Outdated
Show resolved
Hide resolved
.../src/main/java/datadog/trace/instrumentation/jdbc/Dbcp2PoolingDataSourceInstrumentation.java
Outdated
Show resolved
Hide resolved
...jdbc/src/main/java/datadog/trace/instrumentation/jdbc/Dbcp2PoolingDriverInstrumentation.java
Outdated
Show resolved
Hide resolved
...c/main/java/datadog/trace/instrumentation/jdbc/Dbcp2SharedPoolDataSourceInstrumentation.java
Outdated
Show resolved
Hide resolved
...dbc/src/main/java/datadog/trace/instrumentation/jdbc/HikariConcurrentBagInstrumentation.java
Outdated
Show resolved
Hide resolved
| implements Instrumenter.ForSingleType, Instrumenter.HasMethodAdvice { | ||
|
|
||
| public HikariQueuedSequenceSynchronizerInstrumentation() { | ||
| super("jdbc-datasource"); |
There was a problem hiding this comment.
| super("jdbc-datasource"); | |
| super("jdbc-datasource", "hikari"); |
adding an alias will help in case we need to turn off this instrumentation without turning off all of JDBC
| public static class PollFirstAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static AgentSpan onEnter() { | ||
| if (CallDepthThreadLocalMap.getCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class) > 0) { |
There was a problem hiding this comment.
Since this advice bytecode will be lifted out and injected into the DBCP code it should only refer to types that are:
- on the boot-class-path (including those from
agent-bootstrap) - from the JDK
- from the library being instrumented
- injected as helpers
while referring to the surrounding instrumentation class will compile, it will cause issues to have injected bytecode attempt to link back to the original class (for one it will stop the instrumentation class-loader from unloading its classes after everything has been setup)
There was a problem hiding this comment.
Oh, excellent. Thank you! Will fix.
There was a problem hiding this comment.
The dbcp2 instrumentations target dbcp2 classes in two different packages, so I was thinking of chosing one of the helper classes added in this PR for CallDepthThreadLocalMap: either PoolWaitingDecorator or HikariBlockedTracker (I'd rename it to be PoolWaitingTracker, which I should probably do anyway). Does this approach sound good and do you have a preference on which class to use?
| public static class UpdateTransactionStatusAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static void onEnter() { | ||
| CallDepthThreadLocalMap.incrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
|
|
||
| @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) | ||
| public static void onExit() { | ||
| CallDepthThreadLocalMap.decrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
| public static class GetPooledConnectionAndInfoAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static void onEnter() { | ||
| CallDepthThreadLocalMap.incrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
|
|
||
| @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) | ||
| public static void onExit() { | ||
| CallDepthThreadLocalMap.decrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
| public static class GetConnectionAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static void onEnter() { | ||
| CallDepthThreadLocalMap.incrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
|
|
||
| @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) | ||
| public static void onExit() { | ||
| CallDepthThreadLocalMap.decrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
| public static class ConnectAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static void onEnter() { | ||
| CallDepthThreadLocalMap.incrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
|
|
||
| @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) | ||
| public static void onExit() { | ||
| CallDepthThreadLocalMap.decrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
| public static class GetPooledConnectionAndInfoAdvice { | ||
| @Advice.OnMethodEnter(suppress = Throwable.class) | ||
| public static void onEnter() { | ||
| CallDepthThreadLocalMap.incrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
|
|
||
| @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) | ||
| public static void onExit() { | ||
| CallDepthThreadLocalMap.decrementCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class); |
There was a problem hiding this comment.
As mentioned above, advice bytecode should not refer to its surrounding instrumentation class
| static void after(@Advice.This ConcurrentBag<?> thiz) | ||
| throws IllegalAccessException, NoSuchFieldException { | ||
| try { | ||
| Field handoffQueueField = thiz.getClass().getDeclaredField("handoffQueue"); |
There was a problem hiding this comment.
You could avoid reflection/setAccessible (which may stop working in future JDKs) by having a specific instrumentation for versions of Hikari with this field - to make sure the instrumentation only matched those versions you'd implement Instrumenter.WithTypeStructure and return return declaresField(named("handoffQueue"))
The advice could then use something like @Advice.FieldValue(value = "handoffQueue", readOnly = false) SynchronousQueue handoffQueue to access the field - to update it you'd just write to the handoffQueue argument and byte-buddy would translate that into setting the field.
There was a problem hiding this comment.
Thank you very much for the guidance--that will definitely be better.
| // ignore -- see HikariQueuedSequenceSynchronizerInstrumentation for older Hikari versions | ||
| } | ||
|
|
||
| Field hikariPoolField = thiz.getClass().getDeclaredField("listener"); |
There was a problem hiding this comment.
Consider using @Advice.FieldValue to access fields from method advice, rather than reflection.
|
Converting back to draft while I work on the changes suggested by @mcculls (thanks, again!). |
- Comment on the overall structure and highlight related instrumentations. - Avoid using reflection and breakup HikariConcurrentBagInstrumentation.ConstructorAdvice into separate, simpler instrumentations: HikariPoolInstrumentation and HikariConcurrentBagHandoffQueueInstrumentation. - Move HikariBlockedTrackingSynchronousQueue into HikariConcurrentBagHandoffQueueInstrumentation. - Make sure the instrumentationName is consistently "jdbc".
|
@mcculls I made the Hikari changes (minus the alias at this point) and was able to completely eliminate reflection in the process. I'm curious if you had any comments on the Hikari updates in 192f3f4. I also had two areas where I had some follow-up points for clarification. If you could take a look at these comments, that would be helpful, and then I can wrap everything else up. |
Thanks to @mcculls for pointing out the issue.
This would help if this feature becomes enabled it by default in the future, or if someone using this feature wanted to disable it for a particular pool library. Suggested during code review. Co-authored-by: Stuart McCulloch <[email protected]>
deejgregor
force-pushed
the
hikaricp-blocked-tracking
branch
from
553cf91 to
faf7ae1
Compare
|
This was merged in #9636 and will be available in v1.54.0 expected next week - thanks for the contribution! |
3 participants
What Does This Do
This adds a
pool.waitingspan when waiting for an available database connection from a Hikari (>= 2.4.0) or DBCP2 (>= 2.10.0) connection pool.This instrumentation is disabled by default. It is only enabled when JDBC instrumentation is enabled (which is the default) and
dd.trace.experimental.jdbc.pool.waiting.enabledis set to true (default is false). The aliases "dbcp2" and "hikari" are also added to allow control per pool implementation.Motivation
Additional Notes
Is this a contribution you would be interested in?
It would definitely be helpful to us at $WORK if this could be in the tracer, as we use connection pools heavily and delays due to exhausted connection pools tend to be not be quick to identify.
Instrumented Code
Hikari
There is a common method,
ConcurrentBag.borrow, that is used for both blocking and non-blocking paths. This method is instrumented along with deeper methods that indicate when the blocking path was taken. Depending on the Hikari version, there are two different downstream methods that are instrumented. AThreadLocalis used with the help ofHikariBlockedTrackerto communicate between the various instrumentations when the blocking path was taken. Apool.waitingspan is created whenConcurrentBag.borrowreturns, but only if blocking occurred.Implementation note
For modern versions of HIkari, the instrumentation to determine blocking in
HikariBlockedTrackingSynchronousQueuereplaces theSynchronousQueuecreated byConcurrentBag.<init>, and assumes thattrueis always passed when creating theSynchronousQueue. This sets the fairness policy and it has been set this way since 2017, so the likelihood of it changing in future versions of HIkari is very low.Apache DBCP2
In commons-pool >= 2.10.0 and later, this is straightforward, as
LinkedBlockingDeque.pollFirst(Duration)is called only in blocking cases byGenericObjectPool.borrowObjectfrom a number of places in dbcp2. ACallDepthThreadLocalMapis used to ensure a span is only created whenLinkedBlockingDeque.pollFirstis called from dbcp2 and a test method is added toJDBCInstrumentationTestBaseto ensure this is the case.This code can be extended to work with earlier versions of commons-pool, however determining the blocking signature of
poolFirstwill require a little bit more work and might require differentiating between versions of commons-pool to make sure only the appropriate signature is instrumented (or looking for another way to determine blocking).Test cases
A test method was added in
JDBCInstrumentationTestBase.Additional work
Although this seems to work functionally in with the included test, there are a few items still being worked on:
Contributor Checklist
type:and (comp:orinst:) labels in addition to any usefull labelsclose,fixor any linking keywords when referencing an issue.Use
solvesinstead, and assign the PR milestone to the issueJira ticket: [PROJ-IDENT]