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.

Sign up for GitHub

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

Jump to bottom

Add trace injection for prepared statements in Postgres #7940

Open
wants to merge 9 commits into
base: master
Choose a base branch
from
Open

Add trace injection for prepared statements in Postgres #7940

wants to merge 9 commits into from

Conversation

nenadnoveljic
Copy link
Contributor

@nenadnoveljic nenadnoveljic commented Nov 12, 2024 •
edited
Loading

What Does This Do

Adding trace injection for prepared statements in Postgres.

Motivation

90% of APM/DBM correlation attempts for Postgres involve prepared statements, but we can't retrieve execution plans for these. Injecting trace context into prepared statements will greatly improve the success rate.

Additional Notes

It's not possible to inject trace context into comments for prepared statements. Instead, the tracer sets the application_name with the trace parent, which the Agent samples via pg_stat_activity.application_name, and the backend parses.

Disadvantages:

  • Setting application_name requires an extra database round trip.
  • The original application_name is overwritten.

These drawbacks will be noted in the public documentation.

The feature is disabled by default and can be enabled by setting dd.dbm.trace_prepared_statements to true.

Contributor Checklist

Jira ticket: [PROJ-IDENT]

@pr-commenter
Copy link

pr-commenter bot commented Nov 12, 2024 •
edited
Loading

Benchmarks

Startup

Parameters

Baseline Candidate
baseline_or_candidate baseline candidate
git_branch master nenadnoveljic/pg-prepared
git_commit_date 1732111926 1732112078
git_commit_sha 270a82d f2f7b8f
release_version 1.43.0-SNAPSHOT~270a82d63a 1.43.0-SNAPSHOT~f2f7b8f01c
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
ci_job_date 1732114373 1732114373
ci_job_id 713828636 713828636
ci_pipeline_id 49498317 49498317
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 51 metrics, 12 unstable metrics.

Startup time reports for insecure-bank 
gantt
    title insecure-bank - global startup overhead: candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.101 s) : 0, 1100833
