Guard debug logs in pollPooledChannel by pavel-ptashyts · Pull Request #2300 · AsyncHttpClient/async-http-client

pavel-ptashyts · 2026-08-03T12:49:37Z

Problem

NettyRequestSender.pollPooledChannel runs on every request. Four of its
log statements pass three arguments:

LOGGER.debug("Using pooled Channel '{}' for '{}' to '{}'", channel, request.getMethod(), uri);

SLF4J's Logger declares overloads for one and two arguments only, so a
three-argument call binds to debug(String, Object...) and the compiler
emits the Object[3] at the call site. The array is therefore allocated
before debug is entered, whatever the configured level — the placeholder
mechanism only defers formatting, not argument boxing.

Both pooled-channel branches are the steady-state keep-alive path, so a
client logging at INFO or above allocated one throwaway array per served
request.

Change

Wrap the four statements in isDebugEnabled().

sendRequestWithOpenChannel a few lines up already guards its own
three-argument statement, so the shape is not new to this file. Its guard
does a little more than avoid the array, though: it also hoists
future.getNettyRequest().getHttpRequest() inside the branch, so two method
calls are skipped as well. The precedent stands, the reasoning there is just
wider than it is here.

Scope

Deliberately limited to pollPooledChannel. The same pattern exists in a
few colder places (TimeoutTimerTask, the GOAWAY handler, the orphan-channel
branch in AsyncHttpClientHandler); those are not per-request and are left
alone to keep this focused.

No public API change. No new tests: this is an allocation removal with no
observable behaviour change, and the existing suite covers both branches
(ConnectionPoolTest, MaxTotalConnectionTest, ClientStatsTest).

Verification

mvnw clean verify — BUILD SUCCESS, 1371 tests, 0 failures, 0 errors,
19 skipped. Error Prone, NullAway and Revapi all clean.

Caveat on the testing gate: AGENTS.md requires the build to run on JDK 11
and no JDK 11 is installed on this machine, so it was run on JDK 17
(also in the CI matrix). The JDK 11 leg of CI on this PR is the real gate.

Claude Code on behalf of @pavel-ptashyts

🤖 Generated with Claude Code

SLF4J's Logger has overloads for one and two arguments only, so the four log statements in pollPooledChannel bind to debug(String, Object...) and build their varargs Object[3] at the call site regardless of whether debug is enabled. pollPooledChannel runs on every request, and its two pooled-channel branches are the steady-state keep-alive path, so this allocated an array per served request in production configurations that log at INFO or above. Wrap the calls in isDebugEnabled(), matching what sendRequestWithOpenChannel already does for its own three-argument statement a few lines up. Behaviour when debug logging is enabled is unchanged. Claude Code on behalf of Pavel Ptashyts Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

hyperxpro · 2026-08-03T19:54:46Z

+                    // SLF4J has no three-argument overload, so every log statement in this method binds to
+                    // debug(String, Object...) and allocates its varargs array at the call site whatever the
+                    // level. This is the steady-state connection-reuse path, so guard them all explicitly.


This explains all four guards but it is buried in the deepest branch of the method. Can it move up above the override check, so it is visible from the path most requests actually take?

Also "every log statement in this method" is not quite right, the error call at the top binds to the Throwable overload and never allocates. Every debug statement would be accurate.

Both fixed. The note sits at the top of the method now, right next to the values these statements log, so it is on the path whichever branch you follow.

And you are right about the wording: the onConnectionPoolAttempt failure binds to error(String, Throwable) and allocates nothing, so it is every debug statement, not every log statement. Reworded.

hyperxpro · 2026-08-03T19:54:46Z

        final Channel channel = channelManager.poll(partitionKey);

