changeset 246:4eaeffc68390

Runners: rebuild console logging
author shade
date Fri, 13 May 2016 01:42:55 +0300
parents 44ed77c659aa
children 43189e8da359
files jcstress-core/src/main/java/org/openjdk/jcstress/JCStress.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/collectors/TestResult.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ConsoleReportPrinter.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ExceptionReportPrinter.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/HTMLReportPrinter.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/processors/JCStressTestProcessor.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/Runner.java jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/TestConfig.java
diffstat 8 files changed, 87 insertions(+), 145 deletions(-) [+]
line wrap: on
line diff
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/JCStress.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/JCStress.java	Fri May 13 01:42:55 2016 +0300
@@ -108,9 +108,10 @@
         if (!opts.shouldParse()) {
             opts.printSettingsOn(out);
 
-            List<TestConfig> configs = prepareRunProgram(opts);
+            SortedSet<String> tests = getTests(opts.getTestFilter());
+            List<TestConfig> configs = prepareRunProgram(opts, tests);
 
-            ConsoleReportPrinter printer = new ConsoleReportPrinter(opts, new PrintWriter(out, true), configs.size());
+            ConsoleReportPrinter printer = new ConsoleReportPrinter(opts, new PrintWriter(out, true), tests.size(), configs.size());
             DiskWriteCollector diskCollector = new DiskWriteCollector(opts.getResultFile());
             TestResultCollector sink = MuxCollector.of(printer, diskCollector);
 
@@ -128,6 +129,7 @@
             diskCollector.close();
         }
 
+        out.println();
         out.println("Reading the results back... ");
 
         InProcessCollector collector = new InProcessCollector();
@@ -148,20 +150,19 @@
         out.println("Done.");
     }
 
-    private List<TestConfig> prepareRunProgram(Options opts) {
-        SortedSet<String> tests = getTests(opts.getTestFilter());
+    private List<TestConfig> prepareRunProgram(Options opts, Set<String> tests) {
         List<TestConfig> configs = new ArrayList<>();
         if (opts.shouldFork()) {
             for (String test : tests) {
                 for (int f = 0; f < opts.getForks(); f++) {
-                    configs.add(new TestConfig(opts, TestList.getInfo(test), TestConfig.RunMode.FORKED));
+                    configs.add(new TestConfig(opts, TestList.getInfo(test), TestConfig.RunMode.FORKED, f));
                 }
             }
         } else {
             for (String test : tests) {
                 TestInfo info = TestList.getInfo(test);
                 TestConfig.RunMode mode = info.requiresFork() ? TestConfig.RunMode.FORKED : TestConfig.RunMode.EMBEDDED;
-                configs.add(new TestConfig(opts, info, mode));
+                configs.add(new TestConfig(opts, info, mode, -1));
             }
         }
         return configs;
@@ -205,7 +206,7 @@
 
             if (ecode != 0) {
                 // Test had failed, record this.
-                TestResult result = new TestResult(config, Status.VM_ERROR);
+                TestResult result = new TestResult(config, Status.VM_ERROR, -1);
                 result.addAuxData(new String(baos.toByteArray()).trim());
                 collector.add(result);
             }
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/collectors/TestResult.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/collectors/TestResult.java	Fri May 13 01:42:55 2016 +0300
@@ -34,30 +34,31 @@
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.List;
-import java.util.UUID;
 
 /**
  * @author Aleksey Shipilev (aleksey.shipilev@oracle.com)
  */
 public class TestResult implements Serializable {
 
-    private static final String VM_ID = UUID.randomUUID().toString();
-
-    private final String vmID;
     private final TestConfig config;
+    private final Status status;
+    private final int iterationId;
     private final Multiset<String> states;
     private volatile Environment env;
-    private final Status status;
     private final List<String> auxData;
 
-    public TestResult(TestConfig config, Status status) {
-        this.vmID = VM_ID;
+    public TestResult(TestConfig config, Status status, int iterationId) {
         this.config = config;
         this.status = status;
+        this.iterationId = iterationId;
         this.states = new HashMultiset<>();
         this.auxData = new ArrayList<>();
     }
 
+    public int getIteration() {
+        return iterationId;
+    }
+
     public void addState(String result, long count) {
         states.add(result, count);
     }
@@ -82,10 +83,6 @@
         return status;
     }
 
-    public String getVmID() {
-        return vmID;
-    }
-
     public List<String> getAuxData() {
         return auxData;
     }
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ConsoleReportPrinter.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ConsoleReportPrinter.java	Fri May 13 01:42:55 2016 +0300
@@ -30,20 +30,15 @@
 import org.openjdk.jcstress.infra.TestInfo;
 import org.openjdk.jcstress.infra.collectors.TestResult;
 import org.openjdk.jcstress.infra.collectors.TestResultCollector;
+import org.openjdk.jcstress.infra.runners.TestConfig;
 import org.openjdk.jcstress.infra.runners.TestList;
 import org.openjdk.jcstress.util.StringUtils;
 
 import javax.xml.bind.JAXBException;
 import java.io.FileNotFoundException;
 import java.io.PrintWriter;
-import java.util.ArrayList;
-import java.util.HashMap;
-import java.util.List;
-import java.util.Map;
-import java.util.concurrent.ConcurrentHashMap;
-import java.util.concurrent.ConcurrentMap;
+import java.util.*;
 import java.util.concurrent.TimeUnit;
-import java.util.concurrent.atomic.AtomicLong;
 
 /**
  * Prints the test results to the console.
@@ -55,62 +50,52 @@
     private final boolean verbose;
     private final Options opts;
     private final PrintWriter output;
-    private final int expectedTests;
-    private final int expectedIterations;
-    private final int expectedForks;
+    private final long expectedTests;
+    private final long expectedIterations;
+    private final long expectedConfigs;
 
-    private AtomicLong observedResults = new AtomicLong();
-    private AtomicLong observedCount = new AtomicLong();
+    private long observedIterations;
+    private long observedCount;
 
-    private final ConcurrentMap<String, TestProgress> testsProgress = new ConcurrentHashMap<>();
-    private final int totalExpectedResults;
+    private final Set<String> observedTests = Collections.newSetFromMap(new HashMap<>());
+    private final Set<TestConfig> observedConfigs = Collections.newSetFromMap(new HashMap<>());
 
     private long firstTest;
+    private int progressLen;
 
-    public ConsoleReportPrinter(Options opts, PrintWriter pw, int expectedTests) throws JAXBException, FileNotFoundException {
+    public ConsoleReportPrinter(Options opts, PrintWriter pw, int expectedTests, int expectedConfigs) throws JAXBException, FileNotFoundException {
         this.opts = opts;
         this.output = pw;
         this.expectedTests = expectedTests;
-        this.expectedForks = opts.getForks();
-        this.expectedIterations = opts.getIterations();
-        this.totalExpectedResults = expectedTests * opts.getIterations() * (opts.getForks() > 0 ? opts.getForks() : 1);
+        this.expectedConfigs = expectedConfigs;
+        this.expectedIterations = expectedConfigs * opts.getIterations() * (opts.getForks() > 0 ? opts.getForks() : 1);
         verbose = opts.isVerbose();
+        progressLen = 1;
     }
 
     @Override
-    public void add(TestResult r) {
-        TestProgress e = testsProgress.get(r.getName());
-        if (e == null) {
-            e = new TestProgress(r);
-            TestProgress exist = testsProgress.putIfAbsent(r.getName(), e);
-            e = (exist != null) ? exist : e;
+    public synchronized void add(TestResult r) {
+        if (firstTest == 0) {
+            firstTest = System.nanoTime();
         }
 
-        if (opts.getForks() > 0) {
-            e.enregisterVM(r.getVmID());
-        } else {
-            e.enregisterVM(null);
-        }
-
-        if (firstTest == 0) {
-            firstTest = System.nanoTime();
-        } else {
-            observedResults.incrementAndGet();
-            observedCount.addAndGet(r.getTotalCount());
-        }
+        observedTests.add(r.getName());
+        observedConfigs.add(r.getConfig());
+        observedIterations++;
+        observedCount += r.getTotalCount();
 
         printResult(r, verbose);
     }
 
-    public void printResult(TestResult r, boolean isVerbose) {
+    private void printResult(TestResult r, boolean isVerbose) {
         switch (r.status()) {
             case TIMEOUT_ERROR:
-                printLine(output, "TIMEOUT", r);
+                printLine("TIMEOUT", r);
                 return;
             case CHECK_TEST_ERROR:
             case TEST_ERROR:
                 output.println();
-                printLine(output, "ERROR", r);
+                printLine("ERROR", r);
                 for (String data : r.getAuxData()) {
                     output.println(data);
                 }
@@ -118,28 +103,28 @@
                 return;
             case VM_ERROR:
                 output.println();
-                printLine(output, "VM ERROR", r);
+                printLine("VM ERROR", r);
                 for (String data : r.getAuxData()) {
                     output.println(data);
                 }
                 output.println();
                 return;
             case API_MISMATCH:
-                printLine(output, "SKIPPED", r);
+                printLine("SKIPPED", r);
                 return;
             case NORMAL:
                 TestInfo test = TestList.getInfo(r.getName());
                 if (test == null) {
                     output.println();
-                    printLine(output, "UNKNOWN", r);
+                    printLine("UNKNOWN", r);
                     isVerbose = true;
                 } else {
                     TestGrading grading = new TestGrading(r, test);
                     if (grading.isPassed) {
-                        printLine(output, "OK", r);
+                        printLine("OK", r);
                     } else {
                         output.println();
-                        printLine(output, "FAILED", r);
+                        printLine("FAILED", r);
                         isVerbose = true;
                     }
                 }
@@ -149,6 +134,11 @@
         }
 
         if (isVerbose) {
+            output.format("    (fork: #%d, iteration #%d)%n",
+                    r.getConfig().forkId + 1,
+                    r.getIteration() + 1
+            );
+
             int idLen = "Observed state".length();
             int occLen = "Occurrences".length();
             int expectLen = "Expectation".length();
@@ -223,29 +213,41 @@
 
             output.println();
         }
+
+        printProgress();
     }
 
-    private PrintWriter printLine(PrintWriter output, String label, TestResult r) {
-        return output.printf(" (ETA: %10s) (R: %s) (T:%4d/%d) (F:%2d/%d) (I:%2d/%d) %10s %s\n",
+    private void printLine(String label, TestResult r) {
+        output.printf("\r%" + progressLen + "s\r", "");
+        output.printf("%10s %s\n", "[" + label + "]", chunkName(r.getName()));
+    }
+
+    private void printProgress() {
+        String line = String.format("(ETA: %10s) (Rate: %s samples/sec) (Tests: %4d of %d) (Forks: %2d of %d) (Iterations: %2d of %d) ",
                 computeETA(),
                 computeSpeed(),
-                testsProgress.size(), expectedTests, testsProgress.get(r.getName()).getVMindex(r.getVmID()), expectedForks, testsProgress.get(r.getName()).getIteration(r.getVmID()), expectedIterations,
-                "[" + label + "]", chunkName(r.getName()));
+                observedTests.size(), expectedTests,
+                observedConfigs.size(), expectedConfigs,
+                observedIterations, expectedIterations
+        );
+        progressLen = line.length();
+        output.print(line);
+        output.flush();
     }
 
     private String computeSpeed() {
         long timeSpent = System.nanoTime() - firstTest;
-        return String.format("%3.2E", 1.0 * TimeUnit.SECONDS.toNanos(1) * observedCount.get() / timeSpent);
+        return String.format("%3.2E", 1.0 * TimeUnit.SECONDS.toNanos(1) * observedCount / timeSpent);
     }
 
     private String computeETA() {
         long timeSpent = System.nanoTime() - firstTest;
-        long resultsGot = observedResults.get();
+        long resultsGot = observedIterations;
         if (resultsGot == 0) {
             return "n/a";
         }
 
-        long nsToGo = (long)(timeSpent * (1.0 * (totalExpectedResults - 1) / resultsGot - 1));
+        long nsToGo = (long)(timeSpent * (1.0 * (expectedIterations - 1) / resultsGot - 1));
         if (nsToGo > 0) {
             String result = "";
             long days = TimeUnit.NANOSECONDS.toDays(nsToGo);
@@ -272,62 +274,4 @@
         return name.replace("org.openjdk.jcstress.tests", "o.o.j.t");
     }
 
-    private static class TestProgress {
-        private final String name;
-
-        private int currentVM;
-        private final Map<String, Integer> vmIDs = new HashMap<>();
-        private final Map<String, Integer> iterations = new HashMap<>();
-
-        public TestProgress(TestResult result){
-            this.name = result.getName();
-        }
-
-        @Override
-        public boolean equals(Object o) {
-            if (this == o) return true;
-            if (o == null || getClass() != o.getClass()) return false;
-
-            TestProgress that = (TestProgress) o;
-
-            if (!name.equals(that.name)) return false;
-
-            return true;
-        }
-
-        @Override
-        public int hashCode() {
-            return name.hashCode();
-        }
-
-        public void enregisterVM(String vmID) {
-            if (vmID == null) return;
-            synchronized (this) {
-                Integer id = vmIDs.get(vmID);
-                if (id == null) {
-                    vmIDs.put(vmID, ++currentVM);
-                }
-                Integer iters = iterations.get(vmID);
-                if (iters == null) {
-                    iters = 0;
-                }
-                iterations.put(vmID, ++iters);
-            }
-        }
-
-        public int getVMindex(String vmID) {
-            synchronized (this) {
-                Integer id = vmIDs.get(vmID);
-                return id != null ? id : 0;
-            }
-        }
-
-        public int getIteration(String vmID) {
-            synchronized (this) {
-                Integer iters = iterations.get(vmID);
-                return iters != null ? iters : 0;
-            }
-        }
-    }
-
 }
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ExceptionReportPrinter.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/ExceptionReportPrinter.java	Fri May 13 01:42:55 2016 +0300
@@ -81,7 +81,7 @@
                     }
                 }
 
-                TestResult root = new TestResult(config, status);
+                TestResult root = new TestResult(config, status, 0);
 
                 for (String s : stateCounts.keys()) {
                     root.addState(s, stateCounts.count(s));
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/HTMLReportPrinter.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/grading/HTMLReportPrinter.java	Fri May 13 01:42:55 2016 +0300
@@ -64,7 +64,7 @@
 
     public HTMLReportPrinter(Options opts, InProcessCollector collector) throws JAXBException, FileNotFoundException {
         this.collector = collector;
-        this.printer = new ConsoleReportPrinter(opts, new PrintWriter(System.out, true), 0);
+        this.printer = new ConsoleReportPrinter(opts, new PrintWriter(System.out, true), 0, 0);
         this.resultDir = opts.getResultDest();
         this.verbose = opts.isVerbose();
         new File(resultDir).mkdirs();
@@ -98,7 +98,7 @@
                     auxData.addAll(r.getAuxData());
                 }
 
-                TestResult root = new TestResult(name, status);
+                TestResult root = new TestResult(name, status, 0);
 
                 for (String s : stateCounts.keys()) {
                     root.addState(s, stateCounts.count(s));
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/processors/JCStressTestProcessor.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/processors/JCStressTestProcessor.java	Fri May 13 01:42:55 2016 +0300
@@ -562,7 +562,7 @@
         pw.println("            testLog.flush();");
         pw.println("            run(results);");
         pw.println();
-        pw.println("            dump(testName, results);");
+        pw.println("            dump(c, results);");
         pw.println();
         pw.println("            if (results.count(Outcome.STALE) > 0) {");
         pw.println("                testLog.println(\"Have stale threads, forcing VM to exit\");");
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/Runner.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/Runner.java	Fri May 13 01:42:55 2016 +0300
@@ -79,12 +79,12 @@
         } catch (NoClassDefFoundError | NoSuchMethodError | NoSuchFieldError e) {
             testLog.println("Test sanity check failed, skipping");
             testLog.println();
-            dumpFailure(testName, Status.API_MISMATCH, e);
+            dumpFailure(-1, Status.API_MISMATCH, e);
             return;
         } catch (Throwable e) {
             testLog.println("Check test failed");
             testLog.println();
-            dumpFailure(testName, Status.CHECK_TEST_ERROR, e);
+            dumpFailure(-1, Status.CHECK_TEST_ERROR, e);
             return;
         }
 
@@ -98,19 +98,18 @@
 
             testLog.print(".");
             testLog.flush();
-            dump(testName, internalRun());
+            dump(c, internalRun());
         }
         testLog.println();
     }
 
-
-    protected void dumpFailure(String testName, Status status) {
-        TestResult result = new TestResult(config, status);
+    protected void dumpFailure(int iteration, Status status) {
+        TestResult result = new TestResult(config, status, iteration);
         collector.add(result);
     }
 
-    protected void dumpFailure(String testName, Status status, Throwable aux) {
-        TestResult result = new TestResult(config, status);
+    protected void dumpFailure(int iteration, Status status, Throwable aux) {
+        TestResult result = new TestResult(config, status, iteration);
         StringWriter sw = new StringWriter();
         PrintWriter pw = new PrintWriter(sw);
         aux.printStackTrace(pw);
@@ -119,8 +118,8 @@
         collector.add(result);
     }
 
-    protected void dump(String testName, Counter<R> results) {
-        TestResult result = new TestResult(config, Status.NORMAL);
+    protected void dump(int iteration, Counter<R> results) {
+        TestResult result = new TestResult(config, Status.NORMAL, iteration);
 
         for (R e : results.elementSet()) {
             result.addState(String.valueOf(e), results.count(e));
@@ -144,7 +143,7 @@
                 } catch (TimeoutException e) {
                     allStopped = false;
                 } catch (ExecutionException e) {
-                    dumpFailure(testName, Status.TEST_ERROR, e.getCause());
+                    dumpFailure(-1, Status.TEST_ERROR, e.getCause());
                     return;
                 } catch (InterruptedException e) {
                     return;
@@ -152,7 +151,7 @@
             }
 
             if (TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime) > Math.max(config.time, 60*1000)) {
-                dumpFailure(testName, Status.TIMEOUT_ERROR);
+                dumpFailure(-1, Status.TIMEOUT_ERROR);
                 return;
             }
         }
--- a/jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/TestConfig.java	Fri May 13 00:41:21 2016 +0300
+++ b/jcstress-core/src/main/java/org/openjdk/jcstress/infra/runners/TestConfig.java	Fri May 13 01:42:55 2016 +0300
@@ -43,14 +43,16 @@
     public final String generatedRunnerName;
     public final String appendJvmArgs;
     public final RunMode runMode;
+    public final int forkId;
 
     public enum RunMode {
         EMBEDDED,
         FORKED,
     }
 
-    public TestConfig(Options opts, TestInfo info, RunMode runMode) {
+    public TestConfig(Options opts, TestInfo info, RunMode runMode, int forkId) {
         this.runMode = runMode;
+        this.forkId = forkId;
         time = opts.getTime();
         minStride = opts.getMinStride();
         maxStride = opts.getMaxStride();
@@ -82,7 +84,6 @@
         if (!name.equals(that.name)) return false;
         if (!generatedRunnerName.equals(that.generatedRunnerName)) return false;
         return appendJvmArgs.equals(that.appendJvmArgs);
-
     }
 
     @Override