Total [baseline] (8.65 s) : 0, 8650359
Agent [candidate] (1.091 s) : 0, 1091369
Total [candidate] (8.659 s) : 0, 8659444
section iast
Agent [baseline] (1.227 s) : 0, 1227105
Total [baseline] (9.243 s) : 0, 9243060
Agent [candidate] (1.226 s) : 0, 1225703
Total [candidate] (9.284 s) : 0, 9284373
section iast_HARDCODED_SECRET_DISABLED
Agent [baseline] (1.231 s) : 0, 1231252
Total [baseline] (9.22 s) : 0, 9219774
Agent [candidate] (1.219 s) : 0, 1219352
Total [candidate] (9.224 s) : 0, 9223640
section iast_TELEMETRY_OFF
Agent [baseline] (1.215 s) : 0, 1215356
Total [baseline] (9.197 s) : 0, 9197239
Agent [candidate] (1.216 s) : 0, 1215562
Total [candidate] (9.199 s) : 0, 9199370
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.101 s -
Agent iast 1.227 s 126.272 ms (11.5%)
Agent iast_HARDCODED_SECRET_DISABLED 1.231 s 130.419 ms (11.8%)
Agent iast_TELEMETRY_OFF 1.215 s 114.523 ms (10.4%)
Total tracing 8.65 s -
Total iast 9.243 s 592.701 ms (6.9%)
Total iast_HARDCODED_SECRET_DISABLED 9.22 s 569.416 ms (6.6%)
Total iast_TELEMETRY_OFF 9.197 s 546.88 ms (6.3%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.091 s -
Agent iast 1.226 s 134.333 ms (12.3%)
Agent iast_HARDCODED_SECRET_DISABLED 1.219 s 127.983 ms (11.7%)
Agent iast_TELEMETRY_OFF 1.216 s 124.192 ms (11.4%)
Total tracing 8.659 s -
Total iast 9.284 s 624.93 ms (7.2%)
Total iast_HARDCODED_SECRET_DISABLED 9.224 s 564.196 ms (6.5%)
Total iast_TELEMETRY_OFF 9.199 s 539.926 ms (6.2%) 
gantt
    title insecure-bank - break down per module: candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (698.608 ms) : 0, 698608
BytebuddyAgent [candidate] (693.998 ms) : 0, 693998
GlobalTracer [baseline] (321.282 ms) : 0, 321282
GlobalTracer [candidate] (318.076 ms) : 0, 318076
AppSec [baseline] (55.0 ms) : 0, 55000
AppSec [candidate] (54.779 ms) : 0, 54779
Remote Config [baseline] (693.488 µs) : 0, 693
Remote Config [candidate] (702.259 µs) : 0, 702
Telemetry [baseline] (11.36 ms) : 0, 11360
Telemetry [candidate] (10.015 ms) : 0, 10015
section iast
BytebuddyAgent [baseline] (815.76 ms) : 0, 815760
BytebuddyAgent [candidate] (814.531 ms) : 0, 814531
GlobalTracer [baseline] (309.701 ms) : 0, 309701
GlobalTracer [candidate] (308.905 ms) : 0, 308905
AppSec [baseline] (56.739 ms) : 0, 56739
AppSec [candidate] (58.006 ms) : 0, 58006
Remote Config [baseline] (622.271 µs) : 0, 622
Remote Config [candidate] (644.695 µs) : 0, 645
Telemetry [baseline] (7.573 ms) : 0, 7573
Telemetry [candidate] (7.632 ms) : 0, 7632
IAST [baseline] (22.822 ms) : 0, 22822
IAST [candidate] (22.118 ms) : 0, 22118
section iast_HARDCODED_SECRET_DISABLED
BytebuddyAgent [baseline] (820.998 ms) : 0, 820998
BytebuddyAgent [candidate] (809.961 ms) : 0, 809961
GlobalTracer [baseline] (309.111 ms) : 0, 309111
GlobalTracer [candidate] (307.785 ms) : 0, 307785
AppSec [baseline] (57.952 ms) : 0, 57952
AppSec [candidate] (57.158 ms) : 0, 57158
Remote Config [baseline] (642.387 µs) : 0, 642
Remote Config [candidate] (1.435 ms) : 0, 1435
Telemetry [baseline] (7.532 ms) : 0, 7532
Telemetry [candidate] (7.563 ms) : 0, 7563
IAST [baseline] (21.067 ms) : 0, 21067
IAST [candidate] (21.651 ms) : 0, 21651
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (807.012 ms) : 0, 807012
BytebuddyAgent [candidate] (807.215 ms) : 0, 807215
GlobalTracer [baseline] (307.465 ms) : 0, 307465
GlobalTracer [candidate] (307.345 ms) : 0, 307345
AppSec [baseline] (57.829 ms) : 0, 57829
AppSec [candidate] (57.05 ms) : 0, 57050
Remote Config [baseline] (622.86 µs) : 0, 623
Remote Config [candidate] (622.809 µs) : 0, 623
Telemetry [baseline] (7.436 ms) : 0, 7436
Telemetry [candidate] (7.399 ms) : 0, 7399
IAST [baseline] (21.19 ms) : 0, 21190
IAST [candidate] (22.152 ms) : 0, 22152
Loading
Startup time reports for petclinic 
gantt
    title petclinic - global startup overhead: candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.096 s) : 0, 1095681
