*TimeOutHandlers
Trustin Lee
trustin at gleamynode.net
Mon Feb 9 06:00:19 EST 2009
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