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]
