Merge span decoration and log instrumentation by jpbempel · Pull Request #5809 · DataDog/dd-trace-java

jpbempel · 2023-08-30T09:11:09Z

What Does This Do

Span decoration probes and log probes share the same instrumentor so we need to generate the same instrumentation for both otherwise we fall into the same issues than duplicated probes, and local var access issue with scoping.
CapturedContextInstrumentor is therefore the only instrumentor for both span decoration and log probes

Motivation

Additional Notes

Span decoration probes and log probes share the same instrumentor so we need to generate the same instrumentation for both otherwise we fall into the same issues than duplicated probes, and local var access issue with scoping. CapturedContextInstrumentor is therefore the only instrumentor for both span decoration and log probes

pr-commenter · 2023-08-30T09:57:45Z

Benchmarks

Startup

Parameters

	Baseline	Candidate
commit	1.20.0-SNAPSHOT~360dce29f8	1.20.0-SNAPSHOT~6e5b6b7b23
config	baseline	candidate

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
module	Agent	Agent
parent	None	None
variant	appsec	appsec

Summary

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

Startup time reports for petclinic

gantt
    title petclinic - global startup overhead: candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (988.807 ms) : 0, 988807
Total [baseline] (9.17 s) : 0, 9169557
Agent [candidate] (987.274 ms) : 0, 987274
Total [candidate] (9.149 s) : 0, 9149284
section appsec
Agent [baseline] (1.074 s) : 0, 1073544
Total [baseline] (9.242 s) : 0, 9242489
Agent [candidate] (1.073 s) : 0, 1073441
Total [candidate] (9.284 s) : 0, 9284251
section iast
Agent [baseline] (1.096 s) : 0, 1095542
Total [baseline] (9.386 s) : 0, 9385619
Agent [candidate] (1.116 s) : 0, 1116021
Total [candidate] (9.597 s) : 0, 9596603
section profiling
Agent [baseline] (1.161 s) : 0, 1161160
Total [baseline] (9.457 s) : 0, 9456632
Agent [candidate] (1.161 s) : 0, 1161423
Total [candidate] (9.436 s) : 0, 9435815

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	988.807 ms	-
Agent	appsec	1.074 s	84.737 ms (8.6%)
Agent	iast	1.096 s	106.736 ms (10.8%)
Agent	profiling	1.161 s	172.354 ms (17.4%)
Total	tracing	9.17 s	-
Total	appsec	9.242 s	72.932 ms (0.8%)
Total	iast	9.386 s	216.062 ms (2.4%)
Total	profiling	9.457 s	287.075 ms (3.1%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	987.274 ms	-
Agent	appsec	1.073 s	86.167 ms (8.7%)
Agent	iast	1.116 s	128.747 ms (13.0%)
Agent	profiling	1.161 s	174.149 ms (17.6%)
Total	tracing	9.149 s	-
Total	appsec	9.284 s	134.966 ms (1.5%)
Total	iast	9.597 s	447.319 ms (4.9%)
Total	profiling	9.436 s	286.531 ms (3.1%)

gantt
    title petclinic - break down per module: candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (613.025 ms) : 0, 613025
BytebuddyAgent [candidate] (612.34 ms) : 0, 612340
GlobalTracer [baseline] (284.499 ms) : 0, 284499
GlobalTracer [candidate] (284.147 ms) : 0, 284147
AppSec [baseline] (50.312 ms) : 0, 50312
AppSec [candidate] (49.989 ms) : 0, 49989
Remote Config [baseline] (665.285 µs) : 0, 665
Remote Config [candidate] (664.473 µs) : 0, 664
Telemetry [baseline] (6.01 ms) : 0, 6010
Telemetry [candidate] (5.984 ms) : 0, 5984
section appsec
BytebuddyAgent [baseline] (613.428 ms) : 0, 613428
BytebuddyAgent [candidate] (613.292 ms) : 0, 613292
GlobalTracer [baseline] (284.325 ms) : 0, 284325
GlobalTracer [candidate] (284.517 ms) : 0, 284517
AppSec [baseline] (135.046 ms) : 0, 135046
AppSec [candidate] (134.889 ms) : 0, 134889
Remote Config [baseline] (720.212 µs) : 0, 720
Remote Config [candidate] (722.774 µs) : 0, 723
Telemetry [baseline] (5.725 ms) : 0, 5725
Telemetry [candidate] (5.734 ms) : 0, 5734
section iast
BytebuddyAgent [baseline] (722.069 ms) : 0, 722069
BytebuddyAgent [candidate] (736.014 ms) : 0, 736014
GlobalTracer [baseline] (271.302 ms) : 0, 271302
GlobalTracer [candidate] (275.681 ms) : 0, 275681
AppSec [baseline] (46.973 ms) : 0, 46973
AppSec [candidate] (47.801 ms) : 0, 47801
IAST [baseline] (14.43 ms) : 0, 14430
IAST [candidate] (14.924 ms) : 0, 14924
Remote Config [baseline] (580.136 µs) : 0, 580
Remote Config [candidate] (604.383 µs) : 0, 604
Telemetry [baseline] (5.81 ms) : 0, 5810
Telemetry [candidate] (5.938 ms) : 0, 5938
section profiling
BytebuddyAgent [baseline] (627.438 ms) : 0, 627438
BytebuddyAgent [candidate] (626.522 ms) : 0, 626522
GlobalTracer [baseline] (348.779 ms) : 0, 348779
GlobalTracer [candidate] (348.013 ms) : 0, 348013
AppSec [baseline] (48.99 ms) : 0, 48990
AppSec [candidate] (49.11 ms) : 0, 49110
Remote Config [baseline] (638.662 µs) : 0, 639
Remote Config [candidate] (646.741 µs) : 0, 647
Telemetry [baseline] (5.924 ms) : 0, 5924
Telemetry [candidate] (5.982 ms) : 0, 5982
ProfilingAgent [baseline] (76.46 ms) : 0, 76460
ProfilingAgent [candidate] (78.28 ms) : 0, 78280
Profiling [baseline] (76.484 ms) : 0, 76484
Profiling [candidate] (78.304 ms) : 0, 78304

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (987.032 ms) : 0, 987032
Total [baseline] (8.62 s) : 0, 8619840
Agent [candidate] (1.001 s) : 0, 1001318
Total [candidate] (8.702 s) : 0, 8702375
section appsec
Agent [baseline] (1.073 s) : 0, 1073404
Total [baseline] (8.757 s) : 0, 8756644
Agent [candidate] (1.07 s) : 0, 1070327
Total [candidate] (8.731 s) : 0, 8731043
section iast
Agent [baseline] (1.09 s) : 0, 1090240
Total [baseline] (9.118 s) : 0, 9118122
Agent [candidate] (1.092 s) : 0, 1092150
Total [candidate] (9.167 s) : 0, 9167487
section profiling
Agent [baseline] (1.157 s) : 0, 1157352
Total [baseline] (8.844 s) : 0, 8844140
Agent [candidate] (1.162 s) : 0, 1162289
Total [candidate] (8.907 s) : 0, 8906777

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	987.032 ms	-
Agent	appsec	1.073 s	86.372 ms (8.8%)
Agent	iast	1.09 s	103.208 ms (10.5%)
Agent	profiling	1.157 s	170.32 ms (17.3%)
Total	tracing	8.62 s	-
Total	appsec	8.757 s	136.804 ms (1.6%)
Total	iast	9.118 s	498.282 ms (5.8%)
Total	profiling	8.844 s	224.3 ms (2.6%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.001 s	-
Agent	appsec	1.07 s	69.01 ms (6.9%)
Agent	iast	1.092 s	90.832 ms (9.1%)
Agent	profiling	1.162 s	160.971 ms (16.1%)
Total	tracing	8.702 s	-
Total	appsec	8.731 s	28.668 ms (0.3%)
Total	iast	9.167 s	465.113 ms (5.3%)
Total	profiling	8.907 s	204.402 ms (2.3%)

gantt
    title insecure-bank - break down per module: candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (612.153 ms) : 0, 612153
BytebuddyAgent [candidate] (621.249 ms) : 0, 621249
GlobalTracer [baseline] (283.833 ms) : 0, 283833
GlobalTracer [candidate] (288.142 ms) : 0, 288142
AppSec [baseline] (50.028 ms) : 0, 50028
AppSec [candidate] (50.33 ms) : 0, 50330
Remote Config [baseline] (668.552 µs) : 0, 669
Remote Config [candidate] (685.967 µs) : 0, 686
Telemetry [baseline] (6.002 ms) : 0, 6002
Telemetry [candidate] (6.081 ms) : 0, 6081
section appsec
BytebuddyAgent [baseline] (613.332 ms) : 0, 613332
BytebuddyAgent [candidate] (611.542 ms) : 0, 611542
GlobalTracer [baseline] (284.536 ms) : 0, 284536
GlobalTracer [candidate] (283.57 ms) : 0, 283570
AppSec [baseline] (134.761 ms) : 0, 134761
AppSec [candidate] (134.528 ms) : 0, 134528
Remote Config [baseline] (727.695 µs) : 0, 728
Remote Config [candidate] (720.963 µs) : 0, 721
Telemetry [baseline] (5.719 ms) : 0, 5719
Telemetry [candidate] (5.704 ms) : 0, 5704
section iast
BytebuddyAgent [baseline] (718.731 ms) : 0, 718731
BytebuddyAgent [candidate] (719.319 ms) : 0, 719319
GlobalTracer [baseline] (270.076 ms) : 0, 270076
GlobalTracer [candidate] (270.918 ms) : 0, 270918
AppSec [baseline] (46.486 ms) : 0, 46486
AppSec [candidate] (46.704 ms) : 0, 46704
IAST [baseline] (14.337 ms) : 0, 14337
IAST [candidate] (14.54 ms) : 0, 14540
Remote Config [baseline] (566.447 µs) : 0, 566
Remote Config [candidate] (576.623 µs) : 0, 577
Telemetry [baseline] (5.727 ms) : 0, 5727
Telemetry [candidate] (5.774 ms) : 0, 5774
section profiling
BytebuddyAgent [baseline] (624.98 ms) : 0, 624980
BytebuddyAgent [candidate] (626.141 ms) : 0, 626141
GlobalTracer [baseline] (346.839 ms) : 0, 346839
GlobalTracer [candidate] (347.942 ms) : 0, 347942
AppSec [baseline] (48.812 ms) : 0, 48812
AppSec [candidate] (49.067 ms) : 0, 49067
Remote Config [baseline] (637.924 µs) : 0, 638
Remote Config [candidate] (649.582 µs) : 0, 650
Telemetry [baseline] (5.915 ms) : 0, 5915
Telemetry [candidate] (5.954 ms) : 0, 5954
ProfilingAgent [baseline] (77.41 ms) : 0, 77410
ProfilingAgent [candidate] (79.637 ms) : 0, 79637
Profiling [baseline] (77.434 ms) : 0, 77434
Profiling [candidate] (79.661 ms) : 0, 79661

Load

Parameters

	Baseline	Candidate
commit	1.20.0-SNAPSHOT~360dce29f8	1.20.0-SNAPSHOT~6e5b6b7b23
config	baseline	candidate
end_time	2023-08-30T12:14:29	2023-08-30T12:32:36
start_time	2023-08-30T12:14:11	2023-08-30T12:32:19

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
variant	appsec	appsec

Summary

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

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.328 ms) : 1309, 1346
.   : milestone, 1328,
appsec (1.673 ms) : 1649, 1697
.   : milestone, 1673,
iast (1.457 ms) : 1433, 1481
.   : milestone, 1457,
profiling (1.46 ms) : 1435, 1484
.   : milestone, 1460,
tracing (1.424 ms) : 1399, 1449
.   : milestone, 1424,
section candidate
no_agent (1.326 ms) : 1307, 1345
.   : milestone, 1326,
appsec (1.665 ms) : 1640, 1689
.   : milestone, 1665,
iast (1.462 ms) : 1439, 1486
.   : milestone, 1462,
profiling (1.448 ms) : 1424, 1472
.   : milestone, 1448,
tracing (1.462 ms) : 1438, 1487
.   : milestone, 1462,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.328 ms [1.309 ms, 1.346 ms]	-
appsec	1.673 ms [1.649 ms, 1.697 ms]	345.19 µs (26.0%)
iast	1.457 ms [1.433 ms, 1.481 ms]	129.463 µs (9.8%)
profiling	1.46 ms [1.435 ms, 1.484 ms]	131.844 µs (9.9%)
tracing	1.424 ms [1.399 ms, 1.449 ms]	96.315 µs (7.3%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.326 ms [1.307 ms, 1.345 ms]	-
appsec	1.665 ms [1.64 ms, 1.689 ms]	338.257 µs (25.5%)
iast	1.462 ms [1.439 ms, 1.486 ms]	135.931 µs (10.2%)
profiling	1.448 ms [1.424 ms, 1.472 ms]	121.602 µs (9.2%)
tracing	1.462 ms [1.438 ms, 1.487 ms]	136.136 µs (10.3%)

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~6e5b6b7b23, baseline=1.20.0-SNAPSHOT~360dce29f8
    dateFormat X
    axisFormat %s
section baseline
no_agent (359.812 µs) : 340, 380
.   : milestone, 360,
appsec (659.223 µs) : 638, 680
.   : milestone, 659,
iast (451.004 µs) : 430, 472
.   : milestone, 451,
iast_FULL (515.505 µs) : 495, 536
.   : milestone, 516,
iast_INACTIVE (425.006 µs) : 404, 446
.   : milestone, 425,
profiling (433.108 µs) : 412, 454
.   : milestone, 433,
tracing (431.645 µs) : 410, 453
.   : milestone, 432,
section candidate
no_agent (359.342 µs) : 339, 379
.   : milestone, 359,
appsec (660.448 µs) : 640, 681
.   : milestone, 660,
iast (454.607 µs) : 434, 475
.   : milestone, 455,
iast_FULL (514.943 µs) : 494, 535
.   : milestone, 515,
iast_INACTIVE (431.535 µs) : 410, 453
.   : milestone, 432,
profiling (435.193 µs) : 414, 456
.   : milestone, 435,
tracing (432.337 µs) : 412, 453
.   : milestone, 432,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	359.812 µs [339.835 µs, 379.79 µs]	-
appsec	659.223 µs [638.183 µs, 680.262 µs]	299.41 µs (83.2%)
iast	451.004 µs [430.394 µs, 471.613 µs]	91.191 µs (25.3%)
iast_FULL	515.505 µs [495.14 µs, 535.87 µs]	155.692 µs (43.3%)
iast_INACTIVE	425.006 µs [404.339 µs, 445.672 µs]	65.193 µs (18.1%)
profiling	433.108 µs [412.02 µs, 454.197 µs]	73.296 µs (20.4%)
tracing	431.645 µs [409.963 µs, 453.326 µs]	71.832 µs (20.0%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	359.342 µs [339.387 µs, 379.296 µs]	-
appsec	660.448 µs [639.643 µs, 681.253 µs]	301.106 µs (83.8%)
iast	454.607 µs [434.002 µs, 475.212 µs]	95.265 µs (26.5%)
iast_FULL	514.943 µs [494.458 µs, 535.427 µs]	155.601 µs (43.3%)
iast_INACTIVE	431.535 µs [409.658 µs, 453.412 µs]	72.193 µs (20.1%)
profiling	435.193 µs [414.2 µs, 456.186 µs]	75.852 µs (21.1%)
tracing	432.337 µs [411.815 µs, 452.859 µs]	72.995 µs (20.3%)

shatzi

LGTM

shatzi · 2023-08-30T10:24:33Z

      List<String> probeIds) {
-    new SpanDecorationInstrumentor(this, classLoader, classNode, methodNode, diagnostics, probeIds)
+    new CapturedContextInstrumentor(
+            this, classLoader, classNode, methodNode, diagnostics, probeIds, false, Limits.DEFAULT)


it seems we are calling istrument of the first probe in the captureContextProbe list.

what are the side-effects if a span-decoration is first and the second is a log probe with isCaptureSnapshot() set to true?

I think same for different captureLimits

Fixed that by picking always the first log probe first even though we have specific order dictated by

dd-trace-java/dd-java-agent/agent-debugger/src/main/java/com/datadog/debugger/agent/Configuration.java

Lines 135 to 150 in 967c9d7

public Collection<ProbeDefinition> getDefinitions() {

Collection<ProbeDefinition> result = new ArrayList<>();

if (metricProbes != null) {

result.addAll(metricProbes);

}

if (logProbes != null) {

result.addAll(logProbes);

}

if (spanProbes != null) {

result.addAll(spanProbes);

}

if (spanDecorationProbes != null) {

result.addAll(spanDecorationProbes);

}

return result;

}

jpbempel requested a review from a team as a code owner August 30, 2023 09:11

jpbempel requested review from ojung and removed request for a team August 30, 2023 09:11

jpbempel added the comp: debugger Dynamic Instrumentation label Aug 30, 2023

shatzi approved these changes Aug 30, 2023

View reviewed changes

enforce log probe selection

6e5b6b7

jpbempel merged commit 6308c00 into master Aug 30, 2023

jpbempel deleted the jpbempel/span-deco-mixed-logs branch August 30, 2023 12:40

github-actions Bot added this to the 1.20.0 milestone Aug 30, 2023

jpbempel added the type: bug fix Bug fix label Aug 30, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Merge span decoration and log instrumentation#5809

Merge span decoration and log instrumentation#5809
jpbempel merged 2 commits into
masterfrom
jpbempel/span-deco-mixed-logs

jpbempel commented Aug 30, 2023

Uh oh!

pr-commenter Bot commented Aug 30, 2023 •

edited

Loading

Uh oh!

shatzi left a comment

Uh oh!

shatzi Aug 30, 2023

Uh oh!

jpbempel Aug 30, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

	public Collection<ProbeDefinition> getDefinitions() {
	Collection<ProbeDefinition> result = new ArrayList<>();
	if (metricProbes != null) {
	result.addAll(metricProbes);
	}
	if (logProbes != null) {
	result.addAll(logProbes);
	}
	if (spanProbes != null) {
	result.addAll(spanProbes);
	}
	if (spanDecorationProbes != null) {
	result.addAll(spanDecorationProbes);
	}
	return result;
	}

Uh oh!

Conversation

jpbempel commented Aug 30, 2023

What Does This Do

Motivation

Additional Notes

Uh oh!

pr-commenter Bot commented Aug 30, 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!

shatzi left a comment

Choose a reason for hiding this comment

Uh oh!

shatzi Aug 30, 2023

Choose a reason for hiding this comment

Uh oh!

jpbempel Aug 30, 2023

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

pr-commenter Bot commented Aug 30, 2023 •

edited

Loading