Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DBM-APM: Selectively pre/append sql comments depending on DBMS typeq #6160

Merged
merged 8 commits into from
Nov 8, 2023

Conversation

jmeunier28
Copy link
Contributor

What Does This Do

This PR updates the logic for the APM-DBM link feature introduced in #4847. It changes from prepending the sql comments, containing the APM trace context, to appending them to the raw sql for SQL Server driver implementations only. This requires no changes on the DBM side of things in either the agent or our backend.

Jira ticket: DBMON-2759

Motivation

This fixes an issue, which has been reported by several customers that executing CallableStatements with the following syntax causes exceptions to be thrown when enabling APM-DBM link:

The customer’s code base makes a CallableStatement statementvariable = connection.prepareCall("{call some_function_namehere(?,?,?) }";) and whenever both of these are active, the Java application starts throwing syntax error at or near "{" over and over.

We were able to reproduce this, using the latest version of the java tracer && an internal application. It seems to be caused by the SQL comments we inject being prepended instead of appended. For example, the issue of prepending the comment was reproduced with a simple java application (without APM-DBM link enabled), which did the following:

  final String storedProcedureCall = "/*test commnet*/ {call foo(?, ?)}";
  CallableStatement callableStmt = con.prepareCall(storedProcedureCall);
  callableStmt.setInt(1,10);
  callableStmt.setInt(2,11);
  callableStmt.execute();
  callableStmt.close(); 

... this throws the same exception with message Incorrect syntax near '{'.

Proof of Fix

After doing a custom build of this tracer code, we deployed our test app, which runs a combination of PreparedStatement/Statements/CallableStatement & no longer saw the Incorrect syntax near '{'. exception being thrown.

We were also able to confirm that injection is still working properly, e.g: our events are being properly decorated:

Screen Shot 2023-10-12 at 5 26 06 PM

Screen Shot 2023-10-12 at 5 26 15 PM

Expected DBM Behavior for Stored Procedures

Stored Procedures aren't supported for the APM-DBM usecase (unless the same app that is calling them is the thing that created the stored procedure & the linking was enabled). Otherwise, we wouldn't see the comments if someone had code that was simply calling EXEC proc or {call proc}, since the actual text we see in the activity code is either:

  1. The entire stored proc text e.g.:
CREATE PROCEDURE foo
BEGIN
-- do stuff
END;
  1. The currently executing query in the context of the stored proc

Neither, contains the text EXEC proc, which is what would have the comment injected via the tracer.

Obviously, this is of secondary concern here. Updating the tracer to append the comment will fix this edge case being reported by customers. We really don't want the feature to cause users to see exceptions being thrown in their production code.

@pr-commenter
Copy link

pr-commenter bot commented Nov 6, 2023

Benchmarks

Startup

Parameters

Baseline Candidate
commit 1.23.0-SNAPSHOT~67f30b8244 1.23.0-SNAPSHOT~edee3aa345
config baseline candidate
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
module Agent Agent
parent None None
variant iast iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 54 cases.

Startup time reports for insecure-bank
gantt
    title insecure-bank - global startup overhead: candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.04 s) : 0, 1039980
