*TimeOutHandlers
Christian Migowski
chrismfwrd at gmail.com
Mon Feb 9 04:26:36 EST 2009
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