Flush on tracer close if CI Visibility enabled #6985

nikita-tkachenko-datadog · 2024-05-03T10:21:53Z

What Does This Do

Calls tracer flush when the tracer is closed if CI Visibility is enabled.

Motivation

Handling the following case:

a test starts, a corresponding span is created
before finishing, the test submits an async task that performs some cleanup work. A continuation is registered in the test's trace
the test finishes, its span finishes too, but is not written yet because of the pending async cleanup work

If this is the last test in the suite, after it finishes the JVM shutdown is initiated. A shutdown hook is run that closes the tracer. Following that the test's async cleanup may either fail to complete before JVM terminates or may complete after the tracer has been closed, which will result in discarding it.

Dropping a trace may be fine for APM products, but for CI Visibility it is a requirement that every test span is reported.

Doing a synchronous flush before tracer close will write all the pending traces. This includes traces with ROOT_BUFFERED status, i.e. the ones whose root has finished but whose children are pending (the test trace described above fits this case).

Jira ticket: CIVIS-9930

pr-commenter · 2024-05-06T19:49:20Z

Benchmarks

Startup

Load

Parameters

	Baseline	Candidate
baseline_or_candidate	baseline	candidate
end_time	2024-05-06T19:25:05	2024-05-06T19:31:53
git_branch	master	nikita-tkachenko/flush-traces-on-close
git_commit_date	1715022776	1714730279
git_commit_sha	`dd4d2fe`	`ec93bc5`
release_version	1.34.0-SNAPSHOT~dd4d2fee53	1.34.0-SNAPSHOT~ec93bc5cb9
start_time	2024-05-06T19:24:51	2024-05-06T19:31:40

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
ci_job_date	1715024258	1715024258
ci_job_id	505466685	505466685
ci_pipeline_id	33521871	33521871
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 13 metrics, 15 unstable metrics.

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.34.0-SNAPSHOT~ec93bc5cb9, baseline=1.34.0-SNAPSHOT~dd4d2fee53
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.325 ms) : 1306, 1344
.   : milestone, 1325,
appsec (1.736 ms) : 1712, 1759
.   : milestone, 1736,
appsec_no_iast (1.726 ms) : 1701, 1751
.   : milestone, 1726,
iast (1.475 ms) : 1452, 1497
.   : milestone, 1475,
profiling (1.514 ms) : 1490, 1537
.   : milestone, 1514,
tracing (1.455 ms) : 1430, 1481
.   : milestone, 1455,
section candidate
no_agent (1.345 ms) : 1325, 1365
.   : milestone, 1345,
appsec (1.718 ms) : 1693, 1743
.   : milestone, 1718,
appsec_no_iast (1.724 ms) : 1700, 1748
.   : milestone, 1724,
iast (1.486 ms) : 1464, 1509
.   : milestone, 1486,
profiling (1.499 ms) : 1474, 1523
.   : milestone, 1499,
tracing (1.48 ms) : 1455, 1505
.   : milestone, 1480,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.325 ms [1.306 ms, 1.344 ms]	-
appsec	1.736 ms [1.712 ms, 1.759 ms]	410.897 µs (31.0%)
appsec_no_iast	1.726 ms [1.701 ms, 1.751 ms]	401.128 µs (30.3%)
iast	1.475 ms [1.452 ms, 1.497 ms]	150.078 µs (11.3%)
profiling	1.514 ms [1.49 ms, 1.537 ms]	189.029 µs (14.3%)
tracing	1.455 ms [1.43 ms, 1.481 ms]	130.74 µs (9.9%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.345 ms [1.325 ms, 1.365 ms]	-
appsec	1.718 ms [1.693 ms, 1.743 ms]	373.059 µs (27.7%)
appsec_no_iast	1.724 ms [1.7 ms, 1.748 ms]	378.98 µs (28.2%)
iast	1.486 ms [1.464 ms, 1.509 ms]	141.663 µs (10.5%)
profiling	1.499 ms [1.474 ms, 1.523 ms]	153.894 µs (11.4%)
tracing	1.48 ms [1.455 ms, 1.505 ms]	135.192 µs (10.1%)

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.34.0-SNAPSHOT~ec93bc5cb9, baseline=1.34.0-SNAPSHOT~dd4d2fee53
    dateFormat X
    axisFormat %s
section baseline
no_agent (375.608 µs) : 356, 396
.   : milestone, 376,
iast (481.161 µs) : 461, 502
.   : milestone, 481,
iast_FULL (546.749 µs) : 526, 568
.   : milestone, 547,
iast_GLOBAL (501.923 µs) : 481, 523
.   : milestone, 502,
iast_HARDCODED_SECRET_DISABLED (472.58 µs) : 452, 493
.   : milestone, 473,
iast_INACTIVE (458.942 µs) : 438, 480
.   : milestone, 459,
iast_TELEMETRY_OFF (474.535 µs) : 454, 495
.   : milestone, 475,
tracing (453.648 µs) : 432, 475
.   : milestone, 454,
section candidate
no_agent (368.998 µs) : 349, 389
.   : milestone, 369,
iast (478.898 µs) : 458, 500
.   : milestone, 479,
iast_FULL (549.321 µs) : 529, 570
.   : milestone, 549,
iast_GLOBAL (500.911 µs) : 481, 521
.   : milestone, 501,
iast_HARDCODED_SECRET_DISABLED (479.005 µs) : 458, 500
.   : milestone, 479,
iast_INACTIVE (459.269 µs) : 438, 480
.   : milestone, 459,
iast_TELEMETRY_OFF (472.553 µs) : 451, 494
.   : milestone, 473,
tracing (448.488 µs) : 428, 469
.   : milestone, 448,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	375.608 µs [355.567 µs, 395.648 µs]	-
iast	481.161 µs [460.561 µs, 501.761 µs]	105.554 µs (28.1%)
iast_FULL	546.749 µs [525.908 µs, 567.589 µs]	171.141 µs (45.6%)
iast_GLOBAL	501.923 µs [481.152 µs, 522.694 µs]	126.315 µs (33.6%)
iast_HARDCODED_SECRET_DISABLED	472.58 µs [452.386 µs, 492.774 µs]	96.972 µs (25.8%)
iast_INACTIVE	458.942 µs [437.578 µs, 480.306 µs]	83.334 µs (22.2%)
iast_TELEMETRY_OFF	474.535 µs [453.635 µs, 495.434 µs]	98.927 µs (26.3%)
tracing	453.648 µs [432.373 µs, 474.922 µs]	78.04 µs (20.8%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	368.998 µs [348.845 µs, 389.152 µs]	-
iast	478.898 µs [458.18 µs, 499.615 µs]	109.899 µs (29.8%)
iast_FULL	549.321 µs [528.558 µs, 570.084 µs]	180.322 µs (48.9%)
iast_GLOBAL	500.911 µs [480.562 µs, 521.259 µs]	131.912 µs (35.7%)
iast_HARDCODED_SECRET_DISABLED	479.005 µs [457.715 µs, 500.295 µs]	110.006 µs (29.8%)
iast_INACTIVE	459.269 µs [438.08 µs, 480.458 µs]	90.271 µs (24.5%)
iast_TELEMETRY_OFF	472.553 µs [451.308 µs, 493.799 µs]	103.555 µs (28.1%)
tracing	448.488 µs [427.815 µs, 469.162 µs]	79.49 µs (21.5%)

Dacapo

Parameters

	Baseline	Candidate
baseline_or_candidate	baseline	candidate
git_branch	master	nikita-tkachenko/flush-traces-on-close
git_commit_date	1715022776	1714730279
git_commit_sha	`dd4d2fe`	`ec93bc5`
release_version	1.34.0-SNAPSHOT~dd4d2fee53	1.34.0-SNAPSHOT~ec93bc5cb9

See matching parameters

	Baseline	Candidate
application	biojava	biojava
ci_job_date	1715024789	1715024789
ci_job_id	505466690	505466690
ci_pipeline_id	33521871	33521871
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 12 metrics, 0 unstable metrics.

Execution time for tomcat

gantt
    title tomcat - execution time [CI 0.99] : candidate=1.34.0-SNAPSHOT~ec93bc5cb9, baseline=1.34.0-SNAPSHOT~dd4d2fee53
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.47 ms) : 1458, 1482
.   : milestone, 1470,
appsec (2.204 ms) : 2170, 2237
.   : milestone, 2204,
iast (1.875 ms) : 1840, 1910
.   : milestone, 1875,
iast_GLOBAL (1.907 ms) : 1872, 1941
.   : milestone, 1907,
profiling (1.835 ms) : 1802, 1868
.   : milestone, 1835,
tracing (1.835 ms) : 1803, 1867
.   : milestone, 1835,
section candidate
no_agent (1.471 ms) : 1459, 1482
.   : milestone, 1471,
appsec (2.222 ms) : 2187, 2256
.   : milestone, 2222,
iast (1.881 ms) : 1846, 1916
.   : milestone, 1881,
iast_GLOBAL (1.925 ms) : 1889, 1960
.   : milestone, 1925,
profiling (1.834 ms) : 1801, 1868
.   : milestone, 1834,
tracing (1.833 ms) : 1801, 1865
.   : milestone, 1833,

baseline results

Variant	Execution Time [CI 0.99]	Δ no_agent
no_agent	1.47 ms [1.458 ms, 1.482 ms]	-
appsec	2.204 ms [2.17 ms, 2.237 ms]	733.604 µs (49.9%)
iast	1.875 ms [1.84 ms, 1.91 ms]	405.431 µs (27.6%)
iast_GLOBAL	1.907 ms [1.872 ms, 1.941 ms]	436.788 µs (29.7%)
profiling	1.835 ms [1.802 ms, 1.868 ms]	364.855 µs (24.8%)
tracing	1.835 ms [1.803 ms, 1.867 ms]	365.456 µs (24.9%)

candidate results

Variant	Execution Time [CI 0.99]	Δ no_agent
no_agent	1.471 ms [1.459 ms, 1.482 ms]	-
appsec	2.222 ms [2.187 ms, 2.256 ms]	750.726 µs (51.0%)
iast	1.881 ms [1.846 ms, 1.916 ms]	410.088 µs (27.9%)
iast_GLOBAL	1.925 ms [1.889 ms, 1.96 ms]	453.923 µs (30.9%)
profiling	1.834 ms [1.801 ms, 1.868 ms]	363.665 µs (24.7%)
tracing	1.833 ms [1.801 ms, 1.865 ms]	362.11 µs (24.6%)

Execution time for biojava

gantt
    title biojava - execution time [CI 0.99] : candidate=1.34.0-SNAPSHOT~ec93bc5cb9, baseline=1.34.0-SNAPSHOT~dd4d2fee53
    dateFormat X
    axisFormat %s
section baseline
no_agent (15.37 s) : 15370000, 15370000
.   : milestone, 15370000,
appsec (15.031 s) : 15031000, 15031000
.   : milestone, 15031000,
iast (18.666 s) : 18666000, 18666000
.   : milestone, 18666000,
iast_GLOBAL (17.794 s) : 17794000, 17794000
.   : milestone, 17794000,
profiling (15.41 s) : 15410000, 15410000
.   : milestone, 15410000,
tracing (14.978 s) : 14978000, 14978000
.   : milestone, 14978000,
section candidate
no_agent (15.364 s) : 15364000, 15364000
.   : milestone, 15364000,
appsec (15.171 s) : 15171000, 15171000
.   : milestone, 15171000,
iast (18.491 s) : 18491000, 18491000
.   : milestone, 18491000,
iast_GLOBAL (17.89 s) : 17890000, 17890000
.   : milestone, 17890000,
profiling (14.885 s) : 14885000, 14885000
.   : milestone, 14885000,
tracing (15.298 s) : 15298000, 15298000
.   : milestone, 15298000,

baseline results

Variant	Execution Time [CI 0.99]	Δ no_agent
no_agent	15.37 s [15.37 s, 15.37 s]	-
appsec	15.031 s [15.031 s, 15.031 s]	-339.0 ms (-2.2%)
iast	18.666 s [18.666 s, 18.666 s]	3.296 s (21.4%)
iast_GLOBAL	17.794 s [17.794 s, 17.794 s]	2.424 s (15.8%)
profiling	15.41 s [15.41 s, 15.41 s]	40.0 ms (0.3%)
tracing	14.978 s [14.978 s, 14.978 s]	-392.0 ms (-2.6%)

candidate results

Variant	Execution Time [CI 0.99]	Δ no_agent
no_agent	15.364 s [15.364 s, 15.364 s]	-
appsec	15.171 s [15.171 s, 15.171 s]	-193.0 ms (-1.3%)
iast	18.491 s [18.491 s, 18.491 s]	3.127 s (20.4%)
iast_GLOBAL	17.89 s [17.89 s, 17.89 s]	2.526 s (16.4%)
profiling	14.885 s [14.885 s, 14.885 s]	-479.0 ms (-3.1%)
tracing	15.298 s [15.298 s, 15.298 s]	-66.0 ms (-0.4%)

Flush on tracer close if CI Visibility enabled

ec93bc5

nikita-tkachenko-datadog added type: bug comp: ci visibility Continuous Integration Visibility labels May 3, 2024

nikita-tkachenko-datadog marked this pull request as ready for review May 3, 2024 14:10

nikita-tkachenko-datadog requested a review from a team as a code owner May 3, 2024 14:10

nikita-tkachenko-datadog requested review from mcculls and nayeem-kamal May 3, 2024 14:10

mcculls approved these changes May 6, 2024

View reviewed changes

nikita-tkachenko-datadog merged commit 57be325 into master May 6, 2024
82 checks passed

nikita-tkachenko-datadog deleted the nikita-tkachenko/flush-traces-on-close branch May 6, 2024 20:26

github-actions bot added this to the 1.34.0 milestone May 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flush on tracer close if CI Visibility enabled #6985

Flush on tracer close if CI Visibility enabled #6985

nikita-tkachenko-datadog commented May 3, 2024 •

edited

Loading

pr-commenter bot commented May 6, 2024

Flush on tracer close if CI Visibility enabled #6985

Flush on tracer close if CI Visibility enabled #6985

Conversation

nikita-tkachenko-datadog commented May 3, 2024 • edited Loading

What Does This Do

Motivation

pr-commenter bot commented May 6, 2024

Benchmarks

Startup

Load

Parameters

Summary

Dacapo

Parameters

Summary

nikita-tkachenko-datadog commented May 3, 2024 •

edited

Loading