Total [baseline] (8.803 s) : 0, 8803457
Agent [candidate] (1.035 s) : 0, 1034851
Total [candidate] (8.765 s) : 0, 8764926
section iast
Agent [baseline] (1.153 s) : 0, 1153124
Total [baseline] (9.346 s) : 0, 9346034
Agent [candidate] (1.162 s) : 0, 1161587
Total [candidate] (9.344 s) : 0, 9344459
section iast_TELEMETRY_OFF
Agent [baseline] (1.148 s) : 0, 1147535
Total [baseline] (9.306 s) : 0, 9305989
Agent [candidate] (1.144 s) : 0, 1143676
Total [candidate] (9.364 s) : 0, 9363761
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.04 s -
Agent iast 1.153 s 113.144 ms (10.9%)
Agent iast_TELEMETRY_OFF 1.148 s 107.555 ms (10.3%)
Total tracing 8.803 s -
Total iast 9.346 s 542.578 ms (6.2%)
Total iast_TELEMETRY_OFF 9.306 s 502.532 ms (5.7%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.035 s -
Agent iast 1.162 s 126.737 ms (12.2%)
Agent iast_TELEMETRY_OFF 1.144 s 108.825 ms (10.5%)
Total tracing 8.765 s -
Total iast 9.344 s 579.533 ms (6.6%)
Total iast_TELEMETRY_OFF 9.364 s 598.834 ms (6.8%)
gantt
    title insecure-bank - break down per module: candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (649.047 ms) : 0, 649047
BytebuddyAgent [candidate] (645.447 ms) : 0, 645447
GlobalTracer [baseline] (295.231 ms) : 0, 295231
GlobalTracer [candidate] (293.958 ms) : 0, 293958
AppSec [baseline] (48.955 ms) : 0, 48955
AppSec [candidate] (49.075 ms) : 0, 49075
Remote Config [baseline] (700.664 µs) : 0, 701
Remote Config [candidate] (686.677 µs) : 0, 687
Telemetry [baseline] (11.362 ms) : 0, 11362
Telemetry [candidate] (11.351 ms) : 0, 11351
section iast
BytebuddyAgent [baseline] (765.515 ms) : 0, 765515
BytebuddyAgent [candidate] (771.871 ms) : 0, 771871
GlobalTracer [baseline] (275.529 ms) : 0, 275529
GlobalTracer [candidate] (277.506 ms) : 0, 277506
AppSec [baseline] (46.838 ms) : 0, 46838
AppSec [candidate] (47.343 ms) : 0, 47343
IAST [baseline] (18.343 ms) : 0, 18343
IAST [candidate] (15.601 ms) : 0, 15601
Remote Config [baseline] (581.95 µs) : 0, 582
Remote Config [candidate] (562.285 µs) : 0, 562
Telemetry [baseline] (11.905 ms) : 0, 11905
Telemetry [candidate] (13.984 ms) : 0, 13984
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (762.585 ms) : 0, 762585
BytebuddyAgent [candidate] (758.351 ms) : 0, 758351
GlobalTracer [baseline] (275.202 ms) : 0, 275202
GlobalTracer [candidate] (274.514 ms) : 0, 274514
AppSec [baseline] (46.806 ms) : 0, 46806
AppSec [candidate] (46.619 ms) : 0, 46619
IAST [baseline] (17.307 ms) : 0, 17307
IAST [candidate] (16.767 ms) : 0, 16767
Remote Config [baseline] (564.851 µs) : 0, 565
Remote Config [candidate] (563.096 µs) : 0, 563
Telemetry [baseline] (10.474 ms) : 0, 10474
Telemetry [candidate] (12.533 ms) : 0, 12533
Loading
Startup time reports for petclinic
gantt
    title petclinic - global startup overhead: candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.035 s) : 0, 1034803