Total [baseline] (10.477 s) : 0, 10476940
Agent [candidate] (1.089 s) : 0, 1088839
Total [candidate] (10.462 s) : 0, 10462011
section appsec
Agent [baseline] (1.226 s) : 0, 1225798
Total [baseline] (10.755 s) : 0, 10755025
Agent [candidate] (1.232 s) : 0, 1232159
Total [candidate] (10.72 s) : 0, 10719984
section iast
Agent [baseline] (1.217 s) : 0, 1217442
Total [baseline] (10.93 s) : 0, 10929890
Agent [candidate] (1.22 s) : 0, 1220289
Total [candidate] (10.977 s) : 0, 10977070
section profiling
Agent [baseline] (1.298 s) : 0, 1297890
Total [baseline] (10.83 s) : 0, 10830315
Agent [candidate] (1.289 s) : 0, 1288804
Total [candidate] (10.829 s) : 0, 10828993
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.096 s -
Agent appsec 1.226 s 130.116 ms (11.9%)
Agent iast 1.217 s 121.761 ms (11.1%)
Agent profiling 1.298 s 202.209 ms (18.5%)
Total tracing 10.477 s -
Total appsec 10.755 s 278.084 ms (2.7%)
Total iast 10.93 s 452.95 ms (4.3%)
Total profiling 10.83 s 353.375 ms (3.4%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.089 s -
Agent appsec 1.232 s 143.319 ms (13.2%)
Agent iast 1.22 s 131.45 ms (12.1%)
Agent profiling 1.289 s 199.965 ms (18.4%)
Total tracing 10.462 s -
Total appsec 10.72 s 257.973 ms (2.5%)
Total iast 10.977 s 515.058 ms (4.9%)
Total profiling 10.829 s 366.981 ms (3.5%) 
gantt
    title petclinic - break down per module: candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (696.001 ms) : 0, 696001
BytebuddyAgent [candidate] (692.1 ms) : 0, 692100
GlobalTracer [baseline] (319.576 ms) : 0, 319576
GlobalTracer [candidate] (317.742 ms) : 0, 317742
AppSec [baseline] (54.944 ms) : 0, 54944
AppSec [candidate] (54.521 ms) : 0, 54521
Remote Config [baseline] (706.601 µs) : 0, 707
Remote Config [candidate] (680.6 µs) : 0, 681
Telemetry [baseline] (10.727 ms) : 0, 10727
Telemetry [candidate] (10.041 ms) : 0, 10041
section appsec
BytebuddyAgent [baseline] (711.089 ms) : 0, 711089
BytebuddyAgent [candidate] (714.567 ms) : 0, 714567
GlobalTracer [baseline] (315.499 ms) : 0, 315499
GlobalTracer [candidate] (316.896 ms) : 0, 316896
AppSec [baseline] (167.432 ms) : 0, 167432
AppSec [candidate] (168.483 ms) : 0, 168483
Remote Config [baseline] (634.844 µs) : 0, 635
Remote Config [candidate] (644.472 µs) : 0, 644
Telemetry [baseline] (7.532 ms) : 0, 7532
Telemetry [candidate] (7.864 ms) : 0, 7864
IAST [baseline] (19.741 ms) : 0, 19741
IAST [candidate] (19.749 ms) : 0, 19749
section iast
BytebuddyAgent [baseline] (809.118 ms) : 0, 809118
BytebuddyAgent [candidate] (813.611 ms) : 0, 813611
GlobalTracer [baseline] (307.313 ms) : 0, 307313
GlobalTracer [candidate] (306.244 ms) : 0, 306244
AppSec [baseline] (56.443 ms) : 0, 56443
AppSec [candidate] (57.855 ms) : 0, 57855
Remote Config [baseline] (636.831 µs) : 0, 637
Remote Config [candidate] (600.484 µs) : 0, 600
Telemetry [baseline] (8.403 ms) : 0, 8403
Telemetry [candidate] (7.392 ms) : 0, 7392
IAST [baseline] (21.769 ms) : 0, 21769
IAST [candidate] (20.77 ms) : 0, 20770
section profiling
BytebuddyAgent [baseline] (691.579 ms) : 0, 691579
BytebuddyAgent [candidate] (687.483 ms) : 0, 687483
GlobalTracer [baseline] (404.152 ms) : 0, 404152
GlobalTracer [candidate] (401.52 ms) : 0, 401520
AppSec [baseline] (55.652 ms) : 0, 55652
AppSec [candidate] (55.358 ms) : 0, 55358
Remote Config [baseline] (688.028 µs) : 0, 688
Remote Config [candidate] (684.693 µs) : 0, 685
Telemetry [baseline] (11.871 ms) : 0, 11871
Telemetry [candidate] (13.481 ms) : 0, 13481
ProfilingAgent [baseline] (94.672 ms) : 0, 94672
ProfilingAgent [candidate] (91.096 ms) : 0, 91096
Profiling [baseline] (94.695 ms) : 0, 94695
Profiling [candidate] (91.119 ms) : 0, 91119
Loading

Load

Parameters

Baseline Candidate
baseline_or_candidate baseline candidate
end_time 2024-11-20T14:25:18 2024-11-20T14:32:14
git_branch master nenadnoveljic/pg-prepared
git_commit_date 1732111926 1732112078
git_commit_sha 270a82d f2f7b8f
release_version 1.43.0-SNAPSHOT~270a82d63a 1.43.0-SNAPSHOT~f2f7b8f01c
start_time 2024-11-20T14:25:04 2024-11-20T14:32:01
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
ci_job_date 1732113486 1732113486
ci_job_id 713828638 713828638
ci_pipeline_id 49498317 49498317
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 11 metrics, 15 unstable metrics.

Dacapo

Parameters

Baseline Candidate
baseline_or_candidate baseline candidate
git_branch master nenadnoveljic/pg-prepared
git_commit_date 1732111926 1732112078
git_commit_sha 270a82d f2f7b8f
release_version 1.43.0-SNAPSHOT~270a82d63a 1.43.0-SNAPSHOT~f2f7b8f01c
See matching parameters
Baseline Candidate
application biojava biojava
ci_job_date 1732113992 1732113992
ci_job_id 713828639 713828639
ci_pipeline_id 49498317 49498317
cpu_model Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz
variant appsec appsec

Summary

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

Execution time for tomcat 
gantt
    title tomcat - execution time [CI 0.99] : candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.466 ms) : 1454, 1477
