Vikas Kumar created HADOOP-19996:
------------------------------------
Summary: 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
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]
