Fix tracer logging when instrumenting Gradle Daemon #6080

nikita-tkachenko-datadog · 2023-10-23T09:14:15Z

What Does This Do

Fixes tracer logging to work when instrumenting Gradle Daemon.

Motivation

Tracer logs contain data that is important for debugging.

When Gradle Daemon initialises, it closes original System.out and System.err streams, replacing them with daemon log streams.
Tracer logging is initialised before the daemon, so it refers to the original streams that are closed.
In order for the logging to work, it needs to refer to the daemon log streams.
This is achieved by reinitialising logging settings after Gradle Daemon has finished its initialisation.

Jira ticket: CIVIS-7730

pr-commenter · 2023-10-23T09:55:20Z

Benchmarks

Startup

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~9a80d519df	1.22.0-SNAPSHOT~3407cf2fba
config	baseline	candidate

See matching parameters

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

Summary

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

scenario	Δ mean execution_time	candidate mean execution_time	baseline mean execution_time
scenario:insecure-bank:iast:Telemetry	better [-5.182ms; -0.421ms] or [-62.506%; -5.073%]	5.490ms	8.291ms

Startup time reports for petclinic

gantt
    title petclinic - global startup overhead: candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.012 s) : 0, 1012152
Total [baseline] (9.212 s) : 0, 9211891
Agent [candidate] (1.017 s) : 0, 1017287
Total [candidate] (9.286 s) : 0, 9286307
section appsec
Agent [baseline] (1.103 s) : 0, 1102612
Total [baseline] (9.287 s) : 0, 9286669
Agent [candidate] (1.103 s) : 0, 1103438
Total [candidate] (9.332 s) : 0, 9331838
section iast
Agent [baseline] (1.155 s) : 0, 1155483
Total [baseline] (9.504 s) : 0, 9503806
Agent [candidate] (1.145 s) : 0, 1144925
Total [candidate] (9.431 s) : 0, 9430687
section profiling
Agent [baseline] (1.2 s) : 0, 1199778
Total [baseline] (9.476 s) : 0, 9475593
Agent [candidate] (1.197 s) : 0, 1196567
Total [candidate] (9.601 s) : 0, 9600729

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.012 s	-
Agent	appsec	1.103 s	90.46 ms (8.9%)
Agent	iast	1.155 s	143.332 ms (14.2%)
Agent	profiling	1.2 s	187.627 ms (18.5%)
Total	tracing	9.212 s	-
Total	appsec	9.287 s	74.778 ms (0.8%)
Total	iast	9.504 s	291.915 ms (3.2%)
Total	profiling	9.476 s	263.703 ms (2.9%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.017 s	-
Agent	appsec	1.103 s	86.15 ms (8.5%)
Agent	iast	1.145 s	127.638 ms (12.5%)
Agent	profiling	1.197 s	179.28 ms (17.6%)
Total	tracing	9.286 s	-
Total	appsec	9.332 s	45.531 ms (0.5%)
Total	iast	9.431 s	144.38 ms (1.6%)
Total	profiling	9.601 s	314.422 ms (3.4%)

gantt
    title petclinic - break down per module: candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (630.889 ms) : 0, 630889
BytebuddyAgent [candidate] (633.733 ms) : 0, 633733
GlobalTracer [baseline] (291.653 ms) : 0, 291653
GlobalTracer [candidate] (293.375 ms) : 0, 293375
AppSec [baseline] (48.711 ms) : 0, 48711
AppSec [candidate] (49.129 ms) : 0, 49129
Remote Config [baseline] (654.958 µs) : 0, 655
Remote Config [candidate] (661.196 µs) : 0, 661
Telemetry [baseline] (5.983 ms) : 0, 5983
Telemetry [candidate] (6.03 ms) : 0, 6030
section appsec
BytebuddyAgent [baseline] (632.649 ms) : 0, 632649
BytebuddyAgent [candidate] (632.851 ms) : 0, 632851
GlobalTracer [baseline] (291.848 ms) : 0, 291848
GlobalTracer [candidate] (292.348 ms) : 0, 292348
AppSec [baseline] (137.508 ms) : 0, 137508
AppSec [candidate] (137.706 ms) : 0, 137706
Remote Config [baseline] (638.573 µs) : 0, 639
Remote Config [candidate] (639.542 µs) : 0, 640
Telemetry [baseline] (5.685 ms) : 0, 5685
Telemetry [candidate] (5.703 ms) : 0, 5703
section iast
BytebuddyAgent [baseline] (771.709 ms) : 0, 771709
BytebuddyAgent [candidate] (763.478 ms) : 0, 763478
GlobalTracer [baseline] (276.09 ms) : 0, 276090
GlobalTracer [candidate] (273.41 ms) : 0, 273410
AppSec [baseline] (47.055 ms) : 0, 47055
AppSec [candidate] (46.558 ms) : 0, 46558
Remote Config [baseline] (592.135 µs) : 0, 592
Remote Config [candidate] (587.365 µs) : 0, 587
Telemetry [baseline] (7.694 ms) : 0, 7694
Telemetry [candidate] (7.597 ms) : 0, 7597
IAST [baseline] (17.612 ms) : 0, 17612
IAST [candidate] (18.926 ms) : 0, 18926
section profiling
ProfilingAgent [baseline] (81.065 ms) : 0, 81065
ProfilingAgent [candidate] (81.09 ms) : 0, 81090
BytebuddyAgent [baseline] (651.4 ms) : 0, 651400
BytebuddyAgent [candidate] (648.291 ms) : 0, 648291
GlobalTracer [baseline] (357.213 ms) : 0, 357213
GlobalTracer [candidate] (357.278 ms) : 0, 357278
AppSec [baseline] (49.324 ms) : 0, 49324
AppSec [candidate] (49.485 ms) : 0, 49485
Remote Config [baseline] (662.323 µs) : 0, 662
Remote Config [candidate] (672.789 µs) : 0, 673
Telemetry [baseline] (6.096 ms) : 0, 6096
Telemetry [candidate] (6.129 ms) : 0, 6129
Profiling [baseline] (81.091 ms) : 0, 81091
Profiling [candidate] (81.114 ms) : 0, 81114

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.012 s) : 0, 1012289
Total [baseline] (8.692 s) : 0, 8691975
Agent [candidate] (1.023 s) : 0, 1022517
Total [candidate] (8.714 s) : 0, 8714106
section iast
Agent [baseline] (1.156 s) : 0, 1155839
Total [baseline] (9.313 s) : 0, 9313305
Agent [candidate] (1.14 s) : 0, 1139826
Total [candidate] (9.226 s) : 0, 9226262
section iast_TELEMETRY_OFF
Agent [baseline] (1.143 s) : 0, 1142726
Total [baseline] (9.233 s) : 0, 9233340
Agent [candidate] (1.132 s) : 0, 1131816
Total [candidate] (9.197 s) : 0, 9197299

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.012 s	-
Agent	iast	1.156 s	143.55 ms (14.2%)
Agent	iast_TELEMETRY_OFF	1.143 s	130.436 ms (12.9%)
Total	tracing	8.692 s	-
Total	iast	9.313 s	621.33 ms (7.1%)
Total	iast_TELEMETRY_OFF	9.233 s	541.365 ms (6.2%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.023 s	-
Agent	iast	1.14 s	117.309 ms (11.5%)
Agent	iast_TELEMETRY_OFF	1.132 s	109.299 ms (10.7%)
Total	tracing	8.714 s	-
Total	iast	9.226 s	512.156 ms (5.9%)
Total	iast_TELEMETRY_OFF	9.197 s	483.193 ms (5.5%)

gantt
    title insecure-bank - break down per module: candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (630.914 ms) : 0, 630914
BytebuddyAgent [candidate] (636.979 ms) : 0, 636979
GlobalTracer [baseline] (291.566 ms) : 0, 291566
GlobalTracer [candidate] (294.653 ms) : 0, 294653
AppSec [baseline] (48.943 ms) : 0, 48943
AppSec [candidate] (49.55 ms) : 0, 49550
Remote Config [baseline] (660.656 µs) : 0, 661
Remote Config [candidate] (666.805 µs) : 0, 667
Telemetry [baseline] (5.944 ms) : 0, 5944
Telemetry [candidate] (6.065 ms) : 0, 6065
section iast
BytebuddyAgent [baseline] (772.275 ms) : 0, 772275
BytebuddyAgent [candidate] (760.785 ms) : 0, 760785
GlobalTracer [baseline] (275.657 ms) : 0, 275657
GlobalTracer [candidate] (272.595 ms) : 0, 272595
AppSec [baseline] (46.645 ms) : 0, 46645
AppSec [candidate] (45.944 ms) : 0, 45944
IAST [baseline] (17.641 ms) : 0, 17641
IAST [candidate] (20.184 ms) : 0, 20184
Remote Config [baseline] (572.103 µs) : 0, 572
Remote Config [candidate] (582.984 µs) : 0, 583
Telemetry [baseline] (8.291 ms) : 0, 8291
Telemetry [candidate] (5.49 ms) : 0, 5490
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (761.322 ms) : 0, 761322
BytebuddyAgent [candidate] (753.939 ms) : 0, 753939
GlobalTracer [baseline] (274.953 ms) : 0, 274953
GlobalTracer [candidate] (272.742 ms) : 0, 272742
AppSec [baseline] (46.486 ms) : 0, 46486
AppSec [candidate] (46.356 ms) : 0, 46356
IAST [baseline] (17.116 ms) : 0, 17116
IAST [candidate] (17.069 ms) : 0, 17069
Remote Config [baseline] (583.449 µs) : 0, 583
Remote Config [candidate] (582.988 µs) : 0, 583
Telemetry [baseline] (7.677 ms) : 0, 7677
Telemetry [candidate] (6.926 ms) : 0, 6926

Load

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~9a80d519df	1.22.0-SNAPSHOT~3407cf2fba
config	baseline	candidate
end_time	2023-10-23T13:24:18	2023-10-23T13:40:35
start_time	2023-10-23T13:24:05	2023-10-23T13:40:22

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 petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.343 ms) : 1324, 1362
.   : milestone, 1343,
appsec (1.694 ms) : 1669, 1718
.   : milestone, 1694,
iast (1.453 ms) : 1429, 1477
.   : milestone, 1453,
profiling (1.46 ms) : 1436, 1485
.   : milestone, 1460,
tracing (1.45 ms) : 1426, 1475
.   : milestone, 1450,
section candidate
no_agent (1.33 ms) : 1311, 1349
.   : milestone, 1330,
appsec (1.699 ms) : 1675, 1724
.   : milestone, 1699,
iast (1.447 ms) : 1423, 1472
.   : milestone, 1447,
profiling (1.456 ms) : 1432, 1481
.   : milestone, 1456,
tracing (1.441 ms) : 1416, 1466
.   : milestone, 1441,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.343 ms [1.324 ms, 1.362 ms]	-
appsec	1.694 ms [1.669 ms, 1.718 ms]	351.088 µs (26.1%)
iast	1.453 ms [1.429 ms, 1.477 ms]	110.147 µs (8.2%)
profiling	1.46 ms [1.436 ms, 1.485 ms]	117.773 µs (8.8%)
tracing	1.45 ms [1.426 ms, 1.475 ms]	107.6 µs (8.0%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.33 ms [1.311 ms, 1.349 ms]	-
appsec	1.699 ms [1.675 ms, 1.724 ms]	369.374 µs (27.8%)
iast	1.447 ms [1.423 ms, 1.472 ms]	117.36 µs (8.8%)
profiling	1.456 ms [1.432 ms, 1.481 ms]	126.329 µs (9.5%)
tracing	1.441 ms [1.416 ms, 1.466 ms]	111.079 µs (8.4%)

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~3407cf2fba, baseline=1.22.0-SNAPSHOT~9a80d519df
    dateFormat X
    axisFormat %s
section baseline
no_agent (370.876 µs) : 350, 392
.   : milestone, 371,
iast (465.558 µs) : 445, 486
.   : milestone, 466,
iast_FULL (526.192 µs) : 506, 547
.   : milestone, 526,
iast_INACTIVE (432.019 µs) : 411, 453
.   : milestone, 432,
iast_TELEMETRY_OFF (463.849 µs) : 443, 485
.   : milestone, 464,
tracing (433.56 µs) : 412, 455
.   : milestone, 434,
section candidate
no_agent (364.431 µs) : 344, 385
.   : milestone, 364,
iast (465.361 µs) : 444, 487
.   : milestone, 465,
iast_FULL (524.278 µs) : 504, 545
.   : milestone, 524,
iast_INACTIVE (431.121 µs) : 411, 451
.   : milestone, 431,
iast_TELEMETRY_OFF (456.682 µs) : 436, 477
.   : milestone, 457,
tracing (437.081 µs) : 416, 458
.   : milestone, 437,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	370.876 µs [349.788 µs, 391.964 µs]	-
iast	465.558 µs [444.779 µs, 486.336 µs]	94.681 µs (25.5%)
iast_FULL	526.192 µs [505.697 µs, 546.688 µs]	155.316 µs (41.9%)
iast_INACTIVE	432.019 µs [411.29 µs, 452.748 µs]	61.143 µs (16.5%)
iast_TELEMETRY_OFF	463.849 µs [442.513 µs, 485.186 µs]	92.973 µs (25.1%)
tracing	433.56 µs [412.288 µs, 454.833 µs]	62.684 µs (16.9%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	364.431 µs [344.196 µs, 384.665 µs]	-
iast	465.361 µs [443.952 µs, 486.77 µs]	100.93 µs (27.7%)
iast_FULL	524.278 µs [503.723 µs, 544.834 µs]	159.848 µs (43.9%)
iast_INACTIVE	431.121 µs [410.922 µs, 451.32 µs]	66.69 µs (18.3%)
iast_TELEMETRY_OFF	456.682 µs [436.035 µs, 477.33 µs]	92.251 µs (25.3%)
tracing	437.081 µs [416.023 µs, 458.139 µs]	72.65 µs (19.9%)

mcculls · 2023-10-23T12:46:41Z

internal-api/src/main/java/datadog/trace/api/Resettable.java

+
+public interface Resettable {
+  void reset();
+}


I've added @bantonsson as he knows more about our embedded logger, but I wonder if it makes sense to add such a generic API for such a specific use.

You could instead add a method such as initialize or reset to LogLevelSwitcher and then use the existing GlobalLogLevelSwitcher to drive the reset of DDLoggerFactory. Alternatively you could create a new log-specific interface if you prefer it to be separate from LogLevelSwitcher, but follow a similar pattern.

Good point, I completely overlooked the LogLevelSwitcher interface. Added a new method there instead of Resettable.

… Resettable interface

Fix tracer logging when instrumenting Gradle Daemon

af9e570

nikita-tkachenko-datadog added type: bug comp: ci visibility Continuous Integration Visibility labels Oct 23, 2023

nikita-tkachenko-datadog marked this pull request as ready for review October 23, 2023 12:07

nikita-tkachenko-datadog requested review from a team as code owners October 23, 2023 12:07

nikita-tkachenko-datadog requested review from romainkomorndatadog, mcculls and am312 October 23, 2023 12:07

mcculls requested a review from bantonsson October 23, 2023 12:33

mcculls reviewed Oct 23, 2023

View reviewed changes

Add a new method to LogLevelSwitcher instead of introducing a generic…

3407cf2

… Resettable interface

romainkomorndatadog approved these changes Oct 24, 2023

View reviewed changes

bantonsson approved these changes Oct 25, 2023

View reviewed changes

nikita-tkachenko-datadog merged commit 9824b2e into master Oct 25, 2023
69 checks passed

nikita-tkachenko-datadog deleted the nikita-tkachenko/gradle-daemon-logging-fix branch October 25, 2023 08:50

github-actions bot added this to the 1.22.0 milestone Oct 25, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix tracer logging when instrumenting Gradle Daemon #6080

Fix tracer logging when instrumenting Gradle Daemon #6080

nikita-tkachenko-datadog commented Oct 23, 2023 •

edited

Loading

pr-commenter bot commented Oct 23, 2023 •

edited

Loading

mcculls Oct 23, 2023

nikita-tkachenko-datadog Oct 23, 2023

Fix tracer logging when instrumenting Gradle Daemon #6080

Fix tracer logging when instrumenting Gradle Daemon #6080

Conversation

nikita-tkachenko-datadog commented Oct 23, 2023 • edited Loading

What Does This Do

Motivation

pr-commenter bot commented Oct 23, 2023 • edited Loading

Benchmarks

Startup

Parameters

Summary

Load

Parameters

Summary

mcculls Oct 23, 2023

Choose a reason for hiding this comment

nikita-tkachenko-datadog Oct 23, 2023

Choose a reason for hiding this comment

nikita-tkachenko-datadog commented Oct 23, 2023 •

edited

Loading

pr-commenter bot commented Oct 23, 2023 •

edited

Loading