Skip to content

Commit b5e714a

Browse files
deejgregordeejgregor
committed
Merge SaturatedPoolBlockingTest into JDBCInstrumentationTestBase
Also add PoolWaitingDecorator.
1 parent c033b74 commit b5e714a

File tree

5 files changed

+219
-168
lines changed

5 files changed

+219
-168
lines changed

‎dd-java-agent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/Dbcp2LinkedBlockingDequeInstrumentation.java‎

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@
22

33
import static datadog.trace.agent.tooling.bytebuddy.matcher.NameMatchers.named;
44
import static datadog.trace.bootstrap.instrumentation.api.AgentTracer.startSpan;
5+
import static datadog.trace.instrumentation.jdbc.PoolWaitingDecorator.DECORATE;
6+
import static datadog.trace.instrumentation.jdbc.PoolWaitingDecorator.POOL_WAITING;
57
import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
68

79
import com.google.auto.service.AutoService;
@@ -33,6 +35,11 @@ public String[] knownMatchingTypes() {
3335
};
3436
}
3537

38+
@Override
39+
public String[] helperClassNames() {
40+
return new String[] {packageName + ".PoolWaitingDecorator"};
41+
}
42+
3643
@Override
3744
public void methodAdvice(MethodTransformer transformer) {
3845
transformer.applyAdvice(
@@ -41,12 +48,11 @@ public void methodAdvice(MethodTransformer transformer) {
4148
}
4249

4350
public static class PollFirstAdvice {
44-
private static final String POOL_WAITING = "pool.waiting";
45-
4651
@Advice.OnMethodEnter(suppress = Throwable.class)
4752
public static AgentSpan onEnter() {
4853
if (CallDepthThreadLocalMap.getCallDepth(Dbcp2LinkedBlockingDequeInstrumentation.class) > 0) {
4954
AgentSpan span = startSpan(POOL_WAITING);
55+
DECORATE.afterStart(span);
5056
span.setResourceName("dbcp2.waiting");
5157
return span;
5258
} else {
@@ -58,9 +64,7 @@ public static AgentSpan onEnter() {
5864
public static void onExit(
5965
@Advice.Enter final AgentSpan span, @Advice.Thrown final Throwable throwable) {
6066
if (span != null) {
61-
if (throwable != null) {
62-
span.addThrowable(throwable);
63-
}
67+
DECORATE.onError(span, throwable);
6468
span.finish();
6569
}
6670
}

‎dd-java-agent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/HikariConcurrentBagInstrumentation.java‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33
import static datadog.trace.agent.tooling.bytebuddy.matcher.NameMatchers.named;
44
import static datadog.trace.bootstrap.instrumentation.api.AgentTracer.startSpan;
55
import static datadog.trace.bootstrap.instrumentation.api.Tags.DB_POOL_NAME;
6+
import static datadog.trace.instrumentation.jdbc.PoolWaitingDecorator.DECORATE;
7+
import static datadog.trace.instrumentation.jdbc.PoolWaitingDecorator.POOL_WAITING;
68
import static java.util.Collections.singletonMap;
79
import static net.bytebuddy.matcher.ElementMatchers.isConstructor;
810

@@ -44,7 +46,9 @@ public String instrumentedType() {
4446
@Override
4547
public String[] helperClassNames() {
4648
return new String[] {
47-
packageName + ".HikariBlockedTrackingSynchronousQueue", packageName + ".HikariBlockedTracker"
49+
packageName + ".HikariBlockedTrackingSynchronousQueue",
50+
packageName + ".HikariBlockedTracker",
51+
packageName + ".PoolWaitingDecorator"
4852
};
4953
}
5054

@@ -97,8 +101,6 @@ static void after(@Advice.This ConcurrentBag<?> thiz)
97101
}
98102

99103
public static class BorrowAdvice {
100-
private static final String POOL_WAITING = "pool.waiting";
101-
102104
@Advice.OnMethodEnter(suppress = Throwable.class)
103105
public static Long onEnter() {
104106
HikariBlockedTracker.clearBlocked();
@@ -113,10 +115,9 @@ public static void stopSpan(
113115
if (HikariBlockedTracker.wasBlocked()) {
114116
final AgentSpan span =
115117
startSpan(POOL_WAITING, TimeUnit.MILLISECONDS.toMicros(startTimeMillis));
118+
DECORATE.afterStart(span);
119+
DECORATE.onError(span, throwable);
116120
span.setResourceName("hikari.waiting");
117-
if (throwable != null) {
118-
span.addThrowable(throwable);
119-
}
120121
final String poolName =
121122
InstrumentationContext.get(ConcurrentBag.class, String.class).get(thiz);
122123
if (poolName != null) {

‎dd-java-agent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/PoolWaitingDecorator.java‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
package datadog.trace.instrumentation.jdbc;
2+
3+
import datadog.trace.bootstrap.instrumentation.api.UTF8BytesString;
4+
import datadog.trace.bootstrap.instrumentation.decorator.BaseDecorator;
5+
6+
public class PoolWaitingDecorator extends BaseDecorator {
7+
public static final CharSequence POOL_WAITING = UTF8BytesString.create("pool.waiting");
8+
public static final CharSequence JAVA_JDBC_POOL_WAITING =
9+
UTF8BytesString.create("java-jdbc-pool-waiting");
10+
11+
public static final PoolWaitingDecorator DECORATE = new PoolWaitingDecorator();
12+
13+
@Override
14+
protected String[] instrumentationNames() {
15+
return new String[] {"jdbc"};
16+
}
17+
18+
@Override
19+
protected CharSequence component() {
20+
return JAVA_JDBC_POOL_WAITING;
21+
}
22+
23+
@Override
24+
protected CharSequence spanType() {
25+
return null;
26+
}
27+
}

‎dd-java-agent/instrumentation/jdbc/src/test/groovy/JDBCInstrumentationTestBase.groovy‎

Lines changed: 176 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,11 @@ import datadog.trace.api.Config
66
import datadog.trace.api.DDSpanTypes
77
import datadog.trace.bootstrap.instrumentation.api.InstrumentationTags
88
import datadog.trace.bootstrap.instrumentation.api.Tags
9+
import org.apache.commons.dbcp2.BasicDataSource
10+
import org.apache.commons.pool2.PooledObject
11+
import org.apache.commons.pool2.PooledObjectFactory
12+
import org.apache.commons.pool2.impl.DefaultPooledObject
13+
import org.apache.commons.pool2.impl.GenericObjectPool
914
import org.apache.derby.jdbc.EmbeddedDataSource
1015
import org.h2.jdbcx.JdbcDataSource
1116
import spock.lang.Shared
@@ -18,11 +23,16 @@ import java.sql.Connection
1823
import java.sql.Driver
1924
import java.sql.PreparedStatement
2025
import java.sql.ResultSet
26+
import java.sql.SQLException
27+
import java.sql.SQLTimeoutException
28+
import java.sql.SQLTransientConnectionException
2129
import java.sql.Statement
30+
import java.time.Duration
2231

2332
import static datadog.trace.agent.test.utils.TraceUtils.basicSpan
2433
import static datadog.trace.agent.test.utils.TraceUtils.runUnderTrace
2534
import static datadog.trace.api.config.TraceInstrumentationConfig.DB_CLIENT_HOST_SPLIT_BY_INSTANCE
35+
import static datadog.trace.api.config.TraceInstrumentationConfig.JDBC_POOL_WAITING_ENABLED
2636

2737
abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
2838

@@ -97,6 +107,22 @@ abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
97107
return ds
98108
}
99109

110+
def createDbcp2DS(String dbType, String jdbcUrl) {
111+
BasicDataSource ds = new BasicDataSource()
112+
def jdbcUrlToSet = dbType == "derby" ? jdbcUrl + ";create=true" : jdbcUrl
113+
ds.setUrl(jdbcUrlToSet)
114+
ds.setDriverClassName(jdbcDriverClassNames.get(dbType))
115+
String username = jdbcUserNames.get(dbType)
116+
if (username != null) {
117+
ds.setUsername(username)
118+
}
119+
ds.setPassword(jdbcPasswords.get(dbType))
120+
ds.setMaxTotal(1) // to test proper caching, having > 1 max active connection will be hard to
121+
// determine whether the connection is properly cached
122+
ds.setMaxWait(Duration.ofMillis(1000))
123+
return ds
124+
}
125+
100126
def createHikariDS(String dbType, String jdbcUrl) {
101127
HikariConfig config = new HikariConfig()
102128
def jdbcUrlToSet = dbType == "derby" ? jdbcUrl + ";create=true" : jdbcUrl
@@ -110,6 +136,7 @@ abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
110136
config.addDataSourceProperty("prepStmtCacheSize", "250")
111137
config.addDataSourceProperty("prepStmtCacheSqlLimit", "2048")
112138
config.setMaximumPoolSize(1)
139+
config.setConnectionTimeout(1000)
113140

114141
return new HikariDataSource(config)
115142
}
@@ -133,6 +160,9 @@ abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
133160
if (connectionPoolName == "tomcat") {
134161
ds = createTomcatDS(dbType, jdbcUrl)
135162
}
163+
if (connectionPoolName == "dbcp2") {
164+
ds = createDbcp2DS(dbType, jdbcUrl)
165+
}
136166
if (connectionPoolName == "hikari") {
137167
ds = createHikariDS(dbType, jdbcUrl)
138168
}
@@ -148,6 +178,7 @@ abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
148178

149179
injectSysConfig("dd.trace.jdbc.prepared.statement.class.name", "test.TestPreparedStatement")
150180
injectSysConfig("dd.integration.jdbc-datasource.enabled", "true")
181+
injectSysConfig(JDBC_POOL_WAITING_ENABLED, "true")
151182
}
152183

153184
def setupSpec() {
@@ -814,6 +845,151 @@ abstract class JDBCInstrumentationTest extends VersionedNamingTestBase {
814845
"c3p0" | _
815846
}
816847
848+
def "#connectionPoolName should have pool.waiting span when pool exhausted for #exhaustPoolForMillis with exception thrown #expectException"() {
849+
setup:
850+
String dbType = "hsqldb"
851+
DataSource ds = createDS(connectionPoolName, dbType, jdbcUrls.get(dbType))
852+
853+
if (exhaustPoolForMillis != null) {
854+
def saturatedConnection = ds.getConnection()
855+
new Thread(() -> {
856+
Thread.sleep(exhaustPoolForMillis)
857+
saturatedConnection.close()
858+
}, "saturated connection closer").start()
859+
}
860+
861+
when:
862+
Throwable timedOutException = null
863+
runUnderTrace("parent") {
864+
try {
865+
ds.getConnection().close()
866+
} catch (SQLTransientConnectionException e) {
867+
if (e.getMessage().contains("request timed out after")) {
868+
// Hikari, newer
869+
timedOutException = e
870+
} else {
871+
throw e
872+
}
873+
} catch (SQLTimeoutException e) {
874+
// Hikari, older
875+
timedOutException = e
876+
} catch (SQLException e) {
877+
if (e.getMessage().contains("pool error Timeout waiting for idle object")) {
878+
// dbcp2
879+
timedOutException = e
880+
} else {
881+
throw e
882+
}
883+
}
884+
}
885+
886+
then:
887+
assertTraces(1) {
888+
trace(connectionPoolName == "dbcp2" ? 4 : 3) {
889+
basicSpan(it, "parent")
890+
891+
span {
892+
operationName "database.connection"
893+
resourceName "${ds.class.simpleName}.getConnection"
894+
childOf span(0)
895+
errored timedOutException != null
896+
tags {
897+
"$Tags.COMPONENT" "java-jdbc-connection"
898+
defaultTagsNoPeerService()
899+
if (timedOutException) {
900+
errorTags(timedOutException)
901+
}
902+
}
903+
}
904+
905+
// dbcp2 will have two database.connection spans
906+
if (connectionPoolName == "dbcp2") {
907+
span {
908+
operationName "database.connection"
909+
resourceName "PoolingDataSource.getConnection"
910+
childOf span(1)
911+
errored timedOutException != null
912+
tags {
913+
"$Tags.COMPONENT" "java-jdbc-connection"
914+
defaultTagsNoPeerService()
915+
if (timedOutException) {
916+
errorTags(timedOutException)
917+
}
918+
}
919+
}
920+
}
921+
922+
span {
923+
operationName "pool.waiting"
924+
resourceName "${connectionPoolName}.waiting"
925+
childOf span(connectionPoolName == "dbcp2" ? 2 : 1)
926+
tags {
927+
"$Tags.COMPONENT" "java-jdbc-pool-waiting"
928+
if (connectionPoolName == "hikari") {
929+
"$Tags.DB_POOL_NAME" String
930+
}
931+
defaultTagsNoPeerService()
932+
}
933+
}
934+
}
935+
}
936+
assert expectException == (timedOutException != null)
937+
938+
cleanup:
939+
if (ds instanceof Closeable) {
940+
ds.close()
941+
}
942+
943+
where:
944+
connectionPoolName | exhaustPoolForMillis | expectException
945+
"hikari" | 500 | false
946+
"dbcp2" | 500 | false
947+
"hikari" | 1500 | true
948+
"dbcp2" | 1500 | true
949+
}
950+
951+
def "Ensure LinkedBlockingDeque.pollFirst called outside of DBCP2 does not create spans"() {
952+
setup:
953+
def pool = new GenericObjectPool<>(new PooledObjectFactory() {
954+
955+
@Override
956+
void activateObject(PooledObject p) throws Exception {
957+
}
958+
959+
@Override
960+
void destroyObject(PooledObject p) throws Exception {
961+
}
962+
963+
@Override
964+
PooledObject makeObject() throws Exception {
965+
return new DefaultPooledObject(new Object())
966+
}
967+
968+
@Override
969+
void passivateObject(PooledObject p) throws Exception {
970+
}
971+
972+
@Override
973+
boolean validateObject(PooledObject p) {
974+
return false
975+
}
976+
})
977+
pool.setMaxTotal(1)
978+
979+
when:
980+
def exhaustPoolForMillis = 500
981+
def saturatedConnection = pool.borrowObject()
982+
new Thread(() -> {
983+
Thread.sleep(exhaustPoolForMillis)
984+
pool.returnObject(saturatedConnection)
985+
}, "saturated connection closer").start()
986+
987+
pool.borrowObject(1000)
988+
989+
then:
990+
TEST_WRITER.size() == 0
991+
}
992+
817993
Driver driverFor(String db) {
818994
return newDriver(jdbcDriverClassNames.get(db))
819995
}

0 commit comments

Comments
 (0)