*TimeOutHandlers
Trustin Lee
trustin at gleamynode.net
Mon Feb 9 06:30:51 EST 2009
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
>>
>
More information about the netty-users
mailing list