[
https://issues.apache.org/jira/browse/HADOOP-19996?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18126374#comment-18126374
]
ASF GitHub Bot commented on HADOOP-19996:
-----------------------------------------
vikaskr22 opened a new pull request, #8816:
URL: https://github.com/apache/hadoop/pull/8816
…utStream to reuse the Connection
<!--
Thanks for sending a pull request!
1. If this is your first time, please read our contributor guidelines:
https://cwiki.apache.org/confluence/display/HADOOP/How+To+Contribute
2. Make sure your PR title starts with JIRA issue id, e.g.,
'HADOOP-17799. Your PR title ...'.
-->
### Description of PR
One performance issue was observed when migrated from JDK 8 to JDK 17.
Considerable throughput fall was observed with Ranger-KMS service. On analysis,
like by observing the sockets being created, It was found that KeepAlive cache
was not working. TLS debug log (shared in JIRA) suggested that it is not trying
to cache the connection while closing the stream.
When response size increases beyond the configured threshold ( In Tomcat,
it's 8 KB ), Content-Type is set to "chunked" and ChunkedInputStream is used to
read the response. No issues here.
Issue is occurring when complete JSON payload comes in one TLS record and
chunk terminator bytes are coming in a separate TLS record. Jackson , that is
being used to read the response, calls inputStream.close() as soon as it reads
the entire payload, that is closing braces (}) and doesn't wait for the
terminator chunk to arrive.
At this point, last chunk containing the terminator bytes has not yet
arrived or has not yet been unwrapped, and ChunkedInputStream.close()--->
hurry() tries to clean the unread bytes one last time without getting blocked.
This operation is non-blocking by default. As a result, JVM was not able to
clean the underlying inputStream and it can not be reused, hence connection is
being destroyed. As a result, each call to ranger-KMS is doing a fresh new TLS
handshaking.
**FIX**: As a fix, chunk terminator bytes or any unread bytes from response
inputStream is being drained explicitly before calling close() on the
underlying stream. To prevent Jackson from calling close() automatically just
after reading the json payload, JsonParser.Feature.AUTO_CLOSE_SOURCE is being
disabled. But please note that close() on underlying stream is being called
from the finally block in both cases.
Further, logic to explicitly drain and close is being kept behind a flag
which is set to "false" by default. It can be enabled by adding following
property in the core-site.xml file :
```
Key : hadoop.security.kms.client.drain.response.unread.bytes
value: true
Default value: false
```
Cluster patched with this fix improved the throughput around three times and
average latency also went down significantly.
### How was this patch tested?
- local mvn build passed.
- Tested the change by patching the internal cluster with new hadoop-common
jar.
**Note**: I had to skip few unrelated UTs for my local build as it was stuck
for very long time, like org.apache.hadoop.security.TestDoAsEffectiveUser
### For code changes:
- [ ] Does the title of this PR start with the corresponding JIRA issue id
(e.g. 'HADOOP-17799. Your PR title ...')? ==>YES
- [ ] Object storage: Have the integration tests been executed and the
endpoint
declared according to the connector-specific documentation? *Note:
Automated CI
testing doesn't cover all cases so manual testing with cloud storage
is still
required.* ==> N/A
- [ ] If adding new dependencies to the code, are these dependencies
licensed in a way that is compatible for inclusion under [ASF
2.0](http://www.apache.org/legal/resolved.html#category-a)? ==> N/A
- [ ] If applicable, have you updated the `LICENSE`, `LICENSE-binary`,
`NOTICE-binary` files? ==? N/A
### AI Tooling
If an AI tool was used:
- [ ] The PR includes the phrase "Contains content generated by <tool>"
where <tool> is the name of the AI tool used. ==> N/A
- [ ] My use of AI contributions follows the ASF legal policy
https://www.apache.org/legal/generative-tooling.html ==> N/A
> With Java 17 KeepAlive caching not working when KMSClientProvider makes
> requests to KMS
> ---------------------------------------------------------------------------------------
>
> Key: HADOOP-19996
> URL: https://issues.apache.org/jira/browse/HADOOP-19996
> Project: Hadoop Common
> Issue Type: Bug
> Components: hadoop-common
> Reporter: Vikas Kumar
> Assignee: Vikas Kumar
> Priority: Major
>
> Recently after upgrading from Java 8 to Java 17 on one existing cluster, we
> observed more than 70% drop in the throughput between client app using
> KMSClientProvider to make requests to Ranger-KMS.
> Apart from throughput, average latency also increased. As soon as we rollback
> to Java 8, it was back to normal.
> Further we found, Ranger-KMS with Java 17 and client using hadoop-common's
> KMSClientProvider with Java 8 is working fine. If we switch to Java 17 on
> the client side, issue starts occuring.
> *My observation and debugging:*
> I suspected the new features of Java 17 like GC and default TLSv1.3 might be
> impacting the throughput. I tried with parallel GC as well, it didn't help.
> Ranger-KMS and client app were explicitly configured to use TLSv1.2 only.
> Still issue persists.
> Enabled tls debug log and can see very frequent *Connection reset* warning
> stack trace. I know that it may happen when server closes the connection due
> to idleTimeout. But frequency was high in Java 17 env in comparison to very
> few occurrences or zero occurrences in env with Java 8.
> Apart from Connection reset, many "Broken pipe" traces were there.
> *Thread dump analysis on the Ranger-KMS side:*
> At the time when client app was getting Connection reset/broken pipe, many
> of the KMS worker threads were occupied in I/O op with underlying socket's
> stream. Load on KMS was not increasing, many of the threads were idle waiting
> for the new task.
> I observed one difference in Java 17 & Java 8 Socket close stack trace on
> client app side:
> *Following is with Java 8:*
>
> {code:java}
> at sun.net.www.http.HttpClient.closeServer(HttpClient.java:1075)
> at sun.net.www.protocol.https.HttpsClient.closeServer(HttpsClient.java:428)
> at sun.net.www.http.KeepAliveCache.put(KeepAliveCache.java:196)
> at
> sun.net.www.protocol.https.HttpsClient.putInKeepAliveCache(HttpsClient.java:667)
> at sun.net.www.http.HttpClient.finished(HttpClient.java:397)
> at
> sun.net.www.http.ChunkedInputStream.closeUnderlying(ChunkedInputStream.java:219)
> at sun.net.www.http.ChunkedInputStream.processRaw(ChunkedInputStream.java:455)
> at
> sun.net.www.http.ChunkedInputStream.readAheadNonBlocking(ChunkedInputStream.java:520)
> at sun.net.www.http.ChunkedInputStream.readAhead(ChunkedInputStream.java:611)
> at sun.net.www.http.ChunkedInputStream.hurry(ChunkedInputStream.java:768)
> at
> sun.net.www.http.ChunkedInputStream.closeUnderlying(ChunkedInputStream.java:221)
> {code}
> *And following is with Java 17:*
>
>
> {code:java}
> at java.base/sun.net.www.http.HttpClient.closeServer(HttpClient.java:1155)
> at
> java.base/sun.net.www.protocol.https.HttpsClient.closeServer(HttpsClient.java:445)
> at
> java.base/sun.net.www.http.ChunkedInputStream.closeUnderlying(ChunkedInputStream.java:222)
> at
> java.base/sun.net.www.http.ChunkedInputStream.close(ChunkedInputStream.java:769)
> at java.base/java.io.FilterInputStream.close(FilterInputStream.java:179)
> {code}
> Note the difference,
>
> In Java 8 when client calls close() on underlying stream, it tries to drain
> any unread bytes left on the inputStream. And there it succeeds , stream is
> clean and retuned to the KeepAlive cache. You can observe
> *HttpsClient.putInKeepAliveCache*
> Same is not happening in Java 17 cluster. Here also it tries to drain the
> unread bytes but fails. hence connection destroyed and connection caching is
> not happening.
> This behaviour indicated towards possibility of connection leaks.
> Check the code
> [here|https://github.com/apache/hadoop/blob/997fa7c12a407c441855f1a409767f198db68cd3/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/crypto/key/kms/KMSClientProvider.java#L585]
> , In KMSClientProvider.java, when it gets 401 it goes to KMS again with
> required tokens. And for this it creates a new Connection , assign it to
> existing "con" reference variable. It missed to close the older connection.
> In the same method, in finally block it calls
> IOUtils.closeStream(is) for new connection.
>
> *To prove this finding,* If I simply drain the unread bytes (if exists)
> explicitly before calling close(), I start getting similar throughput that I
> was getting with Java 8, now I can't see any Connection reset or errors in
> the log.
>
> For example: Average latency without patch was around 225 ms and after patch
> it reduced to around 60-65 ms.
>
> PS: I read that in higher versions of Java, {{SLSocketImpl}} was completely
> rewritten around {{SSLEngine}} record boundaries. I suspect some behaviour
> difference.
>
> *Proposed Fix:* Irrespective of any behaviour difference, it would be better
> to drain the stream before closing.
>
> Request community members to review this and suggest. If this finding is
> correct, I can raise the PR.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
