Today I updated my dependencies to Lyo 4.1.0 and I notice that processing a query that formerly took about 10 seconds now takes 5 minutes. Is it possible that I configure the client incorrectly?
ClientConfig clientConfig = new ClientConfig().connectorProvider(new ApacheConnectorProvider());
SSLContext sslContext = new SSLContextBuilder().loadTrustMaterial(TrustSelfSignedStrategy.INSTANCE).build();
ClientBuilder clientBuilder = ClientBuilder.newBuilder()
.withConfig(clientConfig)
.sslContext(sslContext)
.hostnameVerifier(NoopHostnameVerifier.INSTANCE)
.register(new JEEFormAuthenticator(server, userid, password));
// .register(HttpAuthenticationFeature.basic(userid, password));
return new OslcClient(clientBuilder);
Formerly I did that with the JazzRootServicesHelper, but that seems to have disappeared.
When I iterate over the query members I see dramatically different durations (see millis in parantheses):
That’s interesting, we have migrated from Wink Client over Apache HttpClient to JAX-RS Client (Jersey in most of our uses) over Apache HttpClient between 2.4 and 4.0. I have not done any performance tests on the 2.x client but was also unsatisfied with the single-threaded performance and implemented some code to make concurrent OSLC requests using Kotlin coroutines. Around 50 OSLC POST requests to a Creation Factory finish in under 1s. This is how the client is initialized in that case.
But that code doesn’t do any processing of an OSLC Query response, and I recall @jad having some perf issues with the OSLC Query as well. Let’s investigate that first. @estepper if you could help with reproducing this issue on a code I can run, it will be of great value. @jad would it make sense to try to equalize the SysML OSLC Server codebase between 2.4 and 5.0.0-SNAPSHOT commits to test if our new client indeed introduces a big perf hit? @estepper would it be too much work for you to test your old code but with Lyo 2.4.0 client to narrow down when the regression was introduced, please?
I want to note that there was a big XXE CVE discovered in Jena (aside from the Log4shell issue that affected Fuseki) that lies in processing RDF/XML files and we were forced to migrate to Jena 4.x to get a fix for that, but there are lots of perf regression complaints on the jena-users mailing list coming from the Jena 3.x users upgrading to 4.x. If the root cause traces to that, it may require Jena dev community help.
I’ll be off until Friday. Then I’ll see how I can help.
For now I quickly tried out your additions ClientBuilder properties. ApacheClientProperties.DISABLE_COOKIES did not make a difference. Setting the socket timeout to 2 seconds makes my code fail almost immediately:
Exception in thread "main" javax.ws.rs.ProcessingException: java.net.SocketTimeoutException: Read timed out
at org.glassfish.jersey.apache.connector.ApacheConnector.apply(ApacheConnector.java:481)
at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:252)
at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:684)
at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:681)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:681)
at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:411)
at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:311)
at org.eclipse.lyo.client.JEEFormAuthenticator.followRedirects(JEEFormAuthenticator.java:173)
at org.eclipse.lyo.client.JEEFormAuthenticator.filter(JEEFormAuthenticator.java:138)
at org.glassfish.jersey.client.ClientFilteringStages$ResponseFilterStage.apply(ClientFilteringStages.java:140)
at org.glassfish.jersey.client.ClientFilteringStages$ResponseFilterStage.apply(ClientFilteringStages.java:128)
at org.glassfish.jersey.process.internal.Stages.process(Stages.java:171)
at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:257)
at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:684)
at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:681)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:681)
at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:411)
at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:311)
at org.eclipse.lyo.client.OslcClient.getResource(OslcClient.java:265)
at org.eclipse.lyo.client.OslcClient.getResource(OslcClient.java:189)
at com.foo.sync.server.doors.rm.impl.consumer.AbstractRMConsumer.getProjectByTitle(AbstractRMConsumer.java:111)
at com.foo.sync.server.doors.rm.Test.lambda$0(Test.java:33)
at com.foo.sync.server.doors.rm.Test.measure(Test.java:92)
at com.foo.sync.server.doors.rm.Test.main(Test.java:31)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:280)
at org.apache.http.impl.io.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:129)
at org.apache.http.impl.io.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:53)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
at org.glassfish.jersey.apache.connector.ApacheConnector.apply(ApacheConnector.java:435)
... 31 more
We’ve compared the slow setup with the new libraries to the older fast setup and we’re almost certain that the slowness is caused by repeated authentications. In both setups authentication takes about 4.6 seconds. With the old libraries we see this gap exactly once at the beginning. But with the new setup we’re seeing frequent gaps with exact multiples of 4.6 seconds while we process our query result. These gaps are caused by demand loading parent navigation folders and module structure when they’re needed.
A breakpoint on the old/fast org.apache.http.impl.conn.DefaultClientConnection is hit exactly twice, once for the form login and once for the following authenticated requests. But a breakpoint on the new/slow org.glassfish.jersey.apache.connector.ApacheConnector.HttpClientConnection is hit many times. How can we configure our client such that our authenticated connection itself is properly reused?
With new slow version the connections are not properly released, so they stay marked “leased” and can not be reused for the next request.
The proper release of the connection in the old fast version is triggered by a call to EntityUtils.consume(newResp.getEntity()) in JazzFormAuthClient.followRedirects().
This call seems missing in the new JEEFormAuthenticator.followRedirects().
Ok, I think the call to lastRedirectResponse.close() in JEEFormAuthenticator.followRedirects() should be sufficient.
BUT: In org.apache.http.impl.execchain.ConnectionHolder.close() a call to releaseConnection(false) is made. This “false” argument to the “reusable” parameter is the real problem. It caused the managed connection to be physically closed and released to the connection manager without the “state” object that would be needed to reuse the connection later.
I found a work-around. It’s not nice, but it seems to demonstrate the problem.
I removed the httpclient-4.5.13.jar from the classpath and added its sources directly to my Eclipse project. Then I changed org.apache.http.impl.execchain.HttpResponseProxy.close() from:
public void close() throws IOException {
if (this.connHolder != null) {
this.connHolder.close();
}
}
To:
public void close() throws IOException {
if (this.connHolder != null) {
this.connHolder.releaseConnection();
}
}
To me the following questions remain: Is this a bug in httpclient or is it just not used correctly? If the latter, how is it used correctly?
Thank you @estepper for the investigation! I filed https://github.com/eclipse/lyo/issues/257 and I think the likely cause for this is that the filter does not try to append auth cookies to every request but only reacts when a 401 response it obtained. You seem to have worked around this problem by reusing one connection, which is good but not always possible (e.g. if the server sends you a Connection: close). I think a better approach would be to check if there are cookies to append to the request and if yes, to always append them. This way we don’t care if the client connection is fresh or reused. Only if the cookies are no longer valid, we’d re-authenticate for a 401 response.
Sadly, I don’t have access to a Jazz installation right now and would not be able to test the change to the logic in
I would be very grateful if you submit a PR if a change to JEEFormAuthenticator helps.
P.S. I think it was @jamsden who developed JEEFormAuthenticator, so he may know better what’s the best way forward is.