waitFor not working

[mazz]

I think I found a bug but I need confirmation that I'm using this right.

There are Waiter built-ins. I'm using "waitFor(Object identifier, long millisecsWait)". In my rule, I'm executing specifically this:

waitFor("block", 80000)

I am never signaling this. Essentially, I want a sleep for 80000 millis. This will be a sleep right? If I never signal it, I assume it should timeout after 80000 millis. But I just tried it and I'm not timing out here (I have a System.out.println in my rule immediately after that waitFor but I never see the output, thus I conclude that waitFor never timed out).

I'm looking at the method Waiter.waitFor and in that method I see:

waitFor = millisecs == 0 ? 0 : millisecs + start - System.currentTimeMillis();

what happens if the expression "millisecs + start - System.currentTimeMillis()" comes out to 0? In that case, the this.wait(waitFor) will end up this.wait(0) which will be an indefinite wait, which is not what we want.

Somehow this method needs to guard against that.

[mazz]

I can't get this waitFor(long) to ever return it seems. So I think its more than just the lucky situation where that expression results in 0. I'm not sure what the problem is yet, but for sure, I can't get waitFor(long) to return when I use any amount of millis.

[mazz]

Of course, when I attach a debugger and try to step through this code, it all works perfectly fine :-/

[mazz]

OK, so when its blocked, I then attach to a debugger and its stuck on Waiter line 54 (this.wait(waitFor)) and waitFor is equal to 0, which explains the indefinite block. I do see "millisecs" set to the value I have in my rule (I've tried values between 8 and 80000, and millisecs is always that value, but waitFor for some reason gets set to 0 at some point though I can't see where because I can't attach a debugger to it and see it fail. I can only attach after it blocks - somehow, attaching a debugger before hand changes some timings that lets it succeed).

[mazz]

Twiddled some of the code and I got it to work. I have no idea how or why waitFor ends up being 0 as consistently as I see it happen (and when I attach with a debugger, it never happens), but this patch fixes the problem for me. Notice that explicitly ensure wait(0) is never called unless the caller really wanted to wait indefinitely (i.e. millisecs == 0)

Index: Waiter.java
===================================================================
--- Waiter.java    (revision 372)
+++ Waiter.java    (working copy)
@@ -46,19 +46,22 @@
     public void waitFor(long millisecs)
     {
         long start = System.currentTimeMillis();
-        long waitFor = millisecs == 0 ? 0 : millisecs;
+        long waitForMillis = millisecs;
         synchronized(this) {
             waiting = true;
-            while (!signalled && waitFor >= 0){
+            while (!signalled && waitForMillis >= 0){
                 try {
-                    this.wait(waitFor);
+                    if (waitForMillis == 0 && millisecs > 0) {
+                        break;
+                    }
+                    this.wait(waitForMillis);
                 } catch (InterruptedException e) {
                     // ignore
                 }
                
                 if (!signalled)
                 {
-                   waitFor = millisecs == 0 ? 0 : millisecs + start - System.currentTimeMillis();
+                   waitForMillis = (millisecs == 0) ? 0 : millisecs + start - System.currentTimeMillis();
                 }
             }
             if (signalled) {

[mazz]

https://jira.jboss.org/jira/browse/BYTEMAN-89

[adinn]

Hi John,

John Mazzitelli wrote:

Twiddled some of the code and I got it to work. I have no idea how or why waitFor ends up being 0 as consistently as I see it happen (and when I attach with a debugger, it never happens), but this patch fixes the problem for me. Notice that explicitly ensure wait(0) is never called unless the caller really wanted to wait indefinitely (i.e. millisecs == 0)

Yes, this looks good. The only thing I would change is to use a boolean to record the fact that the original time was zero. I think this makes it a little clearer. YMMV. Please  feel free to check in your fix.

     public void waitFor(long millisecs)

     {
         long start = System.currentTimeMillis();

         boolean waitUnbounded = (milliSecs == 0);
         long waitForMillis = millisecs;
         synchronized(this) {
             waiting = true;
             while (!signalled && (waitForMillis > 0 || waitUnbounded)){
                 try {
                     this.wait(waitForMillis);
                 } catch (InterruptedException e) {
                     // ignore
                 }
                
                 if (!signalled)
                 {
                    waitForMillis = (waitUnbounded) ? 0 : millisecs + start - System.currentTimeMillis();
                 }
             }
             if (signalled) { . . .

I believe you kept hitting the wait(0) case because the timer granularrity is so coarse. Imagine your thread sleeps at time  t and wakes up at time t +  k milliseconds. If t = T + t' where T is an integral number of milliseconds and t' is a fraction of a millisecond then the wake up time will be T + k + t', where k is also integral. When t' is < 0.5 milliseconds this gives an interval of near enough 0.5 - t' milliseconds where the new wait time will be computed as 0 (the computation and loop retest will almost certainly happen in sub-micro-seconds). So, on average the new wait time will be 0 just under half the time.