Append DBM trace context comments for SQL Server & Postgres by jmeunier28 · Pull Request #6214 · DataDog/dd-trace-java

jmeunier28 · 2023-11-14T19:57:22Z

What Does This Do

Fix for reported customer issue around calling procedures for postgresql while having DBM-APM link enabled

2023-11-10 13:30:52.870 [Thread-66184] [Error] [modifyJdbcCall] [api_call_unique_identifier-2026618091699623052870] [Client_Id-0] [span_id-99074af426ba7b60ccc2] - com.paymentology.payapi.v1.logging.ApiLogger
Malformed function or procedure escape syntax at offset 40.

org.postgresql.util.PSQLException: Malformed function or procedure escape syntax at offset 40.
at org.postgresql.core.Parser.modifyJdbcCall(Parser.java:1146)
at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:48)
at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:19)
at org.postgresql.util.LruCache.borrow(LruCache.java:123)
at org.postgresql.core.QueryExecutorBase.borrowCallableQuery(QueryExecutorBase.java:301)
at org.postgresql.jdbc.PgConnection.borrowCallableQuery(PgConnection.java:200)
at org.postgresql.jdbc.PgCallableStatement.<init>(PgCallableStatement.java:54)
at org.postgresql.jdbc.PgConnection.prepareCall(PgConnection.java:1333)
at org.postgresql.jdbc.PgConnection.prepareCall(PgConnection.java:1786)
at org.postgresql.jdbc.PgConnection.prepareCall(PgConnection.java:459)
at com.zaxxer.hikari.pool.ProxyConnection.prepareCall(ProxyConnection.java:295)
at com.zaxxer.hikari.pool.HikariProxyConnection.prepareCall(HikariProxyConnection.java)
at com.paymentology.payapi.v1.logging.ApiLogger.lambda$SaveError$7(ApiLogger.java:320)
at java.lang.Thread.run(Thread.java:750)

This happens when running prepared callable statements. E.g. This code:

          final String storedProcedureCall = "{call dogshelterProc(?, ?)}";
          CallableStatement callableStmt = con.prepareCall(storedProcedureCall);

... results in the following exception

exception running jdbc ERROR: syntax error at or near "{"
  Position: 95

When being run from our test application with the latest release of the java tracer. By moving comments to be appended, instead of prepended, I no longer see this exception being thrown. Things are therefore correctly instrumented as a result. Note, we should not append comments for MySQL driver classes, since this actually causes an exception to be thrown when calling the similar procedure code.**

pr-commenter · 2023-11-14T20:41:33Z

Benchmarks

Startup

Parameters

	Baseline	Candidate
baseline_or_candidate	baseline	candidate
git_branch	master	jmeunier/DBMON-3123-two
git_commit_date	1701730732	1701739250
git_commit_sha	`d1eda60`	`e93bf34`
release_version	1.25.0-SNAPSHOT~d1eda60b66	1.25.0-SNAPSHOT~e93bf34330

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
ci_job_date	1701741937	1701741937
ci_job_id	381281891	381281891
ci_pipeline_id	24289102	24289102
cpu_model	Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz	Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz
module	Agent	Agent
parent	None	None
variant	iast	iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 44 metrics, 10 unstable metrics.

Startup time reports for petclinic

gantt
    title petclinic - global startup overhead: candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.048 s) : 0, 1047802
Total [baseline] (9.336 s) : 0, 9335717
Agent [candidate] (1.043 s) : 0, 1042583
Total [candidate] (9.418 s) : 0, 9417778
section appsec
Agent [baseline] (1.13 s) : 0, 1130266
Total [baseline] (9.49 s) : 0, 9490443
Agent [candidate] (1.122 s) : 0, 1121905
Total [candidate] (9.415 s) : 0, 9415221
section iast
Agent [baseline] (1.159 s) : 0, 1158586
Total [baseline] (9.568 s) : 0, 9568274
Agent [candidate] (1.157 s) : 0, 1157117
Total [candidate] (9.491 s) : 0, 9491399
section profiling
Agent [baseline] (1.232 s) : 0, 1231796
Total [baseline] (9.652 s) : 0, 9651688
Agent [candidate] (1.224 s) : 0, 1224227
Total [candidate] (9.641 s) : 0, 9641240

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.048 s	-
Agent	appsec	1.13 s	82.464 ms (7.9%)
Agent	iast	1.159 s	110.784 ms (10.6%)
Agent	profiling	1.232 s	183.994 ms (17.6%)
Total	tracing	9.336 s	-
Total	appsec	9.49 s	154.726 ms (1.7%)
Total	iast	9.568 s	232.557 ms (2.5%)
Total	profiling	9.652 s	315.971 ms (3.4%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.043 s	-
Agent	appsec	1.122 s	79.322 ms (7.6%)
Agent	iast	1.157 s	114.534 ms (11.0%)
Agent	profiling	1.224 s	181.644 ms (17.4%)
Total	tracing	9.418 s	-
Total	appsec	9.415 s	-2.557 ms (-0.0%)
Total	iast	9.491 s	73.62 ms (0.8%)
Total	profiling	9.641 s	223.461 ms (2.4%)

gantt
    title petclinic - break down per module: candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (649.062 ms) : 0, 649062
BytebuddyAgent [candidate] (649.514 ms) : 0, 649514
GlobalTracer [baseline] (307.934 ms) : 0, 307934
GlobalTracer [candidate] (301.779 ms) : 0, 301779
AppSec [baseline] (48.524 ms) : 0, 48524
AppSec [candidate] (48.91 ms) : 0, 48910
Remote Config [baseline] (681.988 µs) : 0, 682
Remote Config [candidate] (702.431 µs) : 0, 702
Telemetry [baseline] (7.179 ms) : 0, 7179
Telemetry [candidate] (7.293 ms) : 0, 7293
section appsec
BytebuddyAgent [baseline] (644.385 ms) : 0, 644385
BytebuddyAgent [candidate] (645.236 ms) : 0, 645236
GlobalTracer [baseline] (305.694 ms) : 0, 305694
GlobalTracer [candidate] (298.526 ms) : 0, 298526
AppSec [baseline] (136.699 ms) : 0, 136699
AppSec [candidate] (136.503 ms) : 0, 136503
Remote Config [baseline] (638.791 µs) : 0, 639
Remote Config [candidate] (642.928 µs) : 0, 643
Telemetry [baseline] (8.658 ms) : 0, 8658
Telemetry [candidate] (6.856 ms) : 0, 6856
section iast
BytebuddyAgent [baseline] (765.213 ms) : 0, 765213
BytebuddyAgent [candidate] (770.106 ms) : 0, 770106
GlobalTracer [baseline] (284.967 ms) : 0, 284967
GlobalTracer [candidate] (278.585 ms) : 0, 278585
AppSec [baseline] (46.067 ms) : 0, 46067
AppSec [candidate] (48.56 ms) : 0, 48560
IAST [baseline] (20.092 ms) : 0, 20092
IAST [candidate] (16.847 ms) : 0, 16847
Remote Config [baseline] (622.612 µs) : 0, 623
Remote Config [candidate] (574.487 µs) : 0, 574
Telemetry [baseline] (7.318 ms) : 0, 7318
Telemetry [candidate] (7.876 ms) : 0, 7876
section profiling
BytebuddyAgent [baseline] (654.996 ms) : 0, 654996
BytebuddyAgent [candidate] (655.906 ms) : 0, 655906
GlobalTracer [baseline] (376.793 ms) : 0, 376793
GlobalTracer [candidate] (369.357 ms) : 0, 369357
AppSec [baseline] (48.758 ms) : 0, 48758
AppSec [candidate] (48.628 ms) : 0, 48628
Remote Config [baseline] (686.356 µs) : 0, 686
Remote Config [candidate] (717.246 µs) : 0, 717
Telemetry [baseline] (7.375 ms) : 0, 7375
Telemetry [candidate] (7.394 ms) : 0, 7394
ProfilingAgent [baseline] (89.138 ms) : 0, 89138
ProfilingAgent [candidate] (88.097 ms) : 0, 88097
Profiling [baseline] (89.165 ms) : 0, 89165
Profiling [candidate] (88.12 ms) : 0, 88120

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.052 s) : 0, 1052308
Total [baseline] (8.773 s) : 0, 8773149
Agent [candidate] (1.033 s) : 0, 1032729
Total [candidate] (8.717 s) : 0, 8716610
section iast
Agent [baseline] (1.17 s) : 0, 1169944
Total [baseline] (9.282 s) : 0, 9281564
Agent [candidate] (1.154 s) : 0, 1154294
Total [candidate] (9.239 s) : 0, 9238894
section iast_TELEMETRY_OFF
Agent [baseline] (1.156 s) : 0, 1155744
Total [baseline] (9.236 s) : 0, 9236307
Agent [candidate] (1.145 s) : 0, 1144855
Total [candidate] (9.223 s) : 0, 9222563

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.052 s	-
Agent	iast	1.17 s	117.636 ms (11.2%)
Agent	iast_TELEMETRY_OFF	1.156 s	103.435 ms (9.8%)
Total	tracing	8.773 s	-
Total	iast	9.282 s	508.416 ms (5.8%)
Total	iast_TELEMETRY_OFF	9.236 s	463.158 ms (5.3%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.033 s	-
Agent	iast	1.154 s	121.565 ms (11.8%)
Agent	iast_TELEMETRY_OFF	1.145 s	112.126 ms (10.9%)
Total	tracing	8.717 s	-
Total	iast	9.239 s	522.284 ms (6.0%)
Total	iast_TELEMETRY_OFF	9.223 s	505.953 ms (5.8%)

gantt
    title insecure-bank - break down per module: candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (651.876 ms) : 0, 651876
BytebuddyAgent [candidate] (644.178 ms) : 0, 644178
GlobalTracer [baseline] (309.239 ms) : 0, 309239
GlobalTracer [candidate] (297.782 ms) : 0, 297782
AppSec [baseline] (48.673 ms) : 0, 48673
AppSec [candidate] (48.51 ms) : 0, 48510
Remote Config [baseline] (680.849 µs) : 0, 681
Remote Config [candidate] (683.178 µs) : 0, 683
Telemetry [baseline] (7.168 ms) : 0, 7168
Telemetry [candidate] (7.323 ms) : 0, 7323
section iast
BytebuddyAgent [baseline] (772.711 ms) : 0, 772711
BytebuddyAgent [candidate] (766.375 ms) : 0, 766375
GlobalTracer [baseline] (286.7 ms) : 0, 286700
GlobalTracer [candidate] (279.181 ms) : 0, 279181
AppSec [baseline] (46.661 ms) : 0, 46661
AppSec [candidate] (47.249 ms) : 0, 47249
IAST [baseline] (21.13 ms) : 0, 21130
IAST [candidate] (16.996 ms) : 0, 16996
Remote Config [baseline] (603.499 µs) : 0, 603
Remote Config [candidate] (583.315 µs) : 0, 583
Telemetry [baseline] (7.389 ms) : 0, 7389
Telemetry [candidate] (9.535 ms) : 0, 9535
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (762.428 ms) : 0, 762428
BytebuddyAgent [candidate] (758.792 ms) : 0, 758792
GlobalTracer [baseline] (285.097 ms) : 0, 285097
GlobalTracer [candidate] (278.631 ms) : 0, 278631
AppSec [baseline] (48.454 ms) : 0, 48454
AppSec [candidate] (51.737 ms) : 0, 51737
IAST [baseline] (18.113 ms) : 0, 18113
IAST [candidate] (14.455 ms) : 0, 14455
Remote Config [baseline] (644.875 µs) : 0, 645
Remote Config [candidate] (562.262 µs) : 0, 562
Telemetry [baseline] (6.408 ms) : 0, 6408
Telemetry [candidate] (6.398 ms) : 0, 6398

Load

Parameters

	Baseline	Candidate
baseline_or_candidate	baseline	candidate
end_time	2023-12-05T01:44:50	2023-12-05T02:01:22
git_branch	master	jmeunier/DBMON-3123-two
git_commit_date	1701730732	1701739250
git_commit_sha	`d1eda60`	`e93bf34`
release_version	1.25.0-SNAPSHOT~d1eda60b66	1.25.0-SNAPSHOT~e93bf34330
start_time	2023-12-05T01:44:36	2023-12-05T02:01:09

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
ci_job_date	1701741937	1701741937
ci_job_id	381281891	381281891
ci_pipeline_id	24289102	24289102
cpu_model	Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz	Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz
variant	iast	iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 9 metrics, 13 unstable metrics.

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.367 ms) : 1347, 1386
.   : milestone, 1367,
appsec (1.747 ms) : 1723, 1772
.   : milestone, 1747,
iast (1.524 ms) : 1500, 1548
.   : milestone, 1524,
profiling (1.525 ms) : 1500, 1551
.   : milestone, 1525,
tracing (1.496 ms) : 1472, 1521
.   : milestone, 1496,
section candidate
no_agent (1.362 ms) : 1343, 1381
.   : milestone, 1362,
appsec (1.776 ms) : 1750, 1801
.   : milestone, 1776,
iast (1.557 ms) : 1533, 1581
.   : milestone, 1557,
profiling (1.514 ms) : 1489, 1540
.   : milestone, 1514,
tracing (1.517 ms) : 1492, 1542
.   : milestone, 1517,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.367 ms [1.347 ms, 1.386 ms]	-
appsec	1.747 ms [1.723 ms, 1.772 ms]	380.595 µs (27.8%)
iast	1.524 ms [1.5 ms, 1.548 ms]	156.906 µs (11.5%)
profiling	1.525 ms [1.5 ms, 1.551 ms]	158.558 µs (11.6%)
tracing	1.496 ms [1.472 ms, 1.521 ms]	129.265 µs (9.5%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.362 ms [1.343 ms, 1.381 ms]	-
appsec	1.776 ms [1.75 ms, 1.801 ms]	413.979 µs (30.4%)
iast	1.557 ms [1.533 ms, 1.581 ms]	195.351 µs (14.3%)
profiling	1.514 ms [1.489 ms, 1.54 ms]	152.34 µs (11.2%)
tracing	1.517 ms [1.492 ms, 1.542 ms]	155.253 µs (11.4%)

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.25.0-SNAPSHOT~e93bf34330, baseline=1.25.0-SNAPSHOT~d1eda60b66
    dateFormat X
    axisFormat %s
section baseline
no_agent (370.944 µs) : 351, 391
.   : milestone, 371,
iast (479.314 µs) : 458, 500
.   : milestone, 479,
iast_FULL (537.395 µs) : 517, 558
.   : milestone, 537,
iast_INACTIVE (453.481 µs) : 433, 474
.   : milestone, 453,
iast_TELEMETRY_OFF (470.017 µs) : 449, 491
.   : milestone, 470,
tracing (441.58 µs) : 421, 462
.   : milestone, 442,
section candidate
no_agent (374.093 µs) : 354, 394
.   : milestone, 374,
iast (477.094 µs) : 457, 498
.   : milestone, 477,
iast_FULL (541.583 µs) : 521, 562
.   : milestone, 542,
iast_INACTIVE (455.357 µs) : 434, 477
.   : milestone, 455,
iast_TELEMETRY_OFF (468.188 µs) : 448, 488
.   : milestone, 468,
tracing (440.804 µs) : 420, 461
.   : milestone, 441,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	370.944 µs [350.654 µs, 391.233 µs]	-
iast	479.314 µs [458.441 µs, 500.188 µs]	108.371 µs (29.2%)
iast_FULL	537.395 µs [516.889 µs, 557.9 µs]	166.451 µs (44.9%)
iast_INACTIVE	453.481 µs [432.64 µs, 474.321 µs]	82.537 µs (22.3%)
iast_TELEMETRY_OFF	470.017 µs [449.166 µs, 490.869 µs]	99.073 µs (26.7%)
tracing	441.58 µs [421.32 µs, 461.839 µs]	70.636 µs (19.0%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	374.093 µs [353.798 µs, 394.387 µs]	-
iast	477.094 µs [456.535 µs, 497.653 µs]	103.001 µs (27.5%)
iast_FULL	541.583 µs [521.091 µs, 562.075 µs]	167.49 µs (44.8%)
iast_INACTIVE	455.357 µs [433.904 µs, 476.809 µs]	81.264 µs (21.7%)
iast_TELEMETRY_OFF	468.188 µs [447.93 µs, 488.447 µs]	94.096 µs (25.2%)
tracing	440.804 µs [420.312 µs, 461.296 µs]	66.711 µs (17.8%)

bantonsson · 2023-12-12T08:43:37Z

-    "com.microsoft.sqlserver.jdbc.SQLServerConnection",
-    // jtds (for SQL Server and Sybase)
-    "net.sourceforge.jtds.jdbc.ConnectionJDBC2", // 1.2
-    "net.sourceforge.jtds.jdbc.JtdsConnection", // 1.3


Had to read this twice to see that these were append before and are append now after the move. A quick comment in the PR would have been helpful.

yeah sorry, I tried to make that clear in the title of the PR but I can update the description as well

No worries. Sometimes it's easier to add a comment yourself in the PR instead of trying to explain everything in the PR description.

jmeunier28 mentioned this pull request Nov 14, 2023

Append DBM trace context comments for SQL Server & Postgres #6208

Closed

Append DBM trace context comments for SQL Server & Postgres

024fdbc

jmeunier28 force-pushed the jmeunier/DBMON-3123-two branch from 92c05b0 to 024fdbc Compare December 5, 2023 01:14

update class comments

e93bf34

jmeunier28 marked this pull request as ready for review December 11, 2023 19:56

jmeunier28 requested a review from a team as a code owner December 11, 2023 19:56

jmeunier28 requested review from dougqh and ygree December 11, 2023 19:56

bantonsson approved these changes Dec 12, 2023

View reviewed changes

jmeunier28 merged commit 1992baf into master Dec 12, 2023

jmeunier28 deleted the jmeunier/DBMON-3123-two branch December 12, 2023 14:37

github-actions Bot added this to the 1.26.0 milestone Dec 12, 2023

nikita-tkachenko-datadog added the comp: database Database Monitoring label Dec 19, 2023

bantonsson added the type: bug fix Bug fix label Dec 22, 2023

jmeunier28 mentioned this pull request Feb 28, 2024

Don't inject comment for callable JDBC statements #6743

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Append DBM trace context comments for SQL Server & Postgres#6214

Append DBM trace context comments for SQL Server & Postgres#6214
jmeunier28 merged 2 commits into
masterfrom
jmeunier/DBMON-3123-two

jmeunier28 commented Nov 14, 2023 •

edited

Loading

Uh oh!

pr-commenter Bot commented Nov 14, 2023 •

edited

Loading

Uh oh!

bantonsson Dec 12, 2023 •

edited

Loading

Uh oh!

jmeunier28 Dec 12, 2023

Uh oh!

bantonsson Dec 13, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

jmeunier28 commented Nov 14, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What Does This Do

Uh oh!

pr-commenter Bot commented Nov 14, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Benchmarks

Startup

Parameters

Summary

Load

Parameters

Summary

Uh oh!

bantonsson Dec 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jmeunier28 Dec 12, 2023

Choose a reason for hiding this comment

Uh oh!

bantonsson Dec 13, 2023

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

jmeunier28 commented Nov 14, 2023 •

edited

Loading

pr-commenter Bot commented Nov 14, 2023 •

edited

Loading

bantonsson Dec 12, 2023 •

edited

Loading