Hi, We managed to observe our issue once again, this time with connection logging. Here is the situation:
No activity was detected on the application log for a few seconds, triggering a tomcat thread dump. The thread dump shows all http-nio-127.0.0.1-8080-exec-* threads waiting on org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.requestConnection while all I/O dispatcher threads are waiting on org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.releaseConnection. The application log (covering the last 2 sec of activity before the application being stuck) shows activity on the http async client until a point where we received requests that are supposed to trigger http communication to upstream servers but nothing is logged by http client (I assume because the threads from incoming requests are waiting to lease a connection). Here are the corresponding logs: http://s000.tinyupload.com/index.php?file_id=15495126975418045294 Thanks, Thomas 2015-05-21 11:46 GMT+02:00 Oleg Kalnichevski <[email protected]>: > On Wed, 2015-05-20 at 17:53 +0200, Thomas Boniface wrote: > > Just to make sure as I'm using log4j2, the configuration is slightly > > different. When testing locally I have logs that looks like this: > > > > org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: > > 2015-05-20 17:45:56,595 DEBUG http-nio-8080-exec-3 [Req_12] [ ] > > Connection request: [route: {}->http://sandbox.stickyadstv.com:80][total > > kept alive: 1; route allocated: 1 of 10; total allocated: 1 of 10] > > org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: > > 2015-05-20 17:45:56,617 DEBUG I/O dispatcher 6 [ ] [ ] Connection > > leased: [id: http-outgoing-5][route: > > {}->http://sandbox.stickyadstv.com:80][total > > kept alive: 0; route allocated: 1 of 10; total allocated: 1 of 10] > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,617 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][r:]: Set attribute > > http.nio.exchange-handler > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:]: Event set [w] > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:]: Set timeout 0 > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:]: Set attribute > > http.nio.http-exchange-state > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:]: Set timeout 60000 > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:]: Event set [w] > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][rw:w]: 883 bytes written > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,618 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][r:w]: Event cleared [w] > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][r:r]: 1349 bytes read > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][r:r]: Remove attribute > > http.nio.exchange-handler > > org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: > > 2015-05-20 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] Releasing > > connection: [id: http-outgoing-5][route: > > {}->http://sandbox.stickyadstv.com:80][total kept alive: 0; route > > allocated: 1 of 10; total allocated: 1 of 10] > > org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: > > 2015-05-20 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] Connection > > [id: http-outgoing-5][route: {}->http://sandbox.stickyadstv.com:80] can > be > > kept alive for 15.0 seconds > > org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: > 2015-05-20 > > 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] http-outgoing-5 > > 192.168.0.89:54298<->5.135.147.172:80[ACTIVE][r:r]: Set timeout 0 > > org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: > > 2015-05-20 17:45:56,653 DEBUG I/O dispatcher 6 [ ] [ ] Connection > > released: [id: http-outgoing-5][route: > > {}->http://sandbox.stickyadstv.com:80][total > > kept alive: 1; route allocated: 1 of 10; total allocated: 1 of 10] > > > > Is this helpful if we log this in a real production environment (this > will > > represent a high volume of data considering the number of request > > processed, could be up to 200k line per seconds) to know why lock seem to > > occur ? > > > > Thomas > > > > Hi Thomas > > I might be able to take a cursory look at the log but you should try to > isolate events that happen at the time of high lock contention and > understand what the client was trying to do. If you find all your i/o > dispatch threads trying to grab or release a connection approximately at > the same time this should explain the lock contention. > > Oleg > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > >
