*TimeOutHandlers
Christian Migowski
chrismfwrd at gmail.com
Mon Feb 9 04:54:48 EST 2009
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
>>
>
More information about the netty-users
mailing list