.   : milestone, 1466,
appsec (2.346 ms) : 2304, 2387
.   : milestone, 2346,
iast (2.08 ms) : 2028, 2132
.   : milestone, 2080,
iast_GLOBAL (2.133 ms) : 2080, 2186
.   : milestone, 2133,
profiling (1.951 ms) : 1909, 1993
.   : milestone, 1951,
tracing (1.932 ms) : 1891, 1972
.   : milestone, 1932,
section candidate
no_agent (1.464 ms) : 1453, 1475
.   : milestone, 1464,
appsec (2.336 ms) : 2295, 2377
.   : milestone, 2336,
iast (2.092 ms) : 2039, 2144
.   : milestone, 2092,
iast_GLOBAL (2.123 ms) : 2070, 2175
.   : milestone, 2123,
profiling (2.44 ms) : 2249, 2630
.   : milestone, 2440,
tracing (1.92 ms) : 1880, 1959
.   : milestone, 1920,
Loading
  • baseline results
Variant Execution Time [CI 0.99] Δ no_agent
no_agent 1.466 ms [1.454 ms, 1.477 ms] -
appsec 2.346 ms [2.304 ms, 2.387 ms] 880.166 µs (60.0%)
iast 2.08 ms [2.028 ms, 2.132 ms] 614.262 µs (41.9%)
iast_GLOBAL 2.133 ms [2.08 ms, 2.186 ms] 667.136 µs (45.5%)
profiling 1.951 ms [1.909 ms, 1.993 ms] 485.332 µs (33.1%)
tracing 1.932 ms [1.891 ms, 1.972 ms] 465.88 µs (31.8%)
  • candidate results
Variant Execution Time [CI 0.99] Δ no_agent
no_agent 1.464 ms [1.453 ms, 1.475 ms] -
appsec 2.336 ms [2.295 ms, 2.377 ms] 872.079 µs (59.6%)
iast 2.092 ms [2.039 ms, 2.144 ms] 627.8 µs (42.9%)
iast_GLOBAL 2.123 ms [2.07 ms, 2.175 ms] 658.577 µs (45.0%)
profiling 2.44 ms [2.249 ms, 2.63 ms] 975.767 µs (66.7%)
tracing 1.92 ms [1.88 ms, 1.959 ms] 455.542 µs (31.1%)
Execution time for biojava 
gantt
    title biojava - execution time [CI 0.99] : candidate=1.43.0-SNAPSHOT~f2f7b8f01c, baseline=1.43.0-SNAPSHOT~270a82d63a
    dateFormat X
    axisFormat %s
section baseline
no_agent (14.935 s) : 14935000, 14935000
.   : milestone, 14935000,
appsec (15.014 s) : 15014000, 15014000
.   : milestone, 15014000,
iast (18.6 s) : 18600000, 18600000
.   : milestone, 18600000,
iast_GLOBAL (18.243 s) : 18243000, 18243000
.   : milestone, 18243000,
profiling (15.469 s) : 15469000, 15469000
.   : milestone, 15469000,
tracing (14.98 s) : 14980000, 14980000
.   : milestone, 14980000,
section candidate
no_agent (14.886 s) : 14886000, 14886000
.   : milestone, 14886000,
appsec (14.954 s) : 14954000, 14954000
.   : milestone, 14954000,
iast (18.766 s) : 18766000, 18766000
.   : milestone, 18766000,
iast_GLOBAL (18.03 s) : 18030000, 18030000
.   : milestone, 18030000,
profiling (14.889 s) : 14889000, 14889000
.   : milestone, 14889000,
tracing (14.873 s) : 14873000, 14873000
.   : milestone, 14873000,
Loading
  • baseline results