Total [baseline] (9.315 s) : 0, 9314754
Agent [candidate] (1.036 s) : 0, 1036000
Total [candidate] (9.285 s) : 0, 9285151
section appsec
Agent [baseline] (1.126 s) : 0, 1126053
Total [baseline] (9.427 s) : 0, 9427175
Agent [candidate] (1.119 s) : 0, 1119047
Total [candidate] (9.36 s) : 0, 9360359
section iast
Agent [baseline] (1.147 s) : 0, 1146967
Total [baseline] (9.463 s) : 0, 9463353
Agent [candidate] (1.15 s) : 0, 1149571
Total [candidate] (9.476 s) : 0, 9475569
section profiling
Agent [baseline] (1.221 s) : 0, 1220980
Total [baseline] (9.521 s) : 0, 9521255
Agent [candidate] (1.22 s) : 0, 1219930
Total [candidate] (9.553 s) : 0, 9552857
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.035 s -
Agent appsec 1.126 s 91.25 ms (8.8%)
Agent iast 1.147 s 112.164 ms (10.8%)
Agent profiling 1.221 s 186.177 ms (18.0%)
Total tracing 9.315 s -
Total appsec 9.427 s 112.422 ms (1.2%)
Total iast 9.463 s 148.599 ms (1.6%)
Total profiling 9.521 s 206.501 ms (2.2%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.036 s -
Agent appsec 1.119 s 83.046 ms (8.0%)
Agent iast 1.15 s 113.57 ms (11.0%)
Agent profiling 1.22 s 183.93 ms (17.8%)
Total tracing 9.285 s -
Total appsec 9.36 s 75.208 ms (0.8%)
Total iast 9.476 s 190.418 ms (2.1%)
Total profiling 9.553 s 267.706 ms (2.9%)
gantt
    title petclinic - break down per module: candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (645.583 ms) : 0, 645583
BytebuddyAgent [candidate] (646.309 ms) : 0, 646309
GlobalTracer [baseline] (294.13 ms) : 0, 294130
GlobalTracer [candidate] (294.371 ms) : 0, 294371
AppSec [baseline] (48.806 ms) : 0, 48806
AppSec [candidate] (49.12 ms) : 0, 49120
Remote Config [baseline] (691.043 µs) : 0, 691
Remote Config [candidate] (691.226 µs) : 0, 691
Telemetry [baseline] (11.254 ms) : 0, 11254
Telemetry [candidate] (11.194 ms) : 0, 11194
section appsec
BytebuddyAgent [baseline] (649.482 ms) : 0, 649482
BytebuddyAgent [candidate] (645.862 ms) : 0, 645862
GlobalTracer [baseline] (295.609 ms) : 0, 295609
GlobalTracer [candidate] (293.749 ms) : 0, 293749
AppSec [baseline] (138.714 ms) : 0, 138714
AppSec [candidate] (137.572 ms) : 0, 137572
Remote Config [baseline] (651.762 µs) : 0, 652
Remote Config [candidate] (641.243 µs) : 0, 641
Telemetry [baseline] (6.927 ms) : 0, 6927
Telemetry [candidate] (6.83 ms) : 0, 6830
section iast
BytebuddyAgent [baseline] (763.618 ms) : 0, 763618
BytebuddyAgent [candidate] (765.263 ms) : 0, 765263
GlobalTracer [baseline] (274.015 ms) : 0, 274015
GlobalTracer [candidate] (274.402 ms) : 0, 274402
AppSec [baseline] (46.509 ms) : 0, 46509
AppSec [candidate] (46.791 ms) : 0, 46791
Remote Config [baseline] (567.557 µs) : 0, 568
Remote Config [candidate] (575.436 µs) : 0, 575
Telemetry [baseline] (10.557 ms) : 0, 10557
Telemetry [candidate] (11.243 ms) : 0, 11243
IAST [baseline] (17.352 ms) : 0, 17352
IAST [candidate] (16.951 ms) : 0, 16951
section profiling
BytebuddyAgent [baseline] (656.185 ms) : 0, 656185
BytebuddyAgent [candidate] (657.13 ms) : 0, 657130
GlobalTracer [baseline] (360.275 ms) : 0, 360275
GlobalTracer [candidate] (359.125 ms) : 0, 359125
AppSec [baseline] (49.623 ms) : 0, 49623
AppSec [candidate] (49.076 ms) : 0, 49076
Remote Config [baseline] (649.173 µs) : 0, 649
Remote Config [candidate] (662.625 µs) : 0, 663
Telemetry [baseline] (11.332 ms) : 0, 11332
Telemetry [candidate] (11.338 ms) : 0, 11338
ProfilingAgent [baseline] (88.637 ms) : 0, 88637
ProfilingAgent [candidate] (88.356 ms) : 0, 88356
Profiling [baseline] (88.66 ms) : 0, 88660
Profiling [candidate] (88.38 ms) : 0, 88380
Loading

Load

Parameters

Baseline Candidate
commit 1.23.0-SNAPSHOT~67f30b8244 1.23.0-SNAPSHOT~edee3aa345
config baseline candidate
end_time 2023-11-08T16:47:06 2023-11-08T17:03:33
start_time 2023-11-08T16:46:53 2023-11-08T17:03:20
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
variant iast iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 22 cases.

Request duration reports for insecure-bank
gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244
    dateFormat X
    axisFormat %s
section baseline
no_agent (361.711 µs) : 342, 382
.   : milestone, 362,
iast (469.502 µs) : 448, 491
.   : milestone, 470,
iast_FULL (525.743 µs) : 505, 546
.   : milestone, 526,
iast_INACTIVE (436.827 µs) : 416, 458
.   : milestone, 437,
iast_TELEMETRY_OFF (463.461 µs) : 443, 484
.   : milestone, 463,
tracing (438.097 µs) : 417, 460
.   : milestone, 438,
section candidate
no_agent (367.639 µs) : 347, 388
.   : milestone, 368,
iast (468.159 µs) : 447, 489
.   : milestone, 468,
iast_FULL (526.27 µs) : 506, 547
.   : milestone, 526,
iast_INACTIVE (436.846 µs) : 415, 459
.   : milestone, 437,
iast_TELEMETRY_OFF (455.605 µs) : 435, 477
.   : milestone, 456,
tracing (432.25 µs) : 411, 453
.   : milestone, 432,
Loading
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 361.711 µs [341.832 µs, 381.589 µs] -
iast 469.502 µs [448.311 µs, 490.693 µs] 107.792 µs (29.8%)
iast_FULL 525.743 µs [505.049 µs, 546.437 µs] 164.032 µs (45.3%)
iast_INACTIVE 436.827 µs [416.053 µs, 457.601 µs] 75.116 µs (20.8%)
iast_TELEMETRY_OFF 463.461 µs [442.695 µs, 484.228 µs] 101.751 µs (28.1%)
tracing 438.097 µs [416.581 µs, 459.614 µs] 76.386 µs (21.1%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 367.639 µs [347.138 µs, 388.14 µs] -
iast 468.159 µs [447.238 µs, 489.079 µs] 100.519 µs (27.3%)
iast_FULL 526.27 µs [505.788 µs, 546.752 µs] 158.631 µs (43.1%)
iast_INACTIVE 436.846 µs [415.16 µs, 458.532 µs] 69.207 µs (18.8%)
iast_TELEMETRY_OFF 455.605 µs [434.617 µs, 476.594 µs] 87.966 µs (23.9%)
tracing 432.25 µs [411.368 µs, 453.133 µs] 64.611 µs (17.6%)
Request duration reports for petclinic
gantt
    title petclinic - request duration [CI 0.99] : candidate=1.23.0-SNAPSHOT~edee3aa345, baseline=1.23.0-SNAPSHOT~67f30b8244
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.348 ms) : 1329, 1367
.   : milestone, 1348,
appsec (1.717 ms) : 1693, 1741
.   : milestone, 1717,
iast (1.483 ms) : 1459, 1506
.   : milestone, 1483,
profiling (1.465 ms) : 1440, 1491
.   : milestone, 1465,
tracing (1.445 ms) : 1420, 1470
.   : milestone, 1445,
section candidate
no_agent (1.347 ms) : 1328, 1366
.   : milestone, 1347,
appsec (1.71 ms) : 1685, 1736
.   : milestone, 1710,
iast (1.456 ms) : 1431, 1480
.   : milestone, 1456,
profiling (1.487 ms) : 1461, 1513
.   : milestone, 1487,
tracing (1.464 ms) : 1440, 1489
.   : milestone, 1464,
Loading
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.348 ms [1.329 ms, 1.367 ms] -
appsec 1.717 ms [1.693 ms, 1.741 ms] 369.03 µs (27.4%)
iast 1.483 ms [1.459 ms, 1.506 ms] 134.693 µs (10.0%)
profiling 1.465 ms [1.44 ms, 1.491 ms] 117.222 µs (8.7%)
tracing 1.445 ms [1.42 ms, 1.47 ms] 97.135 µs (7.2%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.347 ms [1.328 ms, 1.366 ms] -
appsec 1.71 ms [1.685 ms, 1.736 ms] 363.658 µs (27.0%)
iast 1.456 ms [1.431 ms, 1.48 ms] 108.866 µs (8.1%)
profiling 1.487 ms [1.461 ms, 1.513 ms] 139.983 µs (10.4%)
tracing 1.464 ms [1.44 ms, 1.489 ms] 117.454 µs (8.7%)

@@ -73,6 +73,8 @@ public DBMCompatibleConnectionInstrumentation() {
"com.informix.jdbc.IfmxConnection",
};

private static final String locationMode = "prepend";
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It probably makes more sense for this to be a boolean or an enum.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

boolean would be preferred in this case - avoids having to list all the enum classes as helpers

@@ -19,23 +19,28 @@ public class SQLCommenter {
private static final char EQUALS = '=';
private static final char COMMA = ',';
private static final char QUOTE = '\'';
private static final String OPEN_COMMENT_APPEND = " /*";
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are there two constants for OPEN_COMMENT & OPEN_COMMENT_APPEND?
I also see that there's a use of the string literal as "/*" in the code as well.

I think having 3 of same thing is making the code a bit harder to follow.

private static final int INITIAL_CAPACITY = computeInitialCapacity();
private static final String PREPEND = "prepend";
Copy link
Contributor

@dougqh dougqh Nov 7, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd replace these with an enum or a boolean for the two different modes.

sb.append(sql);
sb.append(OPEN_COMMENT_APPEND);
toComment(sb, injectTrace, parentService, dbService, env, version, traceParent);
if (sb.length() == OPEN_COMMENT_APPEND.length() + sql.length()) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It isn't immediately obvious to me what this check is doing.
I'm guessing that it is checking whether the comment was able to be injected, but it is hard to tell.

If that's the case, I'd prefer to see toComment return a boolean indicating success.
That would make the code flow easier to follow.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah sure, that makes sense

@@ -44,6 +49,16 @@ public static String inject(
final String version = config.getVersion();
final int commentSize = capacity(traceParent, parentService, dbService, env, version);
StringBuilder sb = new StringBuilder(sql.length() + commentSize);
if (locationMode.equals(APPEND)) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I'd prefer to see this as an if / else - rather than an if with an early return.
To me, that would make the code easier to understand.

"/*traceparent='00-00000000000000007fffffffffffffff-000000024cb016ea-01'*/ SELECT * FROM foo" | "SqlCommenter" | "Test" | "my-service" | "TestVersion" | false | null | "/*traceparent='00-00000000000000007fffffffffffffff-000000024cb016ea-01'*/ SELECT * FROM foo"
"/*customer-comment*/ SELECT * FROM foo" | "SqlCommenter" | "Test" | "my-service" | "TestVersion" | false | null | "/*ddps='SqlCommenter',dddbs='my-service',dde='Test',ddpv='TestVersion'*/ /*customer-comment*/ SELECT * FROM foo"
"/*traceparent" | "SqlCommenter" | "Test" | "my-service" | "TestVersion" | false | null | "/*ddps='SqlCommenter',dddbs='my-service',dde='Test',ddpv='TestVersion'*/ /*traceparent"
query | ddService | ddEnv | dbService | ddVersion | injectTrace | locationMode | traceParent | expected
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The diff is hard to read. Is there a test here that tests the edge case where the injection fails?

Copy link
Contributor

@dougqh dougqh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I find the logic hard to follow in places.
I'd like to see a bit of clean-up.

I also think the append vs prepend could be better handled with a boolean or an enum.

@@ -124,7 +127,7 @@ public static String onEnter(
final DBInfo dbInfo =
JDBCDecorator.parseDBInfo(
connection, InstrumentationContext.get(Connection.class, DBInfo.class));
sql = SQLCommenter.inject(sql, DECORATE.getDbService(dbInfo));
sql = SQLCommenter.inject(sql, DECORATE.getDbService(dbInfo), appendComment);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Have you considered providing two methods SQLCommenter.append and SQLCommenter.prepend which each just call SQLCommenter.inject with the appropriate boolean flag?

I think that would be much more self-documenting.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah that probably would be easier on the eyes. I'll update that now

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that was a nice improvement. Thanks for doing that.

private static final int INITIAL_CAPACITY = computeInitialCapacity();

public static String inject(final String sql, final String dbService) {
return inject(sql, dbService, null, false);
public static String append(final String sql, final String dbService) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the splitting of the functions.

@jmeunier28 jmeunier28 force-pushed the jmeunier/sql-server-apm-dbm-fix branch from edee3aa to 422977d Compare November 8, 2023 20:20
@jmeunier28
Copy link
Contributor Author

the test failures are unrelated to my PR && is fixed in here #6177

Going to merge this since we have confidence based on the relevant unit / system tests passing

@jmeunier28 jmeunier28 merged commit e01d702 into master Nov 8, 2023
65 of 69 checks passed
@jmeunier28 jmeunier28 deleted the jmeunier/sql-server-apm-dbm-fix branch November 8, 2023 23:15
@github-actions github-actions bot added this to the 1.23.0 milestone Nov 8, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants