More prints for scheduling

constraints/src/main/java/gov/nasa/jpl/aerie/constraints/time/Windows.java

@@ -674,4 +674,15 @@ public boolean equals(final Object other) {
   public String toString() {
     return segments.toString();
   }
+
+  /**
+   * toString only for the true segments
+   */
+  public String trueSegmentsToString(){
+    final var sb = new StringBuilder();
+    sb.append("[");
+    this.iterateEqualTo(true).forEach(w -> sb.append(w.toString()));
+    sb.append("]");
+    return sb.toString();
+  }
 }

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/conflicts/MissingActivityInstanceConflict.java

@@ -39,7 +39,7 @@ public MissingActivityInstanceConflict(
   @Override
   public String toString() {
     if (this.instance != null) {
-      return "Conflict : missing activity instance " + this.instance;
+      return "Conflict : missing activity instance " + this.instance + ". Produced by goal " + getGoal().getName();
     }
     return "Empty conflict";
   }

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/conflicts/MissingActivityTemplateConflict.java

@@ -100,4 +100,17 @@ public ActivityTemplateGoal getGoal() {
   public ActivityCreationTemplate getActTemplate() {
     return template;
   }
+
+  @Override
+  public String toString(){
+    return "Conflict: missing activity template [cardinality:"
+           + this.getCardinality()
+           + ", occurrences: "
+           + (this.getTotalDuration().isPresent() ? this.getTotalDuration() : "N/A")
+           +"] of type: "
+           + getActTemplate().getType().getName()
+           + " in temporal context "
+           + getTemporalContext().trueSegmentsToString()
+           + ". Produced by goal " + getGoal().getName();
+  }
 }

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/conflicts/MissingAssociationConflict.java

@@ -29,4 +29,10 @@ public Collection<SchedulingActivityDirective> getActivityInstancesToChooseFrom(
   public Windows getTemporalContext() {
     return null;
   }
+
+  @Override
+  public String toString(){
+    return "Conflict: missing association between goal and 1 activity of following set: "
+           + this.getActivityInstancesToChooseFrom() + ". Produced by goal " + getGoal().getName();
+  }
 }

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/constraints/activities/ActivityCreationTemplate.java

@@ -206,6 +206,13 @@ public Optional<EventWithActivity> getLastEvent(){
       if(!events.isEmpty()) return Optional.of(events.get(events.size()-1));
       return Optional.empty();
     }
+
+    public void logHistory(){
+      logger.info("Rootfinding history");
+      for(final var event: events){
+        logger.info("Start:" + event.start + " end:" + (event.end==null ? "error" : event.end));
+      }
+    }
   }
   /**
    * create activity if possible
@@ -217,7 +224,9 @@ public Optional<EventWithActivity> getLastEvent(){
   public @NotNull
   Optional<SchedulingActivityDirective> createActivity(String name, Windows windows, SimulationFacade facade, Plan plan, PlanningHorizon planningHorizon, EvaluationEnvironment evaluationEnvironment) {
     //REVIEW: how to properly export any flexibility to instance?
+    logger.info("Trying to create one activity, will loop through possible windows");
     for (var window : windows.iterateEqualTo(true)) {
+      logger.info("Trying in window " + window);
       var act = createInstanceForReal(name, window, facade, plan, planningHorizon, evaluationEnvironment);
       if (act.isPresent()) {
         return act;
@@ -239,6 +248,7 @@ private Optional<SchedulingActivityDirective> createInstanceForReal(final String
     if (this.endRange != null) {
       tnw.addEndInterval(name, this.endRange.start, this.endRange.end);
     }
+    Duration storedDur = null;
     if (this.duration != null) {
       final Optional<Duration> duration;
       try {
@@ -250,10 +260,15 @@ private Optional<SchedulingActivityDirective> createInstanceForReal(final String
         throw new UnsupportedOperationException("Activity creation duration arguments cannot depend on simulation results.", e);
       }
       duration.ifPresent(d -> tnw.addDurationInterval(name, d, d));
+      storedDur = duration.get();
     }
     final var success = tnw.solveConstraints();
     if (!success) {
-      logger.warn("Inconsistent temporal constraints, will try next opportunity for activity placement if it exists");
+      logger.warn("Inconsistent static temporal constraints, will try next opportunity for activity placement if it exists");
+      logger.info("Start range " + this.startRange);
+      logger.info("Start range " + this.endRange);
+      if(storedDur!=null) logger.info("dur range " + storedDur);
+      logger.info("interval range " + interval);
       return Optional.empty();
     }
     final var solved = tnw.getAllData(name);
@@ -440,12 +455,13 @@ private  Optional<SchedulingActivityDirective> rootFindingHelper(
       final TaskNetworkAdapter.TNActData solved,
       final SimulationFacade simulationFacade
   ) {
+    logger.info("Starting rootfinding trying to place activity "+ this.type.getName());
+    final var maxIterations = 20;
     try {
       var endInterval = solved.end();
       var startInterval = solved.start();
 
       final var durationHalfEndInterval = endInterval.duration().dividedBy(2);
-
       final var result = new EquationSolvingAlgorithms
           .SecantDurationAlgorithm<HistoryWithActivity>()
           .findRoot(
@@ -458,21 +474,23 @@ private  Optional<SchedulingActivityDirective> rootFindingHelper(
               durationHalfEndInterval,
               startInterval.start,
               startInterval.end,
-              20);
+              maxIterations);
 
       // TODO: When scheduling is allowed to create activities with anchors, this constructor should pull from an expanded creation template
       final var lastActivityTested = result.history().getLastEvent();
+      logger.info("Finished rootfinding: SUCCESS");
+      history.logHistory();
       return Optional.of(lastActivityTested.get().activity);
     } catch (EquationSolvingAlgorithms.ZeroDerivativeException zeroOrInfiniteDerivativeException) {
-      logger.debug("Rootfinding encountered a zero-derivative");
+      logger.info("Rootfinding encountered a zero-derivative");
     } catch (EquationSolvingAlgorithms.InfiniteDerivativeException infiniteDerivativeException) {
-      logger.debug("Rootfinding encountered an infinite-derivative");
+      logger.info("Rootfinding encountered an infinite-derivative");
     } catch (EquationSolvingAlgorithms.DivergenceException e) {
-      logger.debug("Rootfinding diverged");
+      logger.info("Rootfinding diverged");
     } catch (EquationSolvingAlgorithms.ExceededMaxIterationException e) {
-      logger.debug("Too many iterations");
+      logger.info("Rootfinding exited because too many iterations ("+maxIterations+")");
     } catch (EquationSolvingAlgorithms.NoSolutionException e) {
-      logger.debug("No solution");
+      logger.info("Rootfinding: no solution");
     }
     if(!history.events.isEmpty()) {
       try {
@@ -481,6 +499,8 @@ private  Optional<SchedulingActivityDirective> rootFindingHelper(
         throw new RuntimeException("Exception while simulating original plan after activity insertion failure" ,e);
       }
     }
+    logger.info("Finished rootfinding: FAILURE");
+    history.logHistory();
     return Optional.empty();
   }
 

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/goals/CardinalityGoal.java

@@ -108,6 +108,9 @@ protected CardinalityGoal fill(CardinalityGoal goal) {
       if (occurrenceRange != null) {
         goal.occurrenceRange = occurrenceRange;
       }
+      if(name==null){
+        goal.name = "CardinalityGoal_"+"thereExists_"+this.thereExists.getType().getName()+"_(duration:"+((this.durationRange != null) ? this.durationRange: "N/A") +", occurrences:" + ((this.occurrenceRange != null) ? this.occurrenceRange: "N/A") +")";
+      }
       return goal;
     }
   }//Builder

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/goals/CoexistenceGoal.java

@@ -159,6 +159,10 @@ protected CoexistenceGoal fill(CoexistenceGoal goal) {
 
       goal.alias = alias;
 
+      if(name==null){
+        goal.name = "CoexistenceGoal_forEach_"+forEach.prettyPrint()+"_thereExists_"+this.thereExists.getType().getName();
+      }
+
       return goal;
     }
 

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/goals/RecurrenceGoal.java

@@ -91,6 +91,10 @@ else if (every.max.isNegative()) {
       }
       goal.recurrenceInterval = every;
 
+      if(name==null){
+        goal.name = "RecurrenceGoal_one_"+this.thereExists.getType().getName()+"_every_["+goal.recurrenceInterval.min+","+goal.recurrenceInterval.max+"]";
+      }
+
       return goal;
     }
 

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/simulation/ResumableSimulationDriver.java

@@ -30,6 +30,9 @@
 import java.util.Optional;
 
 public class ResumableSimulationDriver<Model> implements AutoCloseable {
+
+  public long durationSinceRestart = 0;
+
   private static final Logger logger = LoggerFactory.getLogger(ResumableSimulationDriver.class);
   /* The current real time. All the tasks before and at this time have been performed.
  Simulation has not started so it is set to MIN_VALUE. */
@@ -66,14 +69,26 @@ public ResumableSimulationDriver(MissionModel<Model> missionModel, Duration plan
     initSimulation();
   }
 
+
+  private void printTimeSpent(){
+    final var dur = durationSinceRestart/1_000_000_000.;
+    final var average = curTime.isEqualTo(Duration.ZERO) ? 0 : dur/curTime.in(Duration.SECONDS);
+    if(dur != 0) {
+      logger.warn("Time spent in the last sim " + dur + "s, average per simulation second " + average + "s. Simulated until " + curTime);
+    }
+  }
+
   // This method is currently only used in one test.
   /*package-private*/ void clearActivitiesInserted() {activitiesInserted.clear();}
 
   /*package-private*/ void initSimulation(){
     logger.warn("Reinitialization of the scheduling simulation");
+    printTimeSpent();
+    durationSinceRestart = 0;
     plannedDirectiveToTask.clear();
     lastSimResults = null;
     lastSimResultsEnd = Duration.ZERO;
+    long before = System.nanoTime();
     if (this.engine != null) this.engine.close();
     this.engine = new SimulationEngine();
     batch = null;
@@ -96,6 +111,7 @@ public ResumableSimulationDriver(MissionModel<Model> missionModel, Duration plan
         batch = engine.extractNextJobs(Duration.MAX_VALUE);
       }
     }