-        if (channel != null) {
+        if (channel != null && LOGGER.isDebugEnabled()) {


This is the common path and there is nothing here saying why the guard exists. Moving the comment up would cover it.

Same move covers this one. The note is above the override branch now, so it reads before either poll.

hyperxpro · 2026-08-03T19:54:46Z

+                    // SLF4J has no three-argument overload, so every log statement in this method binds to
+                    // debug(String, Object...) and allocates its varargs array at the call site whatever the
+                    // level. This is the steady-state connection-reuse path, so guard them all explicitly.
+                    if (LOGGER.isDebugEnabled()) {


Small correction to the description: the guard in sendRequestWithOpenChannel also hoists getNettyRequest().getHttpRequest() inside the branch, so it is not purely about the varargs array. The precedent stands, the reasoning is just a bit wider there.

Corrected in the description. It hoists getNettyRequest().getHttpRequest() into the branch as well, so two calls are skipped on top of the array. The precedent still holds, the reasoning there is just wider than here.

Review feedback on AsyncHttpClient#2300. The note explaining why all four debug statements are guarded sat in the deepest branch of pollPooledChannel, where a reader following the path most requests take never passes it. Move it to the top of the method, next to the values the statements log. It also claimed "every log statement in this method", which is wrong: the onConnectionPoolAttempt failure at the top binds to error(String, Throwable) and allocates nothing. Say debug statement. Claude Code on behalf of Pavel Ptashyts Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

@pavel-ptashyts

## Problem `Interceptors.exitAfterIntercept` runs for every HTTP response and tested the redirect status like this: ```java if (Redirect30xInterceptor.REDIRECT_STATUSES.contains(statusCode)) { ``` `REDIRECT_STATUSES` is a `Set<Integer>` and `statusCode` is an `int`, so the call autoboxes. `Integer.valueOf` caches -128..127, which covers 100..103 but nothing else a response carries, so every 2xx / 4xx / 5xx response allocated a fresh `Integer` and hashed it, only to answer `false`. Those are almost all of the traffic. ## Change Move the test into a package-private `Redirect30xInterceptor.isRedirect(int)`, next to the set it guards, and gate the set lookup behind Netty's `HttpStatusClass.REDIRECTION.contains(int)`. That check takes a primitive, so only a genuine 3xx pays for the boxing. The set is still consulted rather than inlined as a `switch` over the five known codes. `REDIRECT_STATUSES` is `public` and a mutable `HashSet`; changing what it means is out of scope for a performance change, so any 3xx a caller registered keeps working. Behaviour differs only for a non-3xx code added to the set, which would not be a redirect status. No public API change. ## Scope One predicate, its two call sites, and a unit test. Related per-response allocations found in the same method (`responseHeaders.getAll(SET_COOKIE)` allocates a `LinkedList` per response even with no `Set-Cookie` present) are left for a separate PR. ## Tests `Redirect30xInterceptorTest` covers `isRedirect(int)` directly: the five followed statuses, the 3xx that are not followed (300, 304, 305, 306, 399 - 304 above all, which must reach the normal response path), and non-3xx codes. The redirect paths themselves are already covered by `Relative302Test`, `PerRequestRelative302Test`, `PostRedirectGetTest`, `RedirectBodyTest`, `HttpToHttpsRedirectTest`, `RedirectCredentialSecurityTest`, `RedirectConnectionUsageTest`, `Head302Test`, `StripAuthorizationOnRedirectHttpTest` and `ws.RedirectTest`. ## Verification  Caveat on the testing gate: `AGENTS.md` requires the build to run on JDK 11 and no JDK 11 is installed on this machine, so it was run on **JDK 17** (also in the CI matrix). The JDK 11 leg of CI on this PR is the real gate. Follows the same review pass as #2300. Claude Code on behalf of @pavel-ptashyts 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com> Co-authored-by: Aayush Atharva <24762260+hyperxpro@users.noreply.github.com>

@pavel-ptashyts

## Problem `AsyncHttpClientHandler` requested a read from both lifecycle callbacks: ```java public void channelActive(ChannelHandlerContext ctx) { ctx.read(); } public void channelReadComplete(ChannelHandlerContext ctx) { ctx.read(); } ``` Netty's `HeadContext` already calls `Channel#read()` immediately after firing either event whenever `autoRead` is on. AsyncHttpClient never clears `autoRead` (no `ChannelOption.AUTO_READ` anywhere in the codebase) and Netty defaults it to on, so that was the path for every connection: each read cycle traversed the outbound pipeline and reached `doBeginRead` twice instead of once. The cost is per read cycle, so it scales with how many reads a response takes. ## Change Drive the read from the handler only when `autoRead` is off. That is also a fix in its own right: a caller who disabled `autoRead` through `setChannelOption` previously had the setting silently defeated by these two unconditional reads, since the handler kept requesting reads regardless. ## Verification of the Netty behaviour Checked against `netty-codec-http2` / `netty-transport` **4.2.16.Final**, the version this project builds against, rather than assumed: * `DefaultChannelPipeline$HeadContext.channelActive` and `.channelReadComplete` both call `readIfIsAutoRead()`, which is `if (channel.config().isAutoRead()) channel.read();` * `DefaultChannelConfig`'s constructor initialises `autoRead` to `1`, so on. * HTTP/2 stream channels inherit both behaviours: `AbstractHttp2StreamChannel$2 extends DefaultChannelPipeline`, and `Http2StreamChannelConfig extends DefaultChannelConfig` without overriding `isAutoRead`. The last point matters because this is the shared base class of `HttpHandler`, `WebSocketHandler` and `Http2Handler`, and neither of the two callbacks is overridden by any of them, so the change applies to HTTP/1.1, WebSocket and HTTP/2 stream channels alike. ## Verification of the build `mvnw clean verify` - BUILD SUCCESS, 1371 tests, 0 failures, 0 errors, 19 skipped. Error Prone, NullAway and Revapi all clean. The suites covering the paths most exposed to a change in read behaviour are green: 168 HTTP/2 tests (`BasicHttp2Test`, `Http2MultiplexBugRegressionTest`, `Http2StreamingBodyFlowControlTest`, `Http2StreamOrphanRegressionTest`, `Http2ConformanceRegressionTest` and the rest) and 36 WebSocket tests (`TextMessageTest`, `ByteMessageTest`, `CloseCodeReasonMessageTest`, `WebSocketWriteFutureTest`, `ws.ProxyTunnellingTest`). Caveat on the testing gate: `AGENTS.md` requires the build to run on JDK 11 and no JDK 11 is installed on this machine, so it was run on **JDK 17** (also in the CI matrix). The JDK 11 leg of CI on this PR is the real gate. No public API change. Same review pass as #2300 and #2301. Claude Code on behalf of @pavel-ptashyts 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com> Co-authored-by: Aayush Atharva <24762260+hyperxpro@users.noreply.github.com>

@pavel-ptashyts

## Problem For the default handler (`executeRequest(request)` -> `AsyncCompletionHandlerBase` -> `Response`) the body is copied three times: 1. `HttpHandler.handleChunk` -> `EagerResponseBodyPart` copies each chunk out of the network buffer into a heap `byte[]` (needed: `channelRead` releases the message afterwards); 2. `NettyResponse.getResponseBodyAsByteBuffer` concatenates every part into a freshly allocated array; 3. `getResponseBody(charset)` decodes that array. Step 2 is pure waste when there is only one part, which is the case for any body that lands in a single socket read: it copies a single part into a new array with nothing to concatenate it with. ## Change `getResponseBody(Charset)` decodes straight from the part when there is exactly one of them. The array does not escape the method, so the part's own array can be decoded in place. Several parts are still concatenated before decoding, never decoded one at a time, because a multi-byte character can straddle a part boundary. `getResponseBodyAsBytes` and `getResponseBodyAsByteBuffer` are deliberately left untouched: they hand the array to the caller, so they keep making a defensive copy rather than expose a part's own array. There is no aliasing change anywhere in this PR. ## Measurements Rough probe on JDK 17 over a single-part ASCII body, concatenate-then-decode versus decode-in-place. Not JMH, so read the shape rather than the digits: | body | before | after | |------|--------|-------| | 512 B | 496 ns | 47 ns | | 4 KB | 2277 ns | 373 ns | | 16 KB | 2963 ns | 1450 ns | | 128 KB | 24913 ns | 12248 ns | Plus one fewer whole-body allocation per response. The percentages look large partly because a pure-ASCII body decodes through a JDK intrinsic, which makes the removed copy a big share of what is left. ## Tests Two added to `NettyAsyncResponseTest`: * `testGetResponseBodyDecodesOnePartAndSplitPartsIdentically` splits the two-byte UTF-8 encoding of U+00E9 across two parts and asserts one-part and split-part bodies decode alike. This pins the constraint the comment states: it fails if anyone later makes the multi-part path decode part by part. * `testGetResponseBodyAsBytesDoesNotShareTheBodyPartArray` pins that `getResponseBodyAsBytes` still returns a fresh array and never the part's own. The body bytes are built as an explicit `byte[]` rather than a string literal to keep the source ASCII per `AGENTS.md`. ## Verification `mvnw clean verify` - BUILD SUCCESS, 1373 tests (1371 before, plus these two), 0 failures, 0 errors, 19 skipped. Error Prone, NullAway and Revapi clean. `LargeResponseTest`, `NoNullResponseTest`, `BodyDeferringAsyncHandlerTest` and `RedirectBodyTest`, which exercise the multi-part path, are green. Caveat on the testing gate: `AGENTS.md` requires the build to run on JDK 11 and no JDK 11 is installed on this machine, so it was run on **JDK 17** (also in the CI matrix). The JDK 11 leg of CI on this PR is the real gate. ## Not in scope The multi-part case still concatenates. A `CompositeByteBuf.toString(charset)` variant measured faster there (Netty decodes a multi-component buffer through a recycled, un-zeroed thread-local array instead of a fresh `byte[]`), but it regressed at high part counts in the same probe, so it needs proper benchmarking before it becomes a change. Removing copy 1 would mean retaining network buffers and giving `Response` a lifecycle, which is public API and wants a design discussion first. No public API change here. Same review pass as #2300, #2301 and #2302. Claude Code on behalf of @pavel-ptashyts 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com> Co-authored-by: Aayush Atharva <24762260+hyperxpro@users.noreply.github.com>

This was referenced Aug 3, 2026

Skip redirect set lookup for non-3xx responses #2301

Merged

Read only when the channel does not auto-read #2302

Merged

Decode a lone response body part in place #2303

Merged

hyperxpro requested changes Aug 3, 2026

View reviewed changes

pavel-ptashyts requested a review from hyperxpro August 4, 2026 06:55

hyperxpro approved these changes Aug 5, 2026

View reviewed changes

hyperxpro merged commit 5c383ab into AsyncHttpClient:main Aug 5, 2026
13 checks passed

Navigation Menu

Uh oh!

Guard debug logs in pollPooledChannel - #2300

Guard debug logs in pollPooledChannel#2300
hyperxpro merged 2 commits into
AsyncHttpClient:mainfrom
maygemdev:fix/guard-pooled-channel-debug-logs

pavel-ptashyts commented Aug 3, 2026 •

edited

Loading

Uh oh!

hyperxpro Aug 3, 2026

Uh oh!

pavel-ptashyts Aug 4, 2026

Uh oh!

hyperxpro Aug 3, 2026

Uh oh!

pavel-ptashyts Aug 4, 2026

Uh oh!

hyperxpro Aug 3, 2026

Uh oh!

pavel-ptashyts Aug 4, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

pavel-ptashyts commented Aug 3, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

Change

Scope

Verification

Uh oh!

hyperxpro Aug 3, 2026

Choose a reason for hiding this comment

Uh oh!

pavel-ptashyts Aug 4, 2026

Choose a reason for hiding this comment

Uh oh!

hyperxpro Aug 3, 2026

Choose a reason for hiding this comment

Uh oh!

pavel-ptashyts Aug 4, 2026

Choose a reason for hiding this comment

Uh oh!

hyperxpro Aug 3, 2026

Choose a reason for hiding this comment

Uh oh!

pavel-ptashyts Aug 4, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

pavel-ptashyts commented Aug 3, 2026 •

edited

Loading