You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by "Brooks, Kenneth S" <ke...@chase.com> on 2010/07/20 17:20:43 UTC
Performance
Oleg..
* Here is the wire error and context debug.
o From my end I made 3 service calls, (which translates into 4 total calls because the very first call is to create a security token to be reused on subsequent requests).
o Before I start asking questions let me know what you are seeing in here and your thoughts.
* Also, in a separate exercise I changed over from httpclient to httpcore.
o That made almost no difference in response times.
o Prior to the changeover I had upgraded to httpclient from trunk and had disabled a bunch of interceptors (cookies, proxy, authcache) as well as turned off the stale checking so I think httpclient was running about as thin as I could make it.
o Definitely did not see a 40% increase in performance tho..
o It is reusing the connection.. (before you ask) :)
2010-07-20 01:20:40,235 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:199) - Get connection: HttpRoute[{}->http://localhost:7001], timeout = 0
2010-07-20 01:20:40,235 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:332) - [HttpRoute[{}->http://localhost:7001]] total kept alive: 0, total issued: 0, total allocated: 0 out of 20
2010-07-20 01:20:40,235 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:505) - No free connections [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,235 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:351) - Available capacity: 2 out of 2 [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,235 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:531) - Creating new connection [HttpRoute[{}->http://localhost:7001]]
2010-07-20 01:20:40,266 DEBUG conn.DefaultClientConnectionOperator (DefaultClientConnectionOperator.java:145) - Connecting to localhost/127.0.0.1:7001
2010-07-20 01:20:40,282 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:625) - Attempt 2 to execute request
2010-07-20 01:20:40,298 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:258) - Sending request: POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:262) - >> POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Encoding: none
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:265) - >> Serialization-Type: java
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Length: 628
2010-07-20 01:20:40,298 DEBUG http.headers (DefaultClientConnection.java:265) - >> Host: localhost:7001
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:265) - >> Connection: Keep-Alive
2010-07-20 01:20:40,313 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:243) - Receiving response: HTTP/1.1 200 OK
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:246) - << HTTP/1.1 200 OK
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:249) - << Date: Tue, 20 Jul 2010 05:20:40 GMT
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:249) - << Transfer-Encoding: chunked
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,313 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Encoding: none
2010-07-20 01:20:40,329 DEBUG http.headers (DefaultClientConnection.java:249) - << Serialization-Type: java
2010-07-20 01:20:40,329 DEBUG http.headers (DefaultClientConnection.java:249) - << X-Powered-By: Servlet/2.5 JSP/2.1
2010-07-20 01:20:40,329 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:478) - Connection can be kept alive for ever
2010-07-20 01:20:40,345 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:248) - Released connection is reusable.
2010-07-20 01:20:40,345 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:416) - Releasing connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,345 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:442) - Pooling connection [HttpRoute[{}->http://localhost:7001]][null]; keep alive for ever
2010-07-20 01:20:40,345 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:661) - Notifying no-one, there are no waiting threads
2010-07-20 01:20:40,485 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:199) - Get connection: HttpRoute[{}->http://localhost:7001], timeout = 0
2010-07-20 01:20:40,501 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:332) - [HttpRoute[{}->http://localhost:7001]] total kept alive: 1, total issued: 0, total allocated: 1 out of 20
2010-07-20 01:20:40,501 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:480) - Getting free connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,501 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:625) - Attempt 2 to execute request
2010-07-20 01:20:40,501 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:258) - Sending request: POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:262) - >> POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Encoding: none
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Serialization-Type: java
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Length: 1768
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Host: localhost:7001
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:265) - >> Connection: Keep-Alive
2010-07-20 01:20:40,501 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:243) - Receiving response: HTTP/1.1 200 OK
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:246) - << HTTP/1.1 200 OK
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << Date: Tue, 20 Jul 2010 05:20:40 GMT
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << Transfer-Encoding: chunked
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Encoding: none
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << Serialization-Type: java
2010-07-20 01:20:40,501 DEBUG http.headers (DefaultClientConnection.java:249) - << X-Powered-By: Servlet/2.5 JSP/2.1
2010-07-20 01:20:40,501 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:478) - Connection can be kept alive for ever
2010-07-20 01:20:40,501 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:248) - Released connection is reusable.
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:416) - Releasing connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:442) - Pooling connection [HttpRoute[{}->http://localhost:7001]][null]; keep alive for ever
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:661) - Notifying no-one, there are no waiting threads
2010-07-20 01:20:40,516 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:199) - Get connection: HttpRoute[{}->http://localhost:7001], timeout = 0
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:332) - [HttpRoute[{}->http://localhost:7001]] total kept alive: 1, total issued: 0, total allocated: 1 out of 20
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:480) - Getting free connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,516 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:625) - Attempt 2 to execute request
2010-07-20 01:20:40,516 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:258) - Sending request: POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:262) - >> POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Encoding: none
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Serialization-Type: java
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Length: 1768
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Host: localhost:7001
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:265) - >> Connection: Keep-Alive
2010-07-20 01:20:40,516 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:243) - Receiving response: HTTP/1.1 200 OK
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:246) - << HTTP/1.1 200 OK
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << Date: Tue, 20 Jul 2010 05:20:40 GMT
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << Transfer-Encoding: chunked
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Encoding: none
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << Serialization-Type: java
2010-07-20 01:20:40,516 DEBUG http.headers (DefaultClientConnection.java:249) - << X-Powered-By: Servlet/2.5 JSP/2.1
2010-07-20 01:20:40,516 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:478) - Connection can be kept alive for ever
2010-07-20 01:20:40,516 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:248) - Released connection is reusable.
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:416) - Releasing connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:442) - Pooling connection [HttpRoute[{}->http://localhost:7001]][null]; keep alive for ever
2010-07-20 01:20:40,516 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:661) - Notifying no-one, there are no waiting threads
2010-07-20 01:20:40,532 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:199) - Get connection: HttpRoute[{}->http://localhost:7001], timeout = 0
2010-07-20 01:20:40,532 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:332) - [HttpRoute[{}->http://localhost:7001]] total kept alive: 1, total issued: 0, total allocated: 1 out of 20
2010-07-20 01:20:40,532 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:480) - Getting free connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,532 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:625) - Attempt 2 to execute request
2010-07-20 01:20:40,532 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:258) - Sending request: POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:262) - >> POST /RemotingLoopback-current/essd-remote/ HTTP/1.1
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Encoding: none
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Serialization-Type: java
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Content-Length: 1768
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Host: localhost:7001
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:265) - >> Connection: Keep-Alive
2010-07-20 01:20:40,532 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:243) - Receiving response: HTTP/1.1 200 OK
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:246) - << HTTP/1.1 200 OK
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << Date: Tue, 20 Jul 2010 05:20:40 GMT
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << Transfer-Encoding: chunked
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Type: application/x-java-serialized-object
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << Content-Encoding: none
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << Serialization-Type: java
2010-07-20 01:20:40,532 DEBUG http.headers (DefaultClientConnection.java:249) - << X-Powered-By: Servlet/2.5 JSP/2.1
2010-07-20 01:20:40,532 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:478) - Connection can be kept alive for ever
2010-07-20 01:20:40,532 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:248) - Released connection is reusable.
2010-07-20 01:20:40,532 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:416) - Releasing connection [HttpRoute[{}->http://localhost:7001]][null]
2010-07-20 01:20:40,532 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:442) - Pooling connection [HttpRoute[{}->http://localhost:7001]][null]; keep alive for ever
2010-07-20 01:20:40,532 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:661) - Notifying no-one, there are no waiting threads
This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law. If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED. Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.
RE: Performance
Posted by "Brooks, Kenneth S" <ke...@chase.com>.
I agree with you after looking at the logs.. I would see some responses come back almost instantaneously.. That tells me that its not strictly the protocol overhead.. if it was we would *always* see that overhead..
I think I've found a good balance..
Was able to get the overall response times down to with +/- 5% of the t3 response times.
Did optimizations in our code, also using httpclient 4.1 with most of the interceptors removed from the request/response interceptor stack (since I'm not using auth, etc..).
For small data packets it is taking longer than t3.
For large data packets it is faster than t3.
I was running about 30% slower than t3 but the last little thing that got me over the hump was that I had left the context Debug logging on.
That little bit of logging was enough to drive the CPU usage up by over 10% and also slow the overall run down.
I'm going to button up the implementation and turn it over to the performance team for the big run.. keeping my fingers crossed..
Thanks a bunch for you help.. really was useful as I started digging into the bowels of httpclient and httpcore.. At least I understand the internals a little better now.
-k
> -----Original Message-----
> From: Oleg Kalnichevski [mailto:olegk@apache.org]
> Sent: Tuesday, July 20, 2010 3:36 PM
> To: HttpClient User Discussion
> Subject: Re: Performance
>
> On Tue, 2010-07-20 at 11:20 -0400, Brooks, Kenneth S wrote:
> > Oleg..
> >
> > * Here is the wire error and context debug.
> > o From my end I made 3 service calls, (which translates into 4
> total calls because the very first call is to create a security token to
> be reused on subsequent requests).
> > o Before I start asking questions let me know what you are
> seeing in here and your thoughts.
>
> I am seeing nothing that might suggest an obvious performance related
> problem. Once a connection has been established request / response
> exchanges are almost instantaneous (~10 ms)
>
>
> > * Also, in a separate exercise I changed over from httpclient to
> httpcore.
> > o That made almost no difference in response times.
> > o Prior to the changeover I had upgraded to httpclient from
> trunk and had disabled a bunch of interceptors (cookies, proxy,
> authcache) as well as turned off the stale checking so I think
> httpclient was running about as thin as I could make it.
> > o Definitely did not see a 40% increase in performance tho..
>
> I am fairly confident about this number. If you are not registering any
> performance improvement this basically tell me that one of two things
> are likely to be true
>
> (1) the overhead of HTTP protocol processing is negligible compared to
> the time spent transmitting and processing message content.
> (2) the problem is on the server side. Response latency is much greater
> than the overhead of HTTP protocol processing.
>
> The client side HTTP does not appears to be the performance hot spot. I
> _suspect_ you are optimizing the wrong component.
>
> Oleg
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law. If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED. Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.
Re: Performance
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Tue, 2010-07-20 at 11:20 -0400, Brooks, Kenneth S wrote:
> Oleg..
>
> * Here is the wire error and context debug.
> o From my end I made 3 service calls, (which translates into 4 total calls because the very first call is to create a security token to be reused on subsequent requests).
> o Before I start asking questions let me know what you are seeing in here and your thoughts.
I am seeing nothing that might suggest an obvious performance related
problem. Once a connection has been established request / response
exchanges are almost instantaneous (~10 ms)
> * Also, in a separate exercise I changed over from httpclient to httpcore.
> o That made almost no difference in response times.
> o Prior to the changeover I had upgraded to httpclient from trunk and had disabled a bunch of interceptors (cookies, proxy, authcache) as well as turned off the stale checking so I think httpclient was running about as thin as I could make it.
> o Definitely did not see a 40% increase in performance tho..
I am fairly confident about this number. If you are not registering any
performance improvement this basically tell me that one of two things
are likely to be true
(1) the overhead of HTTP protocol processing is negligible compared to
the time spent transmitting and processing message content.
(2) the problem is on the server side. Response latency is much greater
than the overhead of HTTP protocol processing.
The client side HTTP does not appears to be the performance hot spot. I
_suspect_ you are optimizing the wrong component.
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org