Can we test an object that needs initialization and teardown?

[Adam Retter]

I am experiencing a problem with the discussed approach of setting up
my object in the State's constructor and tearing down in the tests
@arbiter. Basically... I am seeing instances of the state object being
created which are never used for a test run. At a glance, the number
of these unused states seems to be related to the number of JVM forks
and tests executed.

For me the problem manifests because I setup my object in the State's
constructor, but as the state is never executed in a test, the
@arbiter of the test never fires and calls my shutdown method on the
state to teardown my object. I then have a bunch of objects which have
not been torn down which leaves dangling resources.

I am wondering if what I am seeing is either:
a) A bug in JCStress, i.e. Every instantiated State object SHOULD be
used by exactly one test.
b) Not a bug in JCStress. This means that I can't use the State
class's constructor for setup/initialization of my objects state
(this is probably relevant to what Jerzy Krolak is trying to
achieve!).

Code to reproduce this in JCStress very easily (with no external dependencies):

import org.openjdk.jcstress.annotations.*;
import org.openjdk.jcstress.infra.results.L_Result;

import java.io.IOException;
import java.lang.management.ManagementFactory;
import java.nio.file.*;
import java.text.SimpleDateFormat;
import java.util.*;

public class StartStopTest {

    @State
    public static class S {
        public final String id = UUID.randomUUID().toString();
        private final Logger logger = new Logger(id);

        public S() {
            logger.log("<init> S() start");

            // do setup...

            logger.log("<init> S() end");
        }
    }

    @JCStressTest
    @Outcome(id = "false", expect = Expect.ACCEPTABLE, desc =
"something that won't happen")
    public static class startupShutdown {

        @Actor
        public void actor1(final S s) {
            s.logger.log("actor1() start");

            // do something

            s.logger.log("actor1() end");
        }

        @Actor
        public void actor2(final S s) {
            s.logger.log("actor2() start");

            // do something

            s.logger.log("actor2() end");
        }

        @Arbiter
        public void arbiter(final S s, final L_Result r) {
            s.logger.log("arbiter() start");

            // do something...
            // do s.teardown...

            r.r1 = true;

            s.logger.log("arbiter() end");
        }
    }

    public static class Logger {
        private final String id;
        private final Path logFile;

        public Logger(final String id) {
            this.id = id;
            this.logFile = Paths.get("/tmp/StartStopTest-" + id + ".log");
            try {
                Files.write(logFile,
Arrays.asList(logTime(System.currentTimeMillis()) + " [" + id + " @ "
+ getPid() + " / " + Thread.currentThread().getName() + "]: <init>
Logger"), StandardOpenOption.CREATE_NEW);
            } catch (final IOException e) {
                throw new RuntimeException(e);
            }
        }

        private static String logTime(final long ms) {
            final SimpleDateFormat sdfDate = new
SimpleDateFormat("HH:mm:ss.SSS");
            return sdfDate.format(new Date(ms));
        }

        private String getPid() {
            return ManagementFactory.getRuntimeMXBean().getName();
        }

        public void log(final String msg) {
            try {
                synchronized (logFile) {
                    Files.write(logFile,
Arrays.asList(logTime(System.currentTimeMillis()) + " [" + id + " @ "
+ getPid() + " / " + Thread.currentThread().getName() + "]: " + msg),
StandardOpenOption.APPEND);
                }
            } catch (final IOException e) {
                throw new RuntimeException(e);
            }
        }
    }
}


If you run this with jcstress, you will find a bunch of log files in
/tmp named StartStopTest-{uuid}.log. A state that has been run through
a test creates a log with content like:

19:15:43.246 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: <init> Logger
19:15:43.246 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: <init> S() start
19:15:43.247 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: <init> S() end
19:15:43.247 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: actor1() start
19:15:43.248 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: actor1() end
19:15:43.248 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: actor2() start
19:15:43.249 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: actor2() end
19:15:43.249 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: arbiter() start
19:15:43.249 [7ee40f98-c66a-4019-94ad-8fcabe317e47 @ 11211 at bob-3.local
/ main]: arbiter() end

You can find the log files for the state instances that were not run
through tests by running:

grep -r -L "arbiter() end" /tmp/StartStopTest-*

Their content looks like:

19:15:47.330 [3cfc94cf-c430-4b40-9f03-d018cf07611f @ 11211 at bob-3.local
/ jcstress-worker-1]: <init> Logger
19:15:47.330 [3cfc94cf-c430-4b40-9f03-d018cf07611f @ 11211 at bob-3.local
/ jcstress-worker-1]: <init> S() start
19:15:47.331 [3cfc94cf-c430-4b40-9f03-d018cf07611f @ 11211 at bob-3.local
/ jcstress-worker-1]: <init> S() end

Which shows that some state instances were not used by a test, as no
actor or arbiter was recorded acting on them in the log file.
On Tue, 9 Oct 2018 at 18:24, Aleksey Shipilev <shade at redhat.com> wrote:
>
> On 10/09/2018 01:22 PM, Adam Retter wrote:
> > I just want to check whether this approach is sane? ...or if I am
> > doing something totally nuts here?
>
> Putting teardown into finally block in @Arbiter is probably okay.
>
> But the "nuts" part is assuming it is sensible to have very heavy-weight @State. The harness is able
> to capture concurrency bugs by executing lot of tests, and spending the significant time at
> setup/teardown works against that. In other words, @State-s are created by millions per test
> (because @Actor-s are basically one-shot per @State), instantiating and shutting down the database
> every time does not look very sane.
>
> -Aleksey
>


-- 
Adam Retter

skype: adam.retter
tweet: adamretter
http://www.adamretter.org.uk