Random CancelledKeyException's

[Kram]

Hi Everyone,

At the moment I am trying to setup a configurable TCP server that will process a proprietary protocol, and I am using JMeter to do some testing.

I have setup JMeter so that it fires of lots of requests on different threads, I am doing this because I want to only allow a certain number of connections.

While I am doing this though, I seem to get random exceptions, in my log files like so:

2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
java.nio.channels.CancelledKeyException
    at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
    at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
    at com.sun.grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:650)
    at com.sun.grizzly.Controller.doSelect(Controller.java:423)
    at com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
    at com.sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:1117)
    at com.sun.grizzly.Controller.start(Controller.java:924)
    at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
    at java.lang.Thread.run(Thread.java:595)

I am not sure why it happens, I was wondering if anyone else had come across this type of thing before?

Cheers,
Mark

[John ROM]

Hi Mark,
well from looking at the exception what

happend is that the connection (selectionKey) was just ready to have bytes read in.

Then just before Grizzly was going to read those bytes in  the Connection(selectionKey) was canceled.

Remeber your protocolChain is running on a WorkerThread and I think you mentioned that you are
canceling the key in your filter so this can happen : (I am just guessing, because I do not have your code)

1) jmeter sends bytes
2) grizzly signals bytes are ready
3) WorkerThread cancels key
4) grizzly wants to read bytes in
5) CancelledKeyException

Laugh maybe your setup is a little  mean ((-:

But I would like to ask  Alexy or Jeanfrancois who are much more experts then me
if it makes sense to catch CancelledKeyException and log a little bit nicer that the key has been canceled
I don't think you can complete avoid this exception because testing if  key is valid always cost a little performance.....

many Greetings John




-------- Original-Nachricht --------
> Datum: Thu, 24 Jul 2008 16:33:15 +1000
> Von: "Mark Macumber" <mark.macumber@...>
> An: dev@...
> Betreff: Random CancelledKeyException\'s

> Hi Everyone,
>
> At the moment I am trying to setup a configurable TCP server that will
> process a proprietary protocol, and I am using JMeter to do some testing.
>
> I have setup JMeter so that it fires of lots of requests on different
> threads, I am doing this because I want to only allow a certain number of
> connections.
>
> While I am doing this though, I seem to get random exceptions, in my log
> files like so:
>
> 2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
> java.nio.channels.CancelledKeyException
>     at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
>     at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
>     at
> com.sun.grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:650)
>     at com.sun.grizzly.Controller.doSelect(Controller.java:423)
>     at
> com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
>     at
> com.sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:1117)
>     at com.sun.grizzly.Controller.start(Controller.java:924)
>     at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
>     at java.lang.Thread.run(Thread.java:595)
>
> I am not sure why it happens, I was wondering if anyone else had come
> across
> this type of thing before?
>
> Cheers,
> Mark

--
GMX startet ShortView.de. Hier findest Du Leute mit Deinen Interessen!
Jetzt dabei sein: http://www.shortview.de/wasistshortview.php?mc=sv_ext_mf@gmx

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Oleksiy Stashok]

Hi John,

agree,
CancelledKeyException should be logged on some lower level.
Can you take care of that? :)

Thanks.

WBR,
Alexey.

On Jul 24, 2008, at 9:30 , John ROM wrote:

> Hi Mark,
> well from looking at the exception what
>
> happend is that the connection (selectionKey) was just ready to have  
> bytes read in.
>
> Then just before Grizzly was going to read those bytes in  the  
> Connection(selectionKey) was canceled.
>
> Remeber your protocolChain is running on a WorkerThread and I think  
> you mentioned that you are
> canceling the key in your filter so this can happen : (I am just  
> guessing, because I do not have your code)
>
> 1) jmeter sends bytes
> 2) grizzly signals bytes are ready
> 3) WorkerThread cancels key
> 4) grizzly wants to read bytes in
> 5) CancelledKeyException
>
> Laugh maybe your setup is a little  mean ((-:
>
> But I would like to ask  Alexy or Jeanfrancois who are much more  
> experts then me
> if it makes sense to catch CancelledKeyException and log a little  
> bit nicer that the key has been canceled
> I don't think you can complete avoid this exception because testing  
> if  key is valid always cost a little performance.....
>
> many Greetings John
>
>
>
>
> -------- Original-Nachricht --------
>> Datum: Thu, 24 Jul 2008 16:33:15 +1000
>> Von: "Mark Macumber" <mark.macumber@...>
>> An: dev@...
>> Betreff: Random CancelledKeyException\'s
>
>> Hi Everyone,
>>
>> At the moment I am trying to setup a configurable TCP server that  
>> will
>> process a proprietary protocol, and I am using JMeter to do some  
>> testing.
>>
>> I have setup JMeter so that it fires of lots of requests on different
>> threads, I am doing this because I want to only allow a certain  
>> number of
>> connections.
>>
>> While I am doing this though, I seem to get random exceptions, in  
>> my log
>> files like so:
>>
>> 2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
>> java.nio.channels.CancelledKeyException
>>    at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:
>> 55)
>>    at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:
>> 59)
>>    at
>> com
>> .sun
>> .grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:
>> 650)
>>    at com.sun.grizzly.Controller.doSelect(Controller.java:423)
>>    at
>> com
>> .sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
>>    at
>> com
>> .sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:
>> 1117)
>>    at com.sun.grizzly.Controller.start(Controller.java:924)
>>    at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
>>    at java.lang.Thread.run(Thread.java:595)
>>
>> I am not sure why it happens, I was wondering if anyone else had come
>> across
>> this type of thing before?
>>
>> Cheers,
>> Mark
>
> --
> GMX startet ShortView.de. Hier findest Du Leute mit Deinen Interessen!
> Jetzt dabei sein: http://www.shortview.de/wasistshortview.php?mc=sv_ext_mf@gmx
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@...
> For additional commands, e-mail: dev-help@...
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Kram]

Ok so Im just trying to make sense of all this,

The only real way that the framework would invalidate the SelectionKey is when it is supposed to be cancelled, such as when the channel is closed, or interrupted.

Is is explicitly invalidated. So I wonder why there are bytes trying to be sent through a channel whos key is invalid. I am implementing connection managing via the CacheableSelectionKeyHandler, so I guess that if I was to send too many connections from JMeter then it is possible that Grizzly is trying to reclaim the older connections (which is this case are really only a few milliseconds old) and use them for new incomming connections.

Does this logic make sense?

Cheers,
Mark

On Thu, Jul 24, 2008 at 5:30 PM, John ROM <snake-john@...> wrote:

Hi Mark,
well from looking at the exception what

happend is that the connection (selectionKey) was just ready to have bytes read in.

Then just before Grizzly was going to read those bytes in  the Connection(selectionKey) was canceled.

Remeber your protocolChain is running on a WorkerThread and I think you mentioned that you are
canceling the key in your filter so this can happen : (I am just guessing, because I do not have your code)

1) jmeter sends bytes
2) grizzly signals bytes are ready
3) WorkerThread cancels key
4) grizzly wants to read bytes in
5) CancelledKeyException

Laugh maybe your setup is a little  mean ((-:

But I would like to ask  Alexy or Jeanfrancois who are much more experts then me
if it makes sense to catch CancelledKeyException and log a little bit nicer that the key has been canceled
I don't think you can complete avoid this exception because testing if  key is valid always cost a little performance.....

many Greetings John




-------- Original-Nachricht --------
> Datum: Thu, 24 Jul 2008 16:33:15 +1000
> Von: "Mark Macumber" <mark.macumber@...>
> An: dev@...
> Betreff: Random CancelledKeyException\'s

> Hi Everyone,
>
> At the moment I am trying to setup a configurable TCP server that will
> process a proprietary protocol, and I am using JMeter to do some testing.
>
> I have setup JMeter so that it fires of lots of requests on different
> threads, I am doing this because I want to only allow a certain number of
> connections.
>
> While I am doing this though, I seem to get random exceptions, in my log
> files like so:
>
> 2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
> java.nio.channels.CancelledKeyException
>     at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
>     at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
>     at
> com.sun.grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:650)
>     at com.sun.grizzly.Controller.doSelect(Controller.java:423)
>     at
> com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
>     at
> com.sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:1117)
>     at com.sun.grizzly.Controller.start(Controller.java:924)
>     at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
>     at java.lang.Thread.run(Thread.java:595)
>
> I am not sure why it happens, I was wondering if anyone else had come
> across
> this type of thing before?
>
> Cheers,
> Mark

--
GMX startet ShortView.de. Hier findest Du Leute mit Deinen Interessen!
Jetzt dabei sein: http://www.shortview.de/wasistshortview.php?mc=sv_ext_mf@gmx

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Oleksiy Stashok]

Hi Mark,

Ok so Im just trying to make sense of all this,

The only real way that the framework would invalidate the SelectionKey is when it is supposed to be cancelled, such as when the channel is closed, or interrupted.

Is is explicitly invalidated. So I wonder why there are bytes trying to be sent through a channel whos key is invalid. I am implementing connection managing via the CacheableSelectionKeyHandler, so I guess that if I was to send too many connections from JMeter then it is possible that Grizzly is trying to reclaim the older connections (which is this case are really only a few milliseconds old) and use them for new incomming connections.

Does this logic make sense?

Well, it's possible. Can you pls. try the different SelectionKeyHandler, just to check whether it's the case?

Thanks.

WBR,

Alexey.

Cheers,
Mark

On Thu, Jul 24, 2008 at 5:30 PM, John ROM <snake-john@...> wrote:

Hi Mark,
well from looking at the exception what

happend is that the connection (selectionKey) was just ready to have bytes read in.

Then just before Grizzly was going to read those bytes in  the Connection(selectionKey) was canceled.

Remeber your protocolChain is running on a WorkerThread and I think you mentioned that you are
canceling the key in your filter so this can happen : (I am just guessing, because I do not have your code)

1) jmeter sends bytes
2) grizzly signals bytes are ready
3) WorkerThread cancels key
4) grizzly wants to read bytes in
5) CancelledKeyException

Laugh maybe your setup is a little  mean ((-:

But I would like to ask  Alexy or Jeanfrancois who are much more experts then me
if it makes sense to catch CancelledKeyException and log a little bit nicer that the key has been canceled
I don't think you can complete avoid this exception because testing if  key is valid always cost a little performance.....

many Greetings John




-------- Original-Nachricht --------
> Datum: Thu, 24 Jul 2008 16:33:15 +1000
> Von: "Mark Macumber" <mark.macumber@...>
> An: dev@...
> Betreff: Random CancelledKeyException\'s

> Hi Everyone,
>
> At the moment I am trying to setup a configurable TCP server that will
> process a proprietary protocol, and I am using JMeter to do some testing.
>
> I have setup JMeter so that it fires of lots of requests on different
> threads, I am doing this because I want to only allow a certain number of
> connections.
>
> While I am doing this though, I seem to get random exceptions, in my log
> files like so:
>
> 2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
> java.nio.channels.CancelledKeyException
>     at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
>     at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
>     at
> com.sun.grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:650)
>     at com.sun.grizzly.Controller.doSelect(Controller.java:423)
>     at
> com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
>     at
> com.sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:1117)
>     at com.sun.grizzly.Controller.start(Controller.java:924)
>     at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
>     at java.lang.Thread.run(Thread.java:595)
>
> I am not sure why it happens, I was wondering if anyone else had come
> across
> this type of thing before?
>
> Cheers,
> Mark

--
GMX startet ShortView.de. Hier findest Du Leute mit Deinen Interessen!
Jetzt dabei sein: http://www.shortview.de/wasistshortview.php?mc=sv_ext_mf@gmx

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Kram]

Ok so I changed from the CacheableSelectionKeyHandler to the DefaultSelectionKeyHandler, I did not get any errors, which is good. When I switched back, I ran the same exact test and got the previously mentioned error.

So it looks like either a config issue, like the number of available connections, reclaim numbers, etc... or the test itself is incorrect and not very realistic.

I will continue to investigate... and Im sure you'll hear from me if I make any progress, but any further thoughts are definately welcome!

Cheers,
Mark

On Thu, Jul 24, 2008 at 9:51 PM, Oleksiy Stashok <Oleksiy.Stashok@...> wrote:

Hi Mark,

Ok so Im just trying to make sense of all this,

The only real way that the framework would invalidate the SelectionKey is when it is supposed to be cancelled, such as when the channel is closed, or interrupted.

Is is explicitly invalidated. So I wonder why there are bytes trying to be sent through a channel whos key is invalid. I am implementing connection managing via the CacheableSelectionKeyHandler, so I guess that if I was to send too many connections from JMeter then it is possible that Grizzly is trying to reclaim the older connections (which is this case are really only a few milliseconds old) and use them for new incomming connections.

Does this logic make sense?

Well, it's possible. Can you pls. try the different SelectionKeyHandler, just to check whether it's the case?

Thanks.

WBR,

Alexey.

Cheers,
Mark

On Thu, Jul 24, 2008 at 5:30 PM, John ROM <snake-john@...> wrote:

Hi Mark,
well from looking at the exception what

happend is that the connection (selectionKey) was just ready to have bytes read in.

Then just before Grizzly was going to read those bytes in  the Connection(selectionKey) was canceled.

Remeber your protocolChain is running on a WorkerThread and I think you mentioned that you are
canceling the key in your filter so this can happen : (I am just guessing, because I do not have your code)

1) jmeter sends bytes
2) grizzly signals bytes are ready
3) WorkerThread cancels key
4) grizzly wants to read bytes in
5) CancelledKeyException

Laugh maybe your setup is a little  mean ((-:

But I would like to ask  Alexy or Jeanfrancois who are much more experts then me
if it makes sense to catch CancelledKeyException and log a little bit nicer that the key has been canceled
I don't think you can complete avoid this exception because testing if  key is valid always cost a little performance.....

many Greetings John




-------- Original-Nachricht --------
> Datum: Thu, 24 Jul 2008 16:33:15 +1000
> Von: "Mark Macumber" <mark.macumber@...>
> An: dev@...
> Betreff: Random CancelledKeyException\'s

> Hi Everyone,
>
> At the moment I am trying to setup a configurable TCP server that will
> process a proprietary protocol, and I am using JMeter to do some testing.
>
> I have setup JMeter so that it fires of lots of requests on different
> threads, I am doing this because I want to only allow a certain number of
> connections.
>
> While I am doing this though, I seem to get random exceptions, in my log
> files like so:
>
> 2008-07-24 16:29:26,180 [11] ERROR grizzly - doSelect exception
> java.nio.channels.CancelledKeyException
>     at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
>     at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
>     at
> com.sun.grizzly.TCPSelectorHandler.onReadInterest(TCPSelectorHandler.java:650)
>     at com.sun.grizzly.Controller.doSelect(Controller.java:423)
>     at
> com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:82)
>     at
> com.sun.grizzly.Controller.startSelectorHandlerRunner(Controller.java:1117)
>     at com.sun.grizzly.Controller.start(Controller.java:924)
>     at au.com.anz.gsts.gbstp.GBSTPServer$1.run(GBSTPServer.java:90)
>     at java.lang.Thread.run(Thread.java:595)
>
> I am not sure why it happens, I was wondering if anyone else had come
> across
> this type of thing before?
>
> Cheers,
> Mark

--
GMX startet ShortView.de. Hier findest Du Leute mit Deinen Interessen!
Jetzt dabei sein: http://www.shortview.de/wasistshortview.php?mc=sv_ext_mf@gmx

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...