Unexpected behaviour using concurrenttestrunner, repeatingrule and a sleep in test

[GoogleCodeExporter]

To repeat run the following test:
import com.google.code.tempusfugit.concurrency.ConcurrentTestRunner;
import com.google.code.tempusfugit.concurrency.RepeatingRule;
import com.google.code.tempusfugit.concurrency.annotations.Repeating;
import org.junit.Rule;
import org.junit.Test;
import org.junit.runner.RunWith;

import java.util.concurrent.atomic.AtomicInteger;

import static com.google.code.tempusfugit.concurrency.ThreadUtils.sleep;
import static com.google.code.tempusfugit.temporal.Duration.millis;

@RunWith(ConcurrentTestRunner.class)
public class RunConcurrentWithRepeatTest {
    @Rule
    public RepeatingRule rule = new RepeatingRule();

    private static final AtomicInteger counter = new AtomicInteger();

    @Test
    @Repeating(repetition = 1000)
    public void runsMultipleTimes() {
        int count = counter.getAndIncrement();
        System.out.println("count = "+count);
        sleep(millis(100));
    }
}

What is the expected output? What do you see instead?
Expect to print out numbers 1 to 1000
Instead prints out numbers 1 to 100

What version of the product are you using? On what operating system?
Using 1.0 of tempusfugit
Running test in intellij
Tested on both windows xp and Mac snowleopard

Original issue reported on code.google.com by ttenn...@gmail.com on 8 Apr 2010 at 6:10

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

I think the sleep is messing things up, running

@RunWith(ConcurrentTestRunner.class)
public class ConcurrentTestRunnerWithRepeatTest {

    @Rule public RepeatingRule rule = new RepeatingRule();

    private static final AtomicInteger counter = new AtomicInteger();

    @Test
    @Repeating(repetition = 1000)
    public void runsMultipleTimes() {
        counter.getAndIncrement();
    }

    @AfterClass
    public static void assertRepetitionCount() {
        assertThat(counter.get(), is(1000));
    }

}

seems to work fine, if you chuck the system out in the @AfterClass, it shows as 
1000
(see Bug #10 though for why the assert can't be trusted).

I'm playing it with it though as its very curious...

Original comment by toby.wes...@gmail.com on 8 Apr 2010 at 8:07

[GoogleCodeExporter]

for example, try changing the sleep time. 

java.lang.AssertionError: 
Expected: is <1000>
     got: <487>

Original comment by toby.wes...@gmail.com on 8 Apr 2010 at 8:14

[GoogleCodeExporter]

You can also produce the same/similar result without a sleep when the method 
under 
test takes a finite amount of time (that's how I discovered this). i.e.,

@RunWith(ConcurrentTestRunner.class)
public class RunConcurrentlyIssueTest {
    @Rule public ConcurrentRule concurrentRule = new ConcurrentRule();
    @Rule public RepeatingRule repeatingRule = new RepeatingRule();

    private static final AtomicInteger counter = new AtomicInteger();

    @Test
    @Repeating(repetition = 1000)
    public void runsMultipleTimes() {
        doSomethingThatTakesSomeTime();
        int count = counter.getAndIncrement();
        System.out.println("count = " + count);
//        sleep(millis(100));
    }

    private void doSomethingThatTakesSomeTime() {
        for(int i=0;i<1000000;i++){
            new StringBuffer("HelloWorld").toString();
        }
    }

    @AfterClass
    public static void afterClass(){
        System.out.println("counter at end = " + counter);
    }
}

Original comment by ttenn...@gmail.com on 8 Apr 2010 at 8:24

[GoogleCodeExporter]

I think I see the problem.

Line 56 of the ConcurrentTestRunner, the wait for is 10 seconds.
public void finished() {
            shutdown(executor).waitingForCompletion(seconds(10));
        }

If you play with the sleep() in the original example, the boundary is about 10 
millis (other statements in the test method affect total execution time), i.e, 
10*1000repeats is 10 seconds.

So if the total time for the test method to complete times the number of 
repeats 
exceed the waitForCompletion of 10 seconds  the executor shuts down anyway.

Original comment by ttenn...@gmail.com on 8 Apr 2010 at 10:46

[GoogleCodeExporter]

Haha I is got a fix :)) 

Modified ConcurrentTestRunner, code below.

Basically added a list to hold the Future objects from the executor.submit. 
Then in 
the finished() method, do a gets on these (which is a blocking call) and only 
exit 
once all the futures have arrived. Don't really need the shutdown(executor) 
call at 
the end either.

package cs.efx.data.caching.soaktest;

import org.junit.runners.BlockJUnit4ClassRunner;
import org.junit.runners.model.InitializationError;
import org.junit.runners.model.RunnerScheduler;

import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Future;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.atomic.AtomicLong;

import static 
com.google.code.tempusfugit.concurrency.ExecutorServiceShutdown.shutdown;
import static java.util.concurrent.Executors.newCachedThreadPool;

public class MyConcurrentTestRunner extends BlockJUnit4ClassRunner {

