*TimeOutHandlers
Trustin Lee
trustin at gleamynode.net
Mon Feb 9 06:51:58 EST 2009
Great to hear that! :D
Write timeout will not be fired very often because it is fired only
when a message is not written within the specified timeout. It will
never be fired in most loopback device tests. To see it fired, you
will have to set the timeout around 1 ms.
Please note that it's different from MINA's writerIdle status.
There's no counterpart in Netty at this point. Do you find writer
idleness notification useful? For what case, out of curiosity?
Thanks!
— Trustin Lee, http://gleamynode.net/
On Mon, Feb 9, 2009 at 8:39 PM, Christian Migowski <chrismfwrd at gmail.com> wrote:
> I am running some tests in parallel right now and so far it seems that
> the issue is gone, hooray! :-)
> Sorry for suspecting Netty in the first place, I am glad that this OS
> shortcoming could be resolved that easy.
>
> Now there is only the problem that the writetimeout never fires
> although it should.
>
> thanks,
> christian
>
>
>
>
> On Mon, Feb 9, 2009 at 12:30 PM, Trustin Lee <trustin at gleamynode.net> wrote:
>> Revision number in SVN is 813 FYI.
>>
>> — Trustin Lee, http://gleamynode.net/
>>
>>
>>
>> On Mon, Feb 9, 2009 at 8:00 PM, Trustin Lee <trustin at gleamynode.net> wrote:
>>> Thanks for a useful information. The reason I was not able to
>>> reproduce the problem is probably because I was running Windows in a
>>> virtual machine. :-(
>>>
>>> I've just checked in a revised version of HashedWheelTimer that uses
>>> System.currentTimeMillis() instead of System.nanoTime(). Could you
>>> tell me if it fixes the problem?
>>>
>>> — Trustin Lee, http://gleamynode.net/
>>>
>>> On Mon, Feb 9, 2009 at 6:54 PM, Christian Migowski <chrismfwrd at gmail.com> wrote:
>>>> Mr. Google reports that there are rumors in the Internet that
>>>> System.nanoTime is broken on multicore systems (which I have), maybe
>>>> this could be an issue? You're comparing and retrieving the nanotimes
>>>> between multiple threads...
>>>>
>>>> I personally think that the resolution of System.currentTimeMillis()
>>>> should be sufficient for connection idle issues. With that you can
>>>> theoretically go as low as 1ms and that is far lower then a sane idle
>>>> timeout should be set for a network connection.
>>>>
>>>> http://stackoverflow.com/questions/510462/is-system-nanotime-completely-useless/518438
>>>> http://www.principiaprogramatica.com/?p=16
>>>> http://blogs.sun.com/dholmes/entry/inside_the_hotspot_vm_clocks
>>>>
>>>> christian
>>>>
>>>> On Mon, Feb 9, 2009 at 10:26 AM, Christian Migowski
>>>> <chrismfwrd at gmail.com> wrote:
>>>>> Hi Trustin,
>>>>>
>>>>> I am using Windows XP SP2 with Java SE 1.6, to be precise:
>>>>> java version "1.6.0_07"
>>>>> Java(TM) SE Runtime Environment (build 1.6.0_07-b06)
>>>>> Java HotSpot(TM) Client VM (build 10.0-b23, mixed mode, sharing)
>>>>>
>>>>> Upon further investigation, I found the inaccurateness occurs only
>>>>> sometimes, but it sure follows very strange ways. Sometimes the
>>>>> timeouts happen as they should but then they degenerate. Sometimes the
>>>>> timeouts start inaccurate, but getting more correct after some time.
>>>>> I suspect a flaw in the implementation of the HashedWheelTimer, but
>>>>> haven't got familiar with the source yet to point you to a specific
>>>>> issue.
>>>>>
>>>>> I think you should be able to reproduce the behaviour, if the timer
>>>>> starts correctly, keep it running for some time (5-10 minutes?), the
>>>>> inaccurateness should show up then.
>>>>> I'll list two examples below, the first one starts correct but gets
>>>>> incorrect after 6:42 mins. the second one starts incorrect but after
>>>>> 3:54 mins (and gets incorrect again).
>>>>>
>>>>> Sorry for not being able yet to give more detailed hints,
>>>>> regards,
>>>>>
>>>>> christian!
>>>>>
>>>>>
>>>>> Here the logs:
>>>>>
>>>>> Number 1:
>>>>> server started...
>>>>> channel connected: NioAcceptedSocketChannel(id:
>>>>> 5a3d1859-011f-1000-913d-0107798aa198, /127.0.0.1:24235 =>
>>>>> /127.0.0.1:12345)
>>>>> 09:52:49.714
>>>>> 09:52:59.755 readtimeout
>>>>> 09:53:09.766 readtimeout
>>>>> 09:53:19.791 readtimeout
>>>>> 09:53:29.802 readtimeout
>>>>> 09:53:39.827 readtimeout
>>>>> 09:53:49.853 readtimeout
>>>>> 09:53:59.863 readtimeout
>>>>> 09:54:09.889 readtimeout
>>>>> 09:54:19.899 readtimeout
>>>>> 09:54:29.925 readtimeout
>>>>> 09:54:39.951 readtimeout
>>>>> 09:54:49.961 readtimeout
>>>>> 09:54:59.987 readtimeout
>>>>> 09:55:09.997 readtimeout
>>>>> 09:55:20.023 readtimeout
>>>>> 09:55:30.049 readtimeout
>>>>> 09:55:40.059 readtimeout
>>>>> 09:55:50.085 readtimeout
>>>>> 09:56:00.095 readtimeout
>>>>> 09:56:10.121 readtimeout
>>>>> 09:56:20.146 readtimeout
>>>>> 09:56:30.151 readtimeout
>>>>> 09:56:40.188 readtimeout
>>>>> 09:56:50.350 readtimeout
>>>>> 09:57:00.356 readtimeout
>>>>> 09:57:10.377 readtimeout
>>>>> 09:57:20.399 readtimeout
>>>>> 09:57:30.404 readtimeout
>>>>> 09:57:40.426 readtimeout
>>>>> 09:57:50.431 readtimeout
>>>>> 09:58:00.453 readtimeout
>>>>> 09:58:10.474 readtimeout
>>>>> 09:58:20.479 readtimeout
>>>>> 09:58:30.489 readtimeout
>>>>> 09:58:40.484 readtimeout
>>>>> 09:58:50.494 readtimeout
>>>>> 09:59:00.505 readtimeout
>>>>> 09:59:10.500 readtimeout
>>>>> 09:59:20.510 readtimeout
>>>>> 09:59:30.520 readtimeout
>>>>> 09:59:41.702 readtimeout
>>>>> 09:59:54.243 readtimeout
>>>>> 10:00:06.689 readtimeout
>>>>> 10:00:18.792 readtimeout
>>>>> 10:00:31.130 readtimeout
>>>>> 10:00:43.529 readtimeout
>>>>> 10:00:55.617 readtimeout
>>>>> 10:01:08.532 readtimeout
>>>>> 10:01:21.088 readtimeout
>>>>> 10:01:33.660 readtimeout
>>>>> 10:01:46.231 readtimeout
>>>>> 10:01:58.678 readtimeout
>>>>> 10:02:10.937 readtimeout
>>>>> 10:02:23.197 readtimeout
>>>>> 10:02:35.674 readtimeout
>>>>> 10:02:47.637 readtimeout
>>>>> 10:03:00.177 readtimeout
>>>>> 10:03:12.499 readtimeout
>>>>> 10:03:24.620 readtimeout
>>>>> 10:03:36.961 readtimeout
>>>>> 10:03:49.208 readtimeout
>>>>> 10:04:01.378 readtimeout
>>>>> 10:04:13.953 readtimeout
>>>>> 10:04:26.389 readtimeout
>>>>> 10:04:38.730 readtimeout
>>>>> 10:04:50.915 readtimeout
>>>>> 10:05:03.600 readtimeout
>>>>> 10:05:15.582 readtimeout
>>>>> 10:05:28.470 readtimeout
>>>>> 10:05:40.702 readtimeout
>>>>> 10:05:53.121 readtimeout
>>>>> 10:06:05.713 readtimeout
>>>>> 10:06:18.491 readtimeout
>>>>> 10:06:30.645 readtimeout
>>>>> 10:06:43.002 readtimeout
>>>>> 10:06:55.437 readtimeout
>>>>> 10:07:07.700 readtimeout
>>>>> 10:07:20.010 readtimeout
>>>>> 10:07:32.586 readtimeout
>>>>> 10:07:44.552 readtimeout
>>>>> 10:07:57.081 readtimeout
>>>>>
>>>>>
>>>>> Number 2:
>>>>> channel connected
>>>>> channel connected: NioClientSocketChannel(id:
>>>>> 5a4b68fb-011f-1000-8352-01cb22f8a2e1, /127.0.0.1:24717 =>
>>>>> localhost/127.0.0.1:12345)
>>>>> message sent
>>>>> 10:08:25.592
>>>>> 10:08:38.060
>>>>> 10:08:50.184
>>>>> 10:09:02.995
>>>>> 10:09:14.854
>>>>> 10:09:27.259
>>>>> 10:09:39.696
>>>>> 10:09:52.085
>>>>> 10:10:04.225
>>>>> 10:10:16.802
>>>>> 10:10:28.989
>>>>> 10:10:41.128
>>>>> 10:10:53.674
>>>>> 10:11:05.970
>>>>> 10:11:18.219
>>>>> 10:11:30.999
>>>>> 10:11:43.483
>>>>> 10:11:56.029
>>>>> 10:12:08.653
>>>>> 10:12:19.589
>>>>> 10:12:29.604
>>>>> 10:12:39.604
>>>>> 10:12:49.618
>>>>> 10:12:59.618
>>>>> 10:13:09.633
>>>>> 10:13:19.647
>>>>> 10:13:29.647
>>>>> 10:13:39.662
>>>>> 10:13:49.677
>>>>> 10:13:59.677
>>>>> 10:14:09.692
>>>>> 10:14:19.692
>>>>> 10:14:29.707
>>>>> 10:14:39.722
>>>>> 10:14:49.722
>>>>> 10:14:59.737
>>>>> 10:15:09.737
>>>>> 10:15:18.797
>>>>> 10:15:25.737
>>>>> 10:15:32.665
>>>>> 10:15:39.605
>>>>> 10:15:46.544
>>>>> 10:15:53.473
>>>>> 10:16:00.412
>>>>> 10:16:07.341
>>>>> 10:16:14.281
>>>>> 10:16:21.220
>>>>> 10:16:28.149
>>>>> 10:16:35.088
>>>>> 10:16:42.017
>>>>> 10:16:48.956
>>>>> 10:16:55.896
>>>>> 10:17:02.824
>>>>> 10:17:09.764
>>>>> 10:17:16.692
>>>>> 10:17:23.632
>>>>> 10:17:30.571
>>>>> 10:17:37.500
>>>>> 10:17:44.439
>>>>> 10:17:51.368
>>>>> 10:17:58.308
>>>>> 10:18:05.247
>>>>> 10:18:12.176
>>>>> 10:18:19.115
>>>>> 10:18:26.044
>>>>> 10:18:32.983
>>>>> 10:18:39.923
>>>>> 10:18:47.512
>>>>> 10:18:56.405
>>>>> 10:19:05.297
>>>>> 10:19:14.175
>>>>> 10:19:23.067
>>>>> 10:19:31.946
>>>>> 10:19:40.838
>>>>> 10:19:49.730
>>>>> 10:19:58.608
>>>>> 10:20:07.501
>>>>> 10:20:16.393
>>>>> 10:20:25.271
>>>>> 10:20:34.163
>>>>> 10:20:43.042
>>>>> 10:20:51.934
>>>>> 10:21:00.812
>>>>> 10:21:09.705
>>>>> 10:21:18.597
>>>>> 10:21:27.475
>>>>> 10:21:36.367
>>>>> 10:21:45.246
>>>>> 10:21:54.138
>>>>> 10:22:03.030
>>>>> 10:22:11.908
>>>>> 10:22:20.801
>>>>> 10:22:29.693
>>>>> 10:22:38.571
>>>>>
>>>>>
>>>>> On Sun, Feb 8, 2009 at 2:14 PM, Trustin Lee <trustin at gleamynode.net> wrote:
>>>>>> Christian,
>>>>>>
>>>>>> ReadTimeoutHandler seems to work just fine with JDK 1.6.0.12, Windows
>>>>>> Vista SP1. Could you tell me your environment more in detail?
>>>>>>
>>>>>> server started...
>>>>>> channel connected: NioAcceptedSocketChannel(id:
>>>>>> 56024241-011f-1000-a20b-01e853f4ddac, /127.0.0.1:50050 =>
>>>>>> /127.0.0.1:12345)
>>>>>> 22:10:14.354
>>>>>> 22:10:24.393 readtimeout
>>>>>> 22:10:34.479 readtimeout
>>>>>> 22:10:44.465 readtimeout
>>>>>> 22:10:54.438 readtimeout
>>>>>> 22:11:04.414 readtimeout
>>>>>> 22:11:14.370 readtimeout
>>>>>> 22:11:24.314 readtimeout
>>>>>> 22:11:34.252 readtimeout
>>>>>> 22:11:44.179 readtimeout
>>>>>> 22:11:54.143 readtimeout
>>>>>> 22:12:04.067 readtimeout
>>>>>> 22:12:14.008 readtimeout
>>>>>> 22:12:23.955 readtimeout
>>>>>> 22:12:33.929 readtimeout
>>>>>> 22:12:43.890 readtimeout
>>>>>> 22:12:53.814 readtimeout
>>>>>> 22:13:03.761 readtimeout
>>>>>> 22:13:13.714 readtimeout
>>>>>> 22:13:23.661 readtimeout
>>>>>> ...
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> — Trustin Lee, http://gleamynode.net/
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Sun, Feb 8, 2009 at 4:01 PM, Trustin Lee <trustin at gleamynode.net> wrote:
>>>>>>> Hi Christian,
>>>>>>>
>>>>>>> Thanks to your test code, I was able to fix the
>>>>>>> IllegalArgumentException. It should never happen now.
>>>>>>>
>>>>>>> However, I was not able to reproduce the inaccurate delay issue in my
>>>>>>> environment. I think your system might be returning an inaccurate
>>>>>>> value when HashedWheelTimer calls System.nanoTime(). What operating
>>>>>>> system are you using? (I suspect it's Windows again :) Anyway,
>>>>>>> HashedWheelTimer should work even if the precision of
>>>>>>> System.nanoTime() is not good enough. Let me keep tracking down the
>>>>>>> problem.
>>>>>>>
>>>>>>> Cheers,
>>>>>>>
>>>>>>> — Trustin Lee, http://gleamynode.net/
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Fri, Feb 6, 2009 at 10:06 PM, Christian Migowski
>>>>>>> <chrismfwrd at gmail.com> wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> I was playing around with the new TimeoutHandlers (which are a great
>>>>>>>> addition to Netty!) and found out that they are quite inaccurate. I
>>>>>>>> setup a small sample which one server and just one client which are
>>>>>>>> not sending regular messages, just in case of a timeout, and found out
>>>>>>>> that the read timeout is of up to 4 seconds (in both directions) when
>>>>>>>> wanting a 10 second timeout. Here is how I setup the server chain
>>>>>>>> (client doesn't do timeout handling):
>>>>>>>>
>>>>>>>> Timer timer = new HashedWheelTimer(10, TimeUnit.MILLISECONDS, 10);
>>>>>>>> pipeline.addLast("readTimeout", new ReadTimeoutHandler(timer, 10,
>>>>>>>> TimeUnit.SECONDS));
>>>>>>>> pipeline.addLast("writeTimeout", new WriteTimeoutHandler(timer, 5,
>>>>>>>> TimeUnit.SECONDS));
>>>>>>>>
>>>>>>>> pipeline.addLast("handler", new TestHandler());
>>>>>>>>
>>>>>>>>
>>>>>>>> and this is the exceptionCaught() of TestHandler method:
>>>>>>>> public void exceptionCaught(ChannelHandlerContext ctx, ExceptionEvent e) {
>>>>>>>> if (e.getCause() instanceof ChannelWriteTimeoutException) {
>>>>>>>> System.out.println(new
>>>>>>>> SimpleDateFormat("HH:mm:ss.SSS").format(new Date())+" writetimeout");
>>>>>>>> writeTime(e.getChannel());
>>>>>>>> } else if (e.getCause() instanceof ChannelReadTimeoutException) {
>>>>>>>> System.out.println(new
>>>>>>>> SimpleDateFormat("HH:mm:ss.SSS").format(new Date())+" readtimeout");
>>>>>>>> writeTime(e.getChannel());
>>>>>>>> } else {
>>>>>>>> e.getCause().printStackTrace();
>>>>>>>> Channel ch = e.getChannel();
>>>>>>>> ch.close().awaitUninterruptibly();
>>>>>>>> System.out.println("channel closed");
>>>>>>>> }
>>>>>>>> }
>>>>>>>>
>>>>>>>> it produces e.g. this output:
>>>>>>>>
>>>>>>>> 13:58:39.773 readtimeout
>>>>>>>> 13:58:46.634 readtimeout
>>>>>>>> 13:58:53.506 readtimeout
>>>>>>>> 13:59:00.378 readtimeout
>>>>>>>> 13:59:07.238 readtimeout
>>>>>>>> 13:59:14.110 readtimeout
>>>>>>>> 13:59:20.971 readtimeout
>>>>>>>> 13:59:27.843 readtimeout
>>>>>>>> 13:59:34.714 readtimeout
>>>>>>>> 13:59:41.575 readtimeout
>>>>>>>> 13:59:48.447 readtimeout
>>>>>>>> 13:59:55.319 readtimeout
>>>>>>>> 14:00:02.179 readtimeout
>>>>>>>> 14:00:09.120 readtimeout
>>>>>>>> 14:00:17.974 readtimeout
>>>>>>>>
>>>>>>>>
>>>>>>>> as you can see it is never 10 seconds. Also, although the writetimeout
>>>>>>>> is set lower, it is never fired, which seems like a bug to me.
>>>>>>>> Also, because of that inaccurateness, sometimes exceptions in the
>>>>>>>> timer occur (this is not always reproducable):
>>>>>>>>
>>>>>>>> 06.02.2009 12:37:00 org.jboss.netty.handler.timeout.HashedWheelTimer
>>>>>>>> WARNUNG: An exception was thrown by TimerTask.
>>>>>>>> java.lang.IllegalArgumentException: delay must be greater than
>>>>>>>> 10000000 nanoseconds
>>>>>>>> at org.jboss.netty.handler.timeout.HashedWheelTimer.checkDelay(HashedWheelTimer.java:242)
>>>>>>>> at org.jboss.netty.handler.timeout.HashedWheelTimer.newTimeout(HashedWheelTimer.java:197)
>>>>>>>> at org.jboss.netty.handler.timeout.ReadTimeoutHandler$ReadTimeoutTask.run(ReadTimeoutHandler.java:145)
>>>>>>>> at org.jboss.netty.handler.timeout.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:399)
>>>>>>>> at org.jboss.netty.handler.timeout.HashedWheelTimer$Worker.notifyExpiredTimeouts(HashedWheelTimer.java:318)
>>>>>>>> at org.jboss.netty.handler.timeout.HashedWheelTimer$Worker.run(HashedWheelTimer.java:266)
>>>>>>>> at java.lang.Thread.run(Thread.java:595)
>>>>>>>>
>>>>>>>>
>>>>>>>> Is this (the inaccurateness) expected because of the implementation of
>>>>>>>> the HashedWheelTimer or did I just choose unlucky values? Or is it a
>>>>>>>> bug in the timer implementation?
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> greetings,
>>>>>>>> christian!
>>>>>>>> _______________________________________________
>>>>>>>> netty-users mailing list
>>>>>>>> netty-users at lists.jboss.org
>>>>>>>> https://lists.jboss.org/mailman/listinfo/netty-users
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>> _______________________________________________
>>>>>> netty-users mailing list
>>>>>> netty-users at lists.jboss.org
>>>>>> https://lists.jboss.org/mailman/listinfo/netty-users
>>>>>>
>>>>>
>>>>
>>>> _______________________________________________
>>>> netty-users mailing list
>>>> netty-users at lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/netty-users
>>>>
>>>
>>
>> _______________________________________________
>> netty-users mailing list
>> netty-users at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/netty-users
>>
>
> _______________________________________________
> netty-users mailing list
> netty-users at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/netty-users
>
More information about the netty-users
mailing list