search

newrelic / newrelic-java-agent

The New Relic Java agent
Apache License 2.0
196 stars 139 forks source link

Investigate HTTP/2 support with Netty/Vert.x #1945

Open jasonjkeller opened 3 weeks ago

jasonjkeller commented 3 weeks ago

This is a follow-on story to https://github.com/newrelic/newrelic-java-agent/pull/1815 (also loosely related to https://github.com/newrelic/newrelic-java-agent/issues/1799).

It was reported that the previous PR does not seem to address all cases and that there are still scenarios where HTTP/1 requests result in transaction whereas HTTP/2 requests do not. Upon further investigation it appears that Vert.x may be playing a roll in the missing HTTP/2 requests.

We should see if the instrumentation gap can be identified and addressed such that these HTTP/2 requests result in transactions being reported to NR.

workato-integration[bot] commented 3 weeks ago

https://new-relic.atlassian.net/browse/NR-280530

jasonjkeller commented 3 weeks ago

While examining the affected service, I found that the following HTTP/2 related Vert.x and Netty classes were being weaved:

Supportability/WeaveInstrumentation/WeaveClass/com.newrelic.instrumentation.netty-4.1.16/io/vertx/core/http/impl/VertxHttp2ConnectionHandler
Supportability/WeaveInstrumentation/WeaveClass/com.newrelic.instrumentation.netty-4.1.16/io/netty/handler/codec/http2/Http2ConnectionHandler

Following that lead I spun up an example HTTP/2 app using Vert.x & Netty that had similar symptoms; the same endpoint had transactions when using HTTP/1 but not HTTP/2.

Weaving io.vertx.core.http.impl.Http2ServerConnection in the Vert.x instrumentation (which already weaves io.vertx.core.http.impl.Http1xServerConnection for HTTP/1 requests) results in transactions being reported for HTTP/2 requests.

However, the transactions are named slightly differently as the transaction is actually by the Netty instrumentation for HTTP/1 (when we weave HttpObjectDecoder) but for HTTP/2 the transaction is started later by the Vert.x instrumentation (when we weave Http2ServerConnection). So far there is no obvious HTTP/2 Netty decoder that can be weaved to start the transaction earlier (there are challenges with weaving Http2ConnectionHandler$FrameDecoder). Ultimately this may be acceptable.

Debugging the repro app shows the following.

When making the HTTP/1 requests:

channelRead:52, NettyDispatcher (io.netty.bootstrap)
decode:461, HttpObjectDecoder (io.netty.handler.codec.http) // diverges here, netty instrumentation starts a txn here for HTTP/1
decodeRemovalReentryProtection:529, ByteToMessageDecoder (io.netty.handler.codec)
callDecode:468, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:290, ByteToMessageDecoder (io.netty.handler.codec)
invokeChannelRead:444, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1410, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:440, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:919, DefaultChannelPipeline (io.netty.channel)
read:166, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:788, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:724, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:650, NioEventLoop (io.netty.channel.nio)
run:562, NioEventLoop (io.netty.channel.nio)
run:997, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:829, Thread (java.lang)

When making the HTTP/2 requests:

handle:130, VertxUtil$1 (com.nr.vertx.instrumentation)
handle:126, VertxUtil$1 (com.nr.vertx.instrumentation) // txn has to be started in netty before here, or vertx instrumentation will start it here for HTTP/2
emit:335, ContextImpl (io.vertx.core.impl)
emit:176, DuplicatedContext (io.vertx.core.impl)
dispatch:108, Http2ServerRequest (io.vertx.core.http.impl)
onHeaders:116, Http2ServerStream (io.vertx.core.http.impl)
onHeadersRead:183, Http2ServerConnection (io.vertx.core.http.impl)
onHeadersRead:208, Http2ConnectionBase (io.vertx.core.http.impl)
onHeadersRead:44, Http2ServerConnection (io.vertx.core.http.impl) // weaving this class in vertx instrumentation will allow us to start a transaction for HTTP/2
onHeadersRead:48, Http2FrameListenerDecorator (io.netty.handler.codec.http2)
onHeadersRead:48, Http2FrameListenerDecorator (io.netty.handler.codec.http2)
onHeadersRead:63, Http2EmptyDataFrameListener (io.netty.handler.codec.http2)
onHeadersRead:409, DefaultHttp2ConnectionDecoder$FrameReadListener (io.netty.handler.codec.http2)
processFragment:450, DefaultHttp2FrameReader$1 (io.netty.handler.codec.http2)
readHeadersFrame:457, DefaultHttp2FrameReader (io.netty.handler.codec.http2)
processPayloadState:253, DefaultHttp2FrameReader (io.netty.handler.codec.http2)
readFrame:159, DefaultHttp2FrameReader (io.netty.handler.codec.http2)
decodeFrame:173, DefaultHttp2ConnectionDecoder (io.netty.handler.codec.http2)
decodeFrame:63, DecoratingHttp2ConnectionDecoder (io.netty.handler.codec.http2)
decodeFrame:63, DecoratingHttp2ConnectionDecoder (io.netty.handler.codec.http2)
decode:393, Http2ConnectionHandler$FrameDecoder (io.netty.handler.codec.http2) // different unsupported netty decoder, netty instrumentation does not start a txn in this case
decode:453, Http2ConnectionHandler (io.netty.handler.codec.http2)
decodeRemovalReentryProtection:529, ByteToMessageDecoder (io.netty.handler.codec)
callDecode:468, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:290, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:415, VertxHttp2ConnectionHandler (io.vertx.core.http.impl)
invokeChannelRead:444, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
unwrap:1471, SslHandler (io.netty.handler.ssl)
decodeJdkCompatible:1334, SslHandler (io.netty.handler.ssl)
decode:1383, SslHandler (io.netty.handler.ssl) // diverges here
decodeRemovalReentryProtection:529, ByteToMessageDecoder (io.netty.handler.codec)
callDecode:468, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:290, ByteToMessageDecoder (io.netty.handler.codec)
invokeChannelRead:444, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1410, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:440, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:919, DefaultChannelPipeline (io.netty.channel)
read:166, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:788, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:724, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:650, NioEventLoop (io.netty.channel.nio)
run:562, NioEventLoop (io.netty.channel.nio)
run:997, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:829, Thread (java.lang)