    public MyConcurrentTestRunner(Class<?> type) throws InitializationError {
        super(type);
        setScheduler(new ConcurrentScheduler());
    }

    private static class ConcurrentScheduler implements RunnerScheduler {

        private ExecutorService executor;
        private final List<Future<?>> futureResults = new ArrayList<Future<?>>();

        public ConcurrentScheduler() {
            executor = newCachedThreadPool(new ThreadFactory() {
                private AtomicLong count = new AtomicLong();

                public Thread newThread(Runnable runnable) {
                    return new Thread(runnable, "MyConcurrentTestRunner-Thread-" + 
count.getAndIncrement());
                }
            });
        }

        public void schedule(Runnable childStatement) {
            futureResults.add(executor.submit(childStatement));
        }

        public void finished() {
            for (Future<?> future : futureResults) {
                try {
                    future.get();
                } catch (Exception e) {
                    e.printStackTrace();
                }
            }
            shutdown(executor);
        }
    }

}

Original comment by ttenn...@gmail.com on 8 Apr 2010 at 11:01

[GoogleCodeExporter]

Awesome! you beat me to it :D

The shutdown will wait for completion, but if it takes more than 10 seconds 
it'll
barf and I guess thats what we're seeing? So your implmentation for finished() 
above
is waiting for them all to be done right?

It might be better if we swap the original shutdown line to

shutdown(executor).waitingForShutdown(timeout(seconds(10));

I'll have a closer look... Its a bit annoying because long running tests would 
need
to be interruptible (ie, respond to interrupt). It might be that we have to use 
a
WaitFor to capture your code above, so ensuring everything is done before even 
trying
to shutdown...

nice one!

Original comment by toby.wes...@gmail.com on 8 Apr 2010 at 12:18

[GoogleCodeExporter]

In fact, doing the gets then calling shutdown is similar to calling
shutdown(service).awaitingCompletion(...) but with no timeout. It calls

exectuor.shutdown();
executor.awaitTermination(...);

It potentially makes sense to have a timeout so I might suggest we allow the 
timeout
to be configurable. What do you think?

RunnerScheduler.finished() gets called pretty early in the junit flow, so the 10
seconds was basically the time all the tests had to execute before they quietly
"timeout". ie, in ParentRunner;

    private void runChildren(final RunNotifier notifier) {
        for (final T each : getFilteredChildren())
            fScheduler.schedule(new Runnable() {            
                public void run() {
                    ParentRunner.this.runChild(each, notifier);
                }
            });
        fScheduler.finished();
    }

So, the thing is scheduled (in our case on a thread) and immediately finished() 
is
called. So from what I can see, you're dead right, we need to block on 
finished()
until they've truly finished. Until the fix, don't expect any tests that take 
>10
seconds to complete to work with the ConcurrentTestRunner (you get the same 
behaviour
even without using the @RepeatingRule).

I'll implement the fix like this

        public void finished() {
            shutdown(executor).waitingForCompletion(days(365));
        }

for now (which is basically the same as your fix IMO) and do a snapshot for 1.1
tonight to include it (if I can write a test!). How does that sound?

I need to have a look at how the junit timeout will affect things too before 
closing
the bug.

Original comment by toby.wes...@gmail.com on 8 Apr 2010 at 1:23

[GoogleCodeExporter]

was thinking

 public class ConcurrentTestRunner extends BlockJUnit4ClassRunner {
@@ -53,8 +54,13 @@
         }

         public void finished() {
-            shutdown(executor).waitingForCompletion(seconds(10));
+            Boolean completed = 
shutdown(executor).waitingForCompletion(millis(1));
+            if (Thread.currentThread().isInterrupted())
+                throw new RuntimeException(new InterruptedException("scheduler
shutdown was interrupted"));
+            if (!completed)
+                throw new RuntimeException(new TimeoutException("scheduler 
shutdown
timed out before tests completed"));
         }
+
     }

 }
\ No newline at end of file

would also highlight the original problem better (although doesn't fail the 
main test
thread but at least puts some useful information out on the screen).

Original comment by toby.wes...@gmail.com on 8 Apr 2010 at 1:59

[GoogleCodeExporter]

Configurable timeout and throwing exception when times out before complete both 
sound like good ideas.

I'll use a locally patched version of this class until you release a fixed 
version.

Thanks for the rapid response(s) on this :)))

Original comment by ttenn...@gmail.com on 8 Apr 2010 at 5:09

[GoogleCodeExporter]

Fixed in r136, waiting to push a snapshot to java.net

Original comment by toby.wes...@gmail.com on 9 Apr 2010 at 8:25

• Changed state: Fixed

[GoogleCodeExporter]

1.1-SNAPSHOT is on java.net now...

Original comment by toby.wes...@gmail.com on 16 May 2010 at 2:32

[GoogleCodeExporter]

1.1 proper available via maven central (java.net is dead! long live maven 
central)

Original comment by toby.wes...@gmail.com on 20 May 2011 at 2:17