+    this.durationSinceRestart += System.nanoTime() - before;
     countSimulationRestarts++;
   }
 
@@ -109,10 +125,14 @@ public int getCountSimulationRestarts(){
 
   @Override
   public void close() {
+    logger.warn("Closing sim");
+    printTimeSpent();
     this.engine.close();
   }
 
   private void simulateUntil(Duration endTime){
+    long before = System.nanoTime();
+    logger.info("Simulating until "+endTime);
     assert(endTime.noShorterThan(curTime));
       if(batch == null){
         batch = engine.extractNextJobs(Duration.MAX_VALUE);
@@ -129,7 +149,8 @@ private void simulateUntil(Duration endTime){
 
         batch = engine.extractNextJobs(Duration.MAX_VALUE);
       }
-    lastSimResults = null;
+      lastSimResults = null;
+      this.durationSinceRestart += (System.nanoTime() - before);
   }
 
 
@@ -165,6 +186,7 @@ public void simulateActivities(@NotNull Map<ActivityDirectiveId, ActivityDirecti
     final var earliestStartOffset = resolved.get(null).get(0);
 
     if(earliestStartOffset.getRight().noLongerThan(curTime)){
+      logger.info("Restarting simulation because earliest start of activity to simulate " + earliestStartOffset.getRight() + " is before current sim time " + curTime);
       initSimulation();
       simulateSchedule(activitiesInserted);
     } else {
@@ -196,9 +218,12 @@ public Duration getCurrentSimulationEndTime(){
   public SimulationResults getSimulationResultsUpTo(Instant startTimestamp, Duration endTime){
     //if previous results cover a bigger period, we return do not regenerate
     if(endTime.longerThan(curTime)){
+      logger.info("Has to simulate from " + curTime + " to " + endTime + " to get simulation results");
       simulateUntil(endTime);
+    } else{
+      logger.info("Not simulating because asked endTime "+endTime+" is before current sim time " + curTime);
     }
-
+    final var before = System.nanoTime();
     if(lastSimResults == null || endTime.longerThan(lastSimResultsEnd) || startTimestamp.compareTo(lastSimResults.startTime) != 0) {
       lastSimResults = SimulationEngine.computeResults(
           engine,
@@ -210,11 +235,14 @@ public SimulationResults getSimulationResultsUpTo(Instant startTimestamp, Durati
       lastSimResultsEnd = endTime;
       //while sim results may not be up to date with curTime, a regeneration has taken place after the last insertion
     }
+    this.durationSinceRestart += System.nanoTime() - before;
+
     return lastSimResults;
   }
 
   private void simulateSchedule(final Map<ActivityDirectiveId, ActivityDirective> schedule)
   {
+    final var before = System.nanoTime();
     if (schedule.isEmpty()) {
       throw new IllegalArgumentException("simulateSchedule() called with empty schedule, use simulateUntil() instead");
     }
@@ -271,6 +299,7 @@ private void simulateSchedule(final Map<ActivityDirectiveId, ActivityDirective>
       }
     }
     lastSimResults = null;
+    this.durationSinceRestart+= System.nanoTime() - before;
   }
 
   /**

scheduler-driver/src/main/java/gov/nasa/jpl/aerie/scheduler/simulation/SimulationFacade.java

@@ -157,6 +157,7 @@ private ActivityDirectiveId getIdOfRootParent(SimulationResults results, Simulat
   public Map<SchedulingActivityDirective, SchedulingActivityDirectiveId> getAllChildActivities(final Duration endTime)
   throws SimulationException
   {
+    logger.info("Need to compute simulation results until "+ endTime + " for getting child activities");
     if(insertedActivities.size() == 0) return Map.of();
     computeSimulationResultsUntil(endTime);
     final Map<SchedulingActivityDirective, SchedulingActivityDirectiveId> childActivities = new HashMap<>();
@@ -183,6 +184,9 @@ public void removeAndInsertActivitiesFromSimulation(
       final Collection<SchedulingActivityDirective> activitiesToRemove,
       final Collection<SchedulingActivityDirective> activitiesToAdd) throws SimulationException
   {
+    logger.info("Removing("+activitiesToRemove.size()+")/Adding("+activitiesToAdd.size()+") activities from simulation");
+    activitiesToRemove.stream().forEach(remove -> logger.info("Removing act starting at " + remove.startOffset()));
+    activitiesToAdd.stream().forEach(adding -> logger.info("Adding act starting at " + adding.startOffset()));
     var atLeastOneActualRemoval = false;
     for(final var act: activitiesToRemove){
       if(insertedActivities.containsKey(act)){
@@ -204,10 +208,12 @@ public void removeAndInsertActivitiesFromSimulation(
       allActivitiesToSimulate.addAll(insertedActivities.keySet());
       insertedActivities.clear();
       planActDirectiveIdToSimulationActivityDirectiveId.clear();
+      logger.info("(Re)creating simulation driver because at least one removal("+atLeastOneActualRemoval+") or insertion in the past ("+earliestActStartTime+")");
       if (driver != null) {
         this.pastSimulationRestarts += driver.getCountSimulationRestarts();
         driver.close();
       }
+      logger.info("Number of simulation restarts so far: " + this.pastSimulationRestarts);
       driver = new ResumableSimulationDriver<>(missionModel, planningHorizon.getAerieHorizonDuration());
     }
     simulateActivities(allActivitiesToSimulate);