Fix for Vert.x 4.0 instrumentation to close span on timeout#5772
Merged
Conversation
BenchmarksStartupParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 62 cases. Startup time reports for insecure-bankgantt
title insecure-bank - global startup overhead: candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (985.962 ms) : 0, 985962
Total [baseline] (8.638 s) : 0, 8637758
Agent [candidate] (990.252 ms) : 0, 990252
Total [candidate] (8.643 s) : 0, 8642902
section appsec
Agent [baseline] (1.073 s) : 0, 1072679
Total [baseline] (8.729 s) : 0, 8728677
Agent [candidate] (1.081 s) : 0, 1080926
Total [candidate] (8.712 s) : 0, 8712162
section iast
Agent [baseline] (1.1 s) : 0, 1100257
Total [baseline] (9.169 s) : 0, 9168704
Agent [candidate] (1.091 s) : 0, 1091148
Total [candidate] (9.168 s) : 0, 9167520
section profiling
Agent [baseline] (1.17 s) : 0, 1170410
Total [baseline] (8.909 s) : 0, 8908984
Agent [candidate] (1.159 s) : 0, 1158910
Total [candidate] (8.877 s) : 0, 8876951
gantt
title insecure-bank - break down per module: candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section tracing
BytebuddyAgent [baseline] (611.528 ms) : 0, 611528
BytebuddyAgent [candidate] (613.278 ms) : 0, 613278
GlobalTracer [baseline] (283.286 ms) : 0, 283286
GlobalTracer [candidate] (285.636 ms) : 0, 285636
AppSec [baseline] (50.117 ms) : 0, 50117
AppSec [candidate] (50.306 ms) : 0, 50306
Remote Config [baseline] (667.852 µs) : 0, 668
Remote Config [candidate] (657.241 µs) : 0, 657
Telemetry [baseline] (6.036 ms) : 0, 6036
Telemetry [candidate] (5.976 ms) : 0, 5976
section appsec
BytebuddyAgent [baseline] (612.575 ms) : 0, 612575
BytebuddyAgent [candidate] (617.425 ms) : 0, 617425
GlobalTracer [baseline] (284.012 ms) : 0, 284012
GlobalTracer [candidate] (286.942 ms) : 0, 286942
AppSec [baseline] (135.271 ms) : 0, 135271
AppSec [candidate] (135.523 ms) : 0, 135523
Remote Config [baseline] (721.567 µs) : 0, 722
Remote Config [candidate] (731.99 µs) : 0, 732
Telemetry [baseline] (5.758 ms) : 0, 5758
Telemetry [candidate] (5.786 ms) : 0, 5786
section iast
BytebuddyAgent [baseline] (724.615 ms) : 0, 724615
BytebuddyAgent [candidate] (718.841 ms) : 0, 718841
GlobalTracer [baseline] (272.787 ms) : 0, 272787
GlobalTracer [candidate] (270.699 ms) : 0, 270699
AppSec [baseline] (47.781 ms) : 0, 47781
AppSec [candidate] (47.143 ms) : 0, 47143
Remote Config [baseline] (558.482 µs) : 0, 558
Remote Config [candidate] (538.071 µs) : 0, 538
Telemetry [baseline] (5.786 ms) : 0, 5786
Telemetry [candidate] (5.67 ms) : 0, 5670
IAST [baseline] (14.05 ms) : 0, 14050
IAST [candidate] (13.823 ms) : 0, 13823
section profiling
BytebuddyAgent [baseline] (632.961 ms) : 0, 632961
BytebuddyAgent [candidate] (626.513 ms) : 0, 626513
GlobalTracer [baseline] (348.892 ms) : 0, 348892
GlobalTracer [candidate] (346.775 ms) : 0, 346775
AppSec [baseline] (49.557 ms) : 0, 49557
AppSec [candidate] (48.933 ms) : 0, 48933
Remote Config [baseline] (655.57 µs) : 0, 656
Remote Config [candidate] (650.582 µs) : 0, 651
Telemetry [baseline] (6.095 ms) : 0, 6095
Telemetry [candidate] (6.013 ms) : 0, 6013
ProfilingAgent [baseline] (78.597 ms) : 0, 78597
ProfilingAgent [candidate] (77.019 ms) : 0, 77019
Profiling [baseline] (78.621 ms) : 0, 78621
Profiling [candidate] (77.044 ms) : 0, 77044
Startup time reports for petclinicgantt
title petclinic - global startup overhead: candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (989.12 ms) : 0, 989120
Total [baseline] (9.164 s) : 0, 9164214
Agent [candidate] (988.445 ms) : 0, 988445
Total [candidate] (9.191 s) : 0, 9190666
section appsec
Agent [baseline] (1.085 s) : 0, 1085414
Total [baseline] (9.349 s) : 0, 9348851
Agent [candidate] (1.075 s) : 0, 1075386
Total [candidate] (9.268 s) : 0, 9267615
section iast
Agent [baseline] (1.097 s) : 0, 1096543
Total [baseline] (9.449 s) : 0, 9449034
Agent [candidate] (1.09 s) : 0, 1090322
Total [candidate] (9.457 s) : 0, 9456964
section profiling
Agent [baseline] (1.157 s) : 0, 1157002
Total [baseline] (9.432 s) : 0, 9431913
Agent [candidate] (1.162 s) : 0, 1161686
Total [candidate] (9.507 s) : 0, 9506790
gantt
title petclinic - break down per module: candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section tracing
BytebuddyAgent [baseline] (613.266 ms) : 0, 613266
BytebuddyAgent [candidate] (612.767 ms) : 0, 612767
GlobalTracer [baseline] (284.974 ms) : 0, 284974
GlobalTracer [candidate] (284.871 ms) : 0, 284871
AppSec [baseline] (49.861 ms) : 0, 49861
AppSec [candidate] (49.928 ms) : 0, 49928
Remote Config [baseline] (661.449 µs) : 0, 661
Remote Config [candidate] (662.438 µs) : 0, 662
Telemetry [baseline] (5.974 ms) : 0, 5974
Telemetry [candidate] (5.951 ms) : 0, 5951
section appsec
BytebuddyAgent [baseline] (620.277 ms) : 0, 620277
BytebuddyAgent [candidate] (614.263 ms) : 0, 614263
GlobalTracer [baseline] (287.91 ms) : 0, 287910
GlobalTracer [candidate] (285.383 ms) : 0, 285383
AppSec [baseline] (135.912 ms) : 0, 135912
AppSec [candidate] (134.862 ms) : 0, 134862
Remote Config [baseline] (725.717 µs) : 0, 726
Remote Config [candidate] (725.088 µs) : 0, 725
Telemetry [baseline] (5.825 ms) : 0, 5825
Telemetry [candidate] (5.742 ms) : 0, 5742
section iast
BytebuddyAgent [baseline] (722.923 ms) : 0, 722923
BytebuddyAgent [candidate] (718.085 ms) : 0, 718085
GlobalTracer [baseline] (271.361 ms) : 0, 271361
GlobalTracer [candidate] (270.396 ms) : 0, 270396
AppSec [baseline] (47.556 ms) : 0, 47556
AppSec [candidate] (47.365 ms) : 0, 47365
Remote Config [baseline] (549.161 µs) : 0, 549
Remote Config [candidate] (546.627 µs) : 0, 547
Telemetry [baseline] (5.709 ms) : 0, 5709
Telemetry [candidate] (5.671 ms) : 0, 5671
IAST [baseline] (13.88 ms) : 0, 13880
IAST [candidate] (13.869 ms) : 0, 13869
section profiling
BytebuddyAgent [baseline] (625.382 ms) : 0, 625382
BytebuddyAgent [candidate] (627.914 ms) : 0, 627914
GlobalTracer [baseline] (345.311 ms) : 0, 345311
GlobalTracer [candidate] (347.775 ms) : 0, 347775
AppSec [baseline] (48.997 ms) : 0, 48997
AppSec [candidate] (49.232 ms) : 0, 49232
Remote Config [baseline] (647.153 µs) : 0, 647
Remote Config [candidate] (649.33 µs) : 0, 649
Telemetry [baseline] (5.923 ms) : 0, 5923
Telemetry [candidate] (6.071 ms) : 0, 6071
ProfilingAgent [baseline] (77.856 ms) : 0, 77856
ProfilingAgent [candidate] (76.956 ms) : 0, 76956
Profiling [baseline] (77.881 ms) : 0, 77881
Profiling [candidate] (76.98 ms) : 0, 76980
LoadParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 24 cases. Request duration reports for insecure-bankgantt
title insecure-bank - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section baseline
no_agent (355.3 µs) : 336, 375
. : milestone, 355,
appsec (655.453 µs) : 635, 676
. : milestone, 655,
iast (455.206 µs) : 434, 476
. : milestone, 455,
iast_FULL (515.132 µs) : 495, 535
. : milestone, 515,
iast_INACTIVE (430.76 µs) : 409, 452
. : milestone, 431,
profiling (449.8 µs) : 428, 471
. : milestone, 450,
tracing (435.184 µs) : 415, 456
. : milestone, 435,
section candidate
no_agent (359.981 µs) : 340, 380
. : milestone, 360,
appsec (657.763 µs) : 637, 679
. : milestone, 658,
iast (452.097 µs) : 432, 472
. : milestone, 452,
iast_FULL (513.921 µs) : 494, 534
. : milestone, 514,
iast_INACTIVE (429.863 µs) : 409, 451
. : milestone, 430,
profiling (449.79 µs) : 428, 471
. : milestone, 450,
tracing (424.191 µs) : 403, 445
. : milestone, 424,
Request duration reports for petclinicgantt
title petclinic - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~b9895fbd35, baseline=1.20.0-SNAPSHOT~199de1b8ea
dateFormat X
axisFormat %s
section baseline
no_agent (1.355 ms) : 1335, 1375
. : milestone, 1355,
appsec (1.673 ms) : 1649, 1698
. : milestone, 1673,
iast (1.454 ms) : 1429, 1478
. : milestone, 1454,
profiling (1.455 ms) : 1431, 1480
. : milestone, 1455,
tracing (1.426 ms) : 1402, 1451
. : milestone, 1426,
section candidate
no_agent (1.339 ms) : 1321, 1358
. : milestone, 1339,
appsec (1.684 ms) : 1660, 1709
. : milestone, 1684,
iast (1.428 ms) : 1404, 1453
. : milestone, 1428,
profiling (1.45 ms) : 1425, 1475
. : milestone, 1450,
tracing (1.457 ms) : 1432, 1481
. : milestone, 1457,
|
bantonsson
approved these changes
Aug 24, 2023
bantonsson
left a comment
bantonsson
left a comment
Contributor
There was a problem hiding this comment.
👍🏻 Would like some clarification around the long test timeouts.
| .send(msg) | ||
| } | ||
| prefix("/timeout") { | ||
| Thread.sleep(10_000) |
Contributor
There was a problem hiding this comment.
Do we have to wait for 10 seconds? Could we make the timeouts shorter in the tests?
Contributor
Author
There was a problem hiding this comment.
No, we don't have to wait. The whole point for this endpoint is to prevent it responding. The client is supposed to cancel it earlier in this case it's 1s. Unless test is incorrect and the client doesn't cancel within shorter interval then it will wait for at max 10 seconds and then fail.
| @Advice.FieldValue("stream") final HttpClientStream stream, | ||
| @Advice.Return(readOnly = false) boolean result) { | ||
| if (result) { | ||
| AttributeKey<AgentSpan> spanAttr = AttributeKey.valueOf(DD_SPAN_ATTRIBUTE); |
Contributor
There was a problem hiding this comment.
It is probably ok get the attribute key directly here in a vertx setting, but there have been issues with the AttributeKey class being loaded in multiple class loaders leading to confusing results. See AttributeKeys
Contributor
Author
There was a problem hiding this comment.
Hmm, interesting. Would be interesting to know more about possible issues. From what I can see AbstractConstant implementation if there are two AttributeKeys from different class loaders they won't be treated the same key. I didn't notice any issues with Vert.x use case. In the worst case scenario with Vert.x it won't be able to set an error on the span but the span will still be finished by Netty instrumentation.
Actually, I think I can reuse netty41.AttributeKeys. Will push this change to this PR.
| } | ||
|
|
||
| @Override | ||
| public void channelInactive(ChannelHandlerContext ctx) throws Exception { |
Contributor
There was a problem hiding this comment.
I guess this is to ensure that the netty versions behave the same, since vertx seem to need netty 4.1.
Contributor
Author
There was a problem hiding this comment.
Correct, Vert.x uses Netty 4.1. I added this for Netty 4.0 too just because there might be a similar to Vert.x case leading to an unfinished span. Making sure we finish it here will potentially prevent this type of an issue.
bantonsson
reviewed
Aug 24, 2023
Contributor
There was a problem hiding this comment.
Does this need to be declared as a helper class here as well?
Contributor
Author
There was a problem hiding this comment.
Yep, otherwise it'll fail at muzzle check
…ttp client request span
ygree
force-pushed
the
ygree/vertx-client-timeout-handling
branch
from
August 24, 2023 16:27
f1870fb to
b9895fb
Compare
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What Does This Do
Fix for an issue with Vert.x HTTP timed out client requests. It was keeping a request span unfinished.
Vert.x uses Netty under the hood. Netty instrumentation already has timeout handling but turns out that Vert.x has its own timeout handling that have not been covered with instrumentation.
There are two main pieces. First, closing a span in Netty instrumentation in case of the
channelInactiveevent. Second, decorating a span on Vert.x instrumentation side with the original exception, so it's clear that the request has been timed out.Motivation
A client reported issue about created but never finished client http spans in case of timeout.
Additional Notes
Example of a timed out span:
[ { "service": "service-name", "name": "netty.client.request", "resource": "GET /?", "trace_id": "2178227018975193174", "span_id": "7989050593220702817", "parent_id": 0, "start": "1692834467128191917", "duration": 1017764708, "type": "http", "error": 1, "metrics": { "_sampling_priority_v1": 1, "_dd.measured": 1, "_dd.top_level": 1, "thread.id": 27, "process_id": 55085, "_dd.profiling.enabled": 0, "_dd.agent_psr": 1, "peer.port": 80, "_dd.trace_span_attribute_schema": 0 }, "meta": { "_dd.p.dm": "-1", "thread.name": "vert.x-eventloop-thread-0", "http.url": "http://httpstat.us/200", "language": "jvm", "env": "local-test", "version": "1", "peer.ipv4": "20.40.202.3", "component": "netty-client", "error.type": "io.vertx.core.http.impl.NoStackTraceTimeoutException", "span.kind": "client", "error.message": "The timeout period of 1000ms has been exceeded while executing GET /200?sleep=2000 for server httpstat.us:80", "error.stack": "io.vertx.core.http.impl.NoStackTraceTimeoutException: The timeout period of 1000ms has been exceeded while executing GET /200?sleep=2000 for server httpstat.us:80\n", "runtime-id": "aaf5dacb-af13-449d-a82d-9d7bd45422b8", "peer.hostname": "httpstat.us", "http.method": "GET" } } ]