Variant Execution Time [CI 0.99] Δ no_agent
no_agent 14.935 s [14.935 s, 14.935 s] -
appsec 15.014 s [15.014 s, 15.014 s] 79.0 ms (0.5%)
iast 18.6 s [18.6 s, 18.6 s] 3.665 s (24.5%)
iast_GLOBAL 18.243 s [18.243 s, 18.243 s] 3.308 s (22.1%)
profiling 15.469 s [15.469 s, 15.469 s] 534.0 ms (3.6%)
tracing 14.98 s [14.98 s, 14.98 s] 45.0 ms (0.3%)
  • candidate results
Variant Execution Time [CI 0.99] Δ no_agent
no_agent 14.886 s [14.886 s, 14.886 s] -
appsec 14.954 s [14.954 s, 14.954 s] 68.0 ms (0.5%)
iast 18.766 s [18.766 s, 18.766 s] 3.88 s (26.1%)
iast_GLOBAL 18.03 s [18.03 s, 18.03 s] 3.144 s (21.1%)
profiling 14.889 s [14.889 s, 14.889 s] 3.0 ms (0.0%)
tracing 14.873 s [14.873 s, 14.873 s] -13.0 ms (-0.1%)

@nenadnoveljic nenadnoveljic marked this pull request as ready for review November 21, 2024 15:58
@nenadnoveljic nenadnoveljic requested review from a team as code owners November 21, 2024 15:58
mcculls
mcculls reviewed Nov 25, 2024
View reviewed changes
internal-api/src/main/java/datadog/trace/bootstrap/instrumentation/api/InstrumentationTags.java
@@ -107,6 +107,7 @@ public class InstrumentationTags {
public static final String TWILIO_STATUS = "twilio.status";
public static final String TWILIO_PARENT_SID = "twilio.parentSid";
public static final String DBM_TRACE_INJECTED = "_dd.dbm_trace_injected";
public static final String TIME_MS = "dd.instrumentation.time_ms";
Copy link
Contributor

Choose a reason for hiding this comment

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

TIME_MS is too vague as a constant name, it should be INSTRUMENTATION_TIME_MS

amarziali
amarziali reviewed Nov 25, 2024
View reviewed changes
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
}
final String traceParent = DECORATE.traceParent(span, priority);
if (traceParent == null
|| !traceParent.matches("^00-[a-f0-9]{32}-[a-f0-9]{16}-[a-f0-9]{2}$")) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

this can be precompiled since in this way it looks pretty inefficient

amarziali
amarziali reviewed Nov 25, 2024
View reviewed changes
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
} finally {
span.setTag(DBM_TRACE_INJECTED, true);
final long elapsed = System.currentTimeMillis() - startTime;
span.setTag("dd.instrumentation.time_ms", elapsed);
Copy link
Collaborator

Choose a reason for hiding this comment

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

this should be in a constant (i.e InstrumentationTags can be a good place for it)

amarziali
amarziali reviewed Nov 25, 2024
View reviewed changes
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
} catch (SQLException e) {
throw e;
}
} catch (Exception e) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

This can be widen to Throwable

amarziali
amarziali reviewed Nov 25, 2024
View reviewed changes
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
throw e;
}
} catch (Exception e) {
log.debug(
Copy link
Collaborator

Choose a reason for hiding this comment

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

If the statement execution above fails I think that will be catched by the SQLException case. Is this log never printed?

amarziali
amarziali reviewed Nov 25, 2024
View reviewed changes
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
try (Statement statement = connection.createStatement()) {
statement.execute(sql.toString());
} catch (SQLException e) {
throw e;
Copy link
Collaborator

Choose a reason for hiding this comment

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

Do you really want to throw this by our code? I think it should silently swapped and something printed

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@amarziali amarziali amarziali left review comments

@mcculls mcculls mcculls left review comments

At least 1 approving review is required to merge this pull request.

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@nenadnoveljic @mcculls @amarziali