hopefully fix timeout-related bugs in ILP solver, clean up ILP solver and solver interface

jastadd-mquat-base/src/main/java/de/tudresden/inf/st/mquat/utils/StopWatch.java

@@ -20,7 +20,7 @@ public class StopWatch {
   /**
    * Restarts the measurement.
    */
-  public StopWatch reset() {
+  private StopWatch reset() {
     starts = System.nanoTime();
     return this;
   }

jastadd-mquat-benchmark/src/main/java/de/tudresden/inf/st/mquat/benchmark/Benchmark.java

@@ -296,10 +296,13 @@ public class Benchmark {
     try {
       logger.info("Calling solver '{}'", s.getName());
       result = s.solve(model);
+      if (result == null) {
+        result = Solution.emptySolutionOf(model);
+      }
       boolean validSolution = result.isValid();
-      sb.append(s.doesGeneration() ? s.getLastGenerationTime() : -1).append(SEPARATOR)
+      sb.append(s.doesGeneration() ? s.getLastGenerationTime() : 0).append(SEPARATOR)
           .append(s.getLastSolvingTime()).append(SEPARATOR)
-          .append(s.getLastObjective()).append(SEPARATOR)
+          .append(result.computeObjective()).append(SEPARATOR)
           .append(validSolution);
       logger.debug("Solver {} found {} solution in {}{}ms{}",
           s.getName(),

jastadd-mquat-solver-aco/src/main/java/ir/ac/ui/eng/ACOSolver.java

@@ -298,16 +298,6 @@ public class ACOSolver implements BenchmarkableSolver {
     return lastSolvingTime;
   }
 
-  @Override
-  public double getLastObjective() {
-    if (lastSolution != null) {
-      return lastSolution.computeObjective();
-    } else {
-      // TODO throw exception or do something reasonable
-      return 0d;
-    }
-  }
-
   @Override
   public Solver setTimeout(long timeoutValue, TimeUnit timeoutUnit) {
     this.maxSolvingTime = timeoutUnit.toMillis(timeoutValue);

jastadd-mquat-solver-emfer/src/main/java/uniks/EMFeRSolver.java

@@ -237,16 +237,6 @@ public class EMFeRSolver implements BenchmarkableSolver {
       return lastSolvingTime;
    }
 
-   @Override
-   public double getLastObjective() {
-      if (lastSolution != null) {
-         return lastSolution.computeObjective();
-      } else {
-         // TODO throw exception or do something reasonable
-         return 0d;
-      }
-   }
-
    @Override
    public Solver setTimeout(long timeoutValue, TimeUnit timeoutUnit) {
       this.maxSolvingTime = timeoutUnit.toMillis(timeoutValue);

jastadd-mquat-solver-genetic/src/main/java/de/tudresden/inf/st/mquat/solving/genetic/GeneticSolver.java

@@ -134,16 +134,6 @@ public class GeneticSolver implements BenchmarkableSolver {
     return lastSolvingTime;
   }
 
-  @Override
-  public double getLastObjective() {
-    if (lastSolution != null) {
-      return lastSolution.computeObjective();
-    } else {
-      // TODO throw exception or do something reasonable
-      return 0d;
-    }
-  }
-
   @Override
   public Solver setTimeout(long timeoutValue, TimeUnit timeoutUnit) {
     this.maxSolvingTime = timeoutUnit.toMillis(timeoutValue);

jastadd-mquat-solver-ilp/src/main/java/de/tudresden/inf/st/mquat/solving/ilp/AbstractILPSolver.java

@@ -8,26 +8,19 @@ import de.tudresden.inf.st.mquat.utils.StaticSettings;
 import de.tudresden.inf.st.mquat.utils.StopWatch;
 import org.apache.logging.log4j.Logger;
 
-import java.util.ArrayList;
-import java.util.HashMap;
+import java.util.*;
 import java.util.List;
-import java.util.Map;
 import java.util.concurrent.TimeUnit;
 
 public abstract class AbstractILPSolver implements BenchmarkableSolver {
 
   protected transient final Logger logger;
   protected long lastGeneration;
-  protected long lastSolving;
-  protected long lastSolutionCreation;
-  protected double lastObjective;
+  private long lastSolving;
+  private long lastSolutionCreation;
   protected transient long timeoutValue;
   protected transient TimeUnit timeoutUnit;
-  protected transient long timeoutValueOriginal;
-  protected transient TimeUnit timeoutUnitOriginal;
-  protected long timeoutInSeconds;
   protected boolean timedOut;
-  private boolean resetTimeOut;
 
   /**
    * Create a new, abstract solver with default settings.
@@ -40,15 +33,16 @@ public abstract class AbstractILPSolver implements BenchmarkableSolver {
    */
   public AbstractILPSolver(Logger logger) {
     this.logger = logger;
-    this.resetTimeOut = false;
     setTimeout(1, TimeUnit.MINUTES);
     reset();
   }
 
-  protected void cleanup(StopWatch watch) {
-    setTimeout(this.timeoutValueOriginal, this.timeoutUnitOriginal);
-    lastSolving = watch.time(TimeUnit.MILLISECONDS);
-    logger.debug("Solving took " + lastSolving + "ms.");
+  protected void cleanup() {
+    // empty default implementation
+  }
+
+  protected long getLastSolving() {
+    return lastSolving;
   }
 
   /**
@@ -58,55 +52,47 @@ public abstract class AbstractILPSolver implements BenchmarkableSolver {
     this.lastGeneration = 0;
     this.lastSolving = 0;
     this.lastSolutionCreation = 0;
-    this.lastObjective = 0;
     this.timedOut = false;
-    setTimeout(this.timeoutValueOriginal, this.timeoutUnitOriginal);
   }
 
   @Override
   public synchronized Solution solve(Root model) throws SolvingException {
-    reset();
     StopWatch watch = StopWatch.start();
+
+    reset();
     if (model.getNumRequest() == 0) {
-      lastGeneration = watch.time(TimeUnit.MILLISECONDS);
-      cleanup(watch);
       return Solution.emptySolutionOf(model);
     }
 
-
+    // generate the ILP NTA and take the generation time
     final ILP ilp = model.getILP();
     lastGeneration = watch.time(TimeUnit.MILLISECONDS);
     logger.debug("ILP-Generation took {}ms.", lastGeneration);
     if (ilp.hasTimeout()) {
       logger.error("ILP-Generation exceeded timeout, message: '{}'", ilp.timeoutReason());
-      cleanup(watch);
+      this.lastSolving = watch.time(TimeUnit.MILLISECONDS) - this.lastGeneration;
       return Solution.emptySolutionOf(model);
     }
 
-    if (ilp.getNumIlpVariable() != ilp.getNumIlpBound()) {
-      logger.warn("Different variable ({}) and bound ({}) count", ilp.getNumIlpVariable(), ilp.getNumIlpBound());
-    }
-
-    // temporary update timeout to the remaining time.
-    // calling cleanup will reset it to the original value
-    this.timeoutValueOriginal = this.timeoutValue;
-    this.timeoutUnitOriginal = this.timeoutUnit;
-    long nanosRemaining = this.timeoutUnit.toNanos(this.timeoutValue) - watch.time();
+    long nanosRemaining = this.timeoutUnit.toNanos(this.timeoutValue) - watch.time(TimeUnit.NANOSECONDS);
     if (nanosRemaining < 0) {
-      logger.error("ILP-Generation actually timed out");
-      cleanup(watch);
+      logger.error("ILP-Generation did not report a timeout, but it actually did.");
       return Solution.emptySolutionOf(model);
     }
-    setTimeout(nanosRemaining, TimeUnit.NANOSECONDS);
 
+    // provide data structure for ilp-encoded solution
     List<IlpVariable> variablesSetToOne = new ArrayList<>();
-    watch.reset();
 
     // call to abstract method
-    lastObjective = solve0(model, watch, variablesSetToOne);
-
-    cleanup(watch);
-    return populateSolution(variablesSetToOne, new ILPSolution(model));
+    try {
+      solve0(model, watch, variablesSetToOne);
+      this.lastSolving = watch.time(TimeUnit.MILLISECONDS) - this.lastGeneration;
+      // translate ilp-encoded solution to MQuAT solution
+      return populateSolution(variablesSetToOne, new ILPSolution(model));
+    } finally {
+      // always clean up
+      cleanup();
+    }
   }
 
   /**
@@ -141,14 +127,9 @@ public abstract class AbstractILPSolver implements BenchmarkableSolver {
     this.timeoutValue = timeoutValue;
     StaticSettings.put(Root.ILP_TIMEOUT_VALUE, timeoutValue);
     StaticSettings.put(Root.ILP_TIMEOUT_UNIT, timeoutUnit);
-    recomputeTimeoutInSeconds();
     return this;
   }
 
-  protected void recomputeTimeoutInSeconds() {
-    this.timeoutInSeconds = timeoutUnit.toSeconds(timeoutValue);
-  }
-
   @Override
   public boolean doesGeneration() {
     return true;
@@ -164,11 +145,6 @@ public abstract class AbstractILPSolver implements BenchmarkableSolver {
     return lastSolving + lastSolutionCreation;
   }
 
-  @Override
-  public double getLastObjective() {
-    return lastObjective;
-  }
-
   @Override
   public boolean hadTimeout() {
     return this.timedOut;

jastadd-mquat-solver-ilp/src/main/java/de/tudresden/inf/st/mquat/solving/ilp/ILPDirectSolver.java

@@ -2,7 +2,6 @@ package de.tudresden.inf.st.mquat.solving.ilp;
 
 import de.tudresden.inf.st.mquat.jastadd.model.*;
 import de.tudresden.inf.st.mquat.solving.SolvingException;
-import de.tudresden.inf.st.mquat.utils.LoggingProxyForStdOut;
 import de.tudresden.inf.st.mquat.utils.StopWatch;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
@@ -23,7 +22,6 @@ public class ILPDirectSolver extends AbstractILPSolver {
   private boolean writeFiles;
   private Path lp, solutionReadable;
   private glp_prob prob;
-  private int timeoutInMillis;
 
   private static boolean listenerAddedToGlpk = false;
 
@@ -53,15 +51,6 @@ public class ILPDirectSolver extends AbstractILPSolver {
     return this;
   }
 
-  @Override
-  protected void recomputeTimeoutInSeconds() {
-    super.recomputeTimeoutInSeconds();
-    // store timeout in milliseconds, if small enough
-    long timeoutInMillis = this.timeoutInSeconds * 1000;
-    // if smaller than zero, an overflow has occurred
-    this.timeoutInMillis = timeoutInMillis > 0 && timeoutInMillis < Integer.MAX_VALUE ? (int) timeoutInMillis : 0;
-  }
-
   @Override
   protected void reset() {
     super.reset();
@@ -198,14 +187,16 @@ public class ILPDirectSolver extends AbstractILPSolver {
       logger.info("Writing ILP to {}", lp.toAbsolutePath());
       int returnCode = GLPK.glp_write_lp(prob, null, lp.toAbsolutePath().toString());
       if (returnCode != 0) {
-        cleanup(watch);
         throw new SolvingException("Could not write to lp file (error code: " + returnCode + ")");
       }
     }
 
-    // now the generation is really finish, note the time and add it to the other generation time
-    lastGeneration += watch.time(TimeUnit.MILLISECONDS);
-    watch.reset();
+    // now the generation is really finished, update the generation time
+    lastGeneration = watch.time(TimeUnit.MILLISECONDS);
+    long remainingTimeInMillis = this.timeoutUnit.toMillis(this.timeoutValue) - lastGeneration;
+    if (remainingTimeInMillis < 0) {
+      throw new SolvingException("No time left after GLPK initialization.");
+    }
 
     // Setup Parameters. See http://www.maximalsoftware.com/solvopt/optglpk.html
     glp_smcp simplexParam = new glp_smcp();
@@ -217,10 +208,9 @@ public class ILPDirectSolver extends AbstractILPSolver {
       logger.debug("Default simplex parameters: {}", printGetter(simplexParam));
       logger.debug("Default mip parameters: {}", printGetter(param));
     }
-    if(timeoutInMillis > 0) {
-      logger.debug("Set simplex timeout to {}ms.", timeoutInMillis);
-      simplexParam.setTm_lim(timeoutInMillis);
-    }
+
+    logger.debug("Set simplex timeout to {}ms.", remainingTimeInMillis);
+    simplexParam.setTm_lim((int)remainingTimeInMillis);
 
     // TODO maybe presolve is not needed in one of the solvers -- need to be checked
     simplexParam.setPresolve(GLPKConstants.GLP_ON);
@@ -252,24 +242,18 @@ public class ILPDirectSolver extends AbstractILPSolver {
     if (returnCode == GLPKConstants.GLP_ETMLIM) {
       logger.info("Simplex Solving was stopped after time limit was reached.");
     } else if (returnCode != 0) {
-      cleanup(watch);
-      // abuse objective to save return code
-      lastObjective = -1000 - returnCode;
       throw new SolvingException("Solving did not finish correctly, reason: " + translateSimplexReturnError(returnCode));
     }
 
-    if (timeoutInMillis > 0) {
-      // check how much time is left for MIP after simplex has finished
-      int remaining = timeoutInMillis;
-      remaining -= watch.time(TimeUnit.MILLISECONDS);
-      if (remaining < 0) {
-        cleanup(watch);
-        this.timedOut = true;
-        throw new SolvingException("No time left for MIP solver.");
-      }
-      logger.debug("Set MIP timeout to {}ms.", remaining);
-      param.setTm_lim(remaining);
+    // update the remaining time
+    remainingTimeInMillis = this.timeoutUnit.toMillis(this.timeoutValue) - watch.time(TimeUnit.MILLISECONDS);
+
+    if (remainingTimeInMillis < 0) {
+      this.timedOut = true;
+      throw new SolvingException("No time left for MIP solver.");
     }
+    logger.debug("Set MIP timeout to {}ms.", remainingTimeInMillis);
+    param.setTm_lim((int)remainingTimeInMillis);
 
 
     // Finally, solve the integer problem
@@ -280,9 +264,6 @@ public class ILPDirectSolver extends AbstractILPSolver {
       logger.info("MIP Solving was stopped after time limit was reached.");
       this.timedOut = true;
     } else if (returnCode != 0) {
-      cleanup(watch);
-      // abuse objective to save return code
-      lastObjective = -2000 - returnCode;
       throw new SolvingException("Solving did not finish correctly, reason: " + translateMIPReturnError(returnCode));
     }
 
@@ -414,8 +395,8 @@ public class ILPDirectSolver extends AbstractILPSolver {
   }
 
   @Override
-  protected void cleanup(StopWatch watch) {
-    super.cleanup(watch);
+  protected void cleanup() {
+    super.cleanup();
     GLPK.glp_delete_prob(prob);
     prob = null;
   }

jastadd-mquat-solver-ilp/src/main/java/de/tudresden/inf/st/mquat/solving/ilp/ILPExternalSolver.java

@@ -59,8 +59,7 @@ public class ILPExternalSolver extends AbstractILPSolver {
   }
 
   @Override
-  protected void cleanup(StopWatch watch) {
-    super.cleanup(watch);
+  protected void cleanup() {
     if (deleteFilesOnExit) {
       if (lp.toFile().exists() && !lp.toFile().delete()) {
         logger.warn("Could not delete ILP file {}", lp.toAbsolutePath());
@@ -72,8 +71,10 @@ public class ILPExternalSolver extends AbstractILPSolver {
   }
 
   protected double solve0(Root model, StopWatch watch, List<IlpVariable> variablesSetToOne) throws SolvingException {
+
+    long startOfWriteOutInMillis = watch.time(TimeUnit.MILLISECONDS);
+
     // Create temporary files
-    StopWatch writeOut = StopWatch.start();
     try {
       lp = Files.createTempFile("ilp", null);
 //      solution = Files.createTempFile("solution", null);
@@ -88,26 +89,32 @@ public class ILPExternalSolver extends AbstractILPSolver {
     try (BufferedWriter writer = Files.newBufferedWriter(
         lp, StandardOpenOption.CREATE, StandardOpenOption.TRUNCATE_EXISTING)) {
       writer.write(output.toString());
-    } catch (IOException e) { cleanup(watch); throw new SolvingException("Could not write to lp file", e); }
-    long secondsNeededToWriteOut = writeOut.time(TimeUnit.SECONDS);
+    } catch (IOException e) {
+      throw new SolvingException("Could not write to lp file", e);
+    }
+    this.lastGeneration = watch.time(TimeUnit.MILLISECONDS);
+    long millisecondsNeededToWriteOut = watch.time(TimeUnit.MILLISECONDS) - startOfWriteOutInMillis;
+    long remainingTimeInMillis = this.timeoutUnit.toMillis(this.timeoutValue) - lastGeneration;
+    long remainingTimeForSolvingInMillis = Math.max(0, remainingTimeInMillis - 2*millisecondsNeededToWriteOut);
     // take twice the time to have buffer to write out solution afterwards
-    long newTimeout = Math.min(1, timeoutInSeconds - 2 * secondsNeededToWriteOut);
+
 
     // start GLPK to solve the lp file just written, writing out the solution
     Process process;
     String command = "glpsol --lp " + lp.toAbsolutePath() +
 //        " -w " + solution.toAbsolutePath() +
-        " --tmlim " + newTimeout +
+        " --tmlim " + remainingTimeForSolvingInMillis/1000 +
         " -o " + solutionReadable.toAbsolutePath();
     logger.debug("Call: '{}'", command);
     try {
       process = Runtime.getRuntime().exec(command,null, new File("."));
-    } catch (IOException e) { cleanup(watch); throw new SolvingException("Problem calling glpsol. Is it installed?", e); }
+    } catch (IOException e) {
+      throw new SolvingException("Problem calling glpsol. Is it installed?", e);
+    }
     boolean finishedInTime;
     try {
-      finishedInTime = process.waitFor(newTimeout, TimeUnit.SECONDS);
+      finishedInTime = process.waitFor(remainingTimeForSolvingInMillis, TimeUnit.MILLISECONDS);
     } catch (InterruptedException e) {
-      cleanup(watch);
       throw new SolvingException("Interrupted while waiting for result", e);
     }
     StopWatch writerWatch = StopWatch.start();
@@ -116,13 +123,12 @@ public class ILPExternalSolver extends AbstractILPSolver {
       this.timedOut = true;
       try {
         logger.debug("Solver had a timeout, waiting ten seconds to let it write the result.");
-        process.waitFor(60, TimeUnit.SECONDS);
+        process.waitFor(10, TimeUnit.SECONDS);
       } catch (InterruptedException ignored) { }
-      logger.debug("Solver took {} seconds to write the result.", writerWatch.time(TimeUnit.SECONDS));
+      logger.debug("Solver took {}ms to write the result.", writerWatch.time(TimeUnit.MILLISECONDS));
       // then destroy the process
       process.destroyForcibly();
       if (!solutionReadable.toAbsolutePath().toFile().exists()) {
-        cleanup(watch);
         throw new SolvingException("Solving did not finish within " + timeoutValue + " " + timeoutUnit.toString()
             + ", file at " + solutionReadable.toAbsolutePath() + " was not written.");
       }
@@ -130,7 +136,6 @@ public class ILPExternalSolver extends AbstractILPSolver {
     }
     printFromProcess(process);
     if (!solutionReadable.toFile().exists()) {
-      cleanup(watch);
       throw new SolvingException("No solution file was created.");
     }
     logger.debug("Solution at {}", solutionReadable);

jastadd-mquat-solver-random/src/main/java/de/tudresden/inf/st/mquat/solving/random/RandomSolver.java

@@ -105,16 +105,6 @@ public class RandomSolver implements BenchmarkableSolver {
     return lastSolvingTime;
   }
 
-  @Override
-  public double getLastObjective() {
-    if (lastSolution != null) {
-      return lastSolution.computeObjective();
-    } else {
-      // TODO throw exception or do something reasonable
-      return 0d;
-    }
-  }
-
   @Override
   public Solver setTimeout(long timeoutValue, TimeUnit timeoutUnit) {
     this.maxSolvingTime = timeoutUnit.toMillis(timeoutValue);

jastadd-mquat-solver-simple/src/main/java/de/tudresden/inf/st/mquat/solving/simple/SimpleSolver.java

@@ -169,16 +169,6 @@ public class SimpleSolver implements BenchmarkableSolver {
     return lastSolvingTime;
   }
 
-  @Override
-  public double getLastObjective() {
-    if (lastSolution != null) {
-      return lastSolution.computeObjective();
-    } else {
-      // TODO throw exception or do something reasonable
-      return 0d;
-    }
-  }
-
   @Override
   public Solver setTimeout(long timeoutValue, TimeUnit timeoutUnit) {
     this.maxSolvingTime = timeoutUnit.toMillis(timeoutValue);

jastadd-mquat-solver/src/main/java/de/tudresden/inf/st/mquat/solving/BenchmarkableSolver.java

@@ -32,11 +32,6 @@ public interface BenchmarkableSolver extends Solver {
    */
   long getLastSolvingTime();
 
-  /**
-   * @return objective value for the last finished call of {@link #solve(Root)}.
-   */
-  double getLastObjective();
-
   /**
    * @return whether this solver reached the timeout for the last finished call of {@link #solve(Root)}.
    */