fix: prevent excessive logging of constraint weights

triceo · triceo · commit f09a244122b8 · 2024-09-16T14:17:58.000+02:00
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/AbstractScoreDirector.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/AbstractScoreDirector.java
@@ -247,17 +247,12 @@ protected void setWorkingEntityListDirty() {
         workingEntityListRevision++;
     }
 
-    @Override
-    public Solution_ cloneWorkingSolution() {
-        return cloneSolution(workingSolution);
-    }
-
     @Override
     public Solution_ cloneSolution(Solution_ originalSolution) {
         SolutionDescriptor<Solution_> solutionDescriptor = getSolutionDescriptor();
-        Score_ originalScore = (Score_) solutionDescriptor.getScore(originalSolution);
+        Score_ originalScore = solutionDescriptor.getScore(originalSolution);
         Solution_ cloneSolution = solutionDescriptor.getSolutionCloner().cloneSolution(originalSolution);
-        Score_ cloneScore = (Score_) solutionDescriptor.getScore(cloneSolution);
+        Score_ cloneScore = solutionDescriptor.getScore(cloneSolution);
         if (scoreDirectorFactory.isAssertClonedSolution()) {
             if (!Objects.equals(originalScore, cloneScore)) {
                 throw new IllegalStateException("Cloning corruption: "
@@ -297,33 +292,29 @@ protected void setCalculatedScore(Score_ score) {
         calculationCount++;
     }
 
+    /**
+     * @deprecated Unused, but kept for backward compatibility.
+     */
+    @Deprecated(forRemoval = true, since = "1.14.0")
     @Override
     public AbstractScoreDirector<Solution_, Score_, Factory_> clone() {
-        // Breaks incremental score calculation.
-        // Subclasses should overwrite this method to avoid breaking it if possible.
-        AbstractScoreDirector<Solution_, Score_, Factory_> clone =
-                (AbstractScoreDirector<Solution_, Score_, Factory_>) scoreDirectorFactory
-                        .buildScoreDirector(lookUpEnabled, constraintMatchEnabledPreference);
-        clone.setWorkingSolution(cloneWorkingSolution());
-        return clone;
+        throw new UnsupportedOperationException("Cloning score directors is not supported.");
     }
 
     @Override
     public InnerScoreDirector<Solution_, Score_> createChildThreadScoreDirector(ChildThreadType childThreadType) {
         if (childThreadType == ChildThreadType.PART_THREAD) {
-            AbstractScoreDirector<Solution_, Score_, Factory_> childThreadScoreDirector =
-                    (AbstractScoreDirector<Solution_, Score_, Factory_>) scoreDirectorFactory
-                            .buildScoreDirector(lookUpEnabled, constraintMatchEnabledPreference);
+            var childThreadScoreDirector = (AbstractScoreDirector<Solution_, Score_, Factory_>) scoreDirectorFactory
+                    .buildDerivedScoreDirector(lookUpEnabled, constraintMatchEnabledPreference);
             // ScoreCalculationCountTermination takes into account previous phases
             // but the calculationCount of partitions is maxed, not summed.
             childThreadScoreDirector.calculationCount = calculationCount;
             return childThreadScoreDirector;
         } else if (childThreadType == ChildThreadType.MOVE_THREAD) {
             // TODO The move thread must use constraintMatchEnabledPreference in FULL_ASSERT,
             // but it doesn't have to for Indictment Local Search, in which case it is a performance loss
-            AbstractScoreDirector<Solution_, Score_, Factory_> childThreadScoreDirector =
-                    (AbstractScoreDirector<Solution_, Score_, Factory_>) scoreDirectorFactory
-                            .buildScoreDirector(true, constraintMatchEnabledPreference);
+            var childThreadScoreDirector = (AbstractScoreDirector<Solution_, Score_, Factory_>) scoreDirectorFactory
+                    .buildDerivedScoreDirector(true, constraintMatchEnabledPreference);
             childThreadScoreDirector.setWorkingSolution(cloneWorkingSolution());
             return childThreadScoreDirector;
         } else {
@@ -593,7 +584,7 @@ private void assertScoreFromScratch(Score_ score, Object completedAction, boolea
         if (assertionScoreDirectorFactory == null) {
             assertionScoreDirectorFactory = scoreDirectorFactory;
         }
-        try (var uncorruptedScoreDirector = assertionScoreDirectorFactory.buildScoreDirector(false, true)) {
+        try (var uncorruptedScoreDirector = assertionScoreDirectorFactory.buildDerivedScoreDirector(false, true)) {
             uncorruptedScoreDirector.setWorkingSolution(workingSolution);
             Score_ uncorruptedScore = uncorruptedScoreDirector.calculateScore();
             if (!score.equals(uncorruptedScore)) {
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/AbstractScoreDirectorFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/AbstractScoreDirectorFactory.java
@@ -100,8 +100,8 @@ public InnerScoreDirector<Solution_, Score_> buildScoreDirector() {
     @Override
     public void assertScoreFromScratch(Solution_ solution) {
         // Get the score before uncorruptedScoreDirector.calculateScore() modifies it
-        Score_ score = (Score_) getSolutionDescriptor().getScore(solution);
-        try (InnerScoreDirector<Solution_, Score_> uncorruptedScoreDirector = buildScoreDirector(false, true)) {
+        Score_ score = getSolutionDescriptor().getScore(solution);
+        try (var uncorruptedScoreDirector = buildDerivedScoreDirector(false, true)) {
             uncorruptedScoreDirector.setWorkingSolution(solution);
             Score_ uncorruptedScore = uncorruptedScoreDirector.calculateScore();
             if (!score.equals(uncorruptedScore)) {
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/InnerScoreDirector.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/InnerScoreDirector.java
@@ -203,7 +203,9 @@ default Score_ doAndProcessMove(Move<Solution_> move, boolean assertMoveScoreFro
      *
      * @return never null, planning clone
      */
-    Solution_ cloneWorkingSolution();
+    default Solution_ cloneWorkingSolution() {
+        return cloneSolution(getWorkingSolution());
+    }
 
     /**
      * Returns a planning clone of the solution,
@@ -228,17 +230,6 @@ default Score_ doAndProcessMove(Move<Solution_> move, boolean assertMoveScoreFro
      */
     SupplyManager getSupplyManager();
 
-    /**
-     * Clones this {@link ScoreDirector} and its {@link PlanningSolution working solution}.
-     * Use {@link #getWorkingSolution()} to retrieve the {@link PlanningSolution working solution} of that clone.
-     * <p>
-     * This is heavy method, because it usually breaks incremental score calculation. Use it sparingly.
-     * Therefore it's best to clone lazily by delaying the clone call as long as possible.
-     *
-     * @return never null
-     */
-    InnerScoreDirector<Solution_, Score_> clone();
-
     InnerScoreDirector<Solution_, Score_> createChildThreadScoreDirector(ChildThreadType childThreadType);
 
     /**
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/InnerScoreDirectorFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/InnerScoreDirectorFactory.java
@@ -62,6 +62,25 @@ default InnerScoreDirector<Solution_, Score_> buildScoreDirector(boolean lookUpE
     InnerScoreDirector<Solution_, Score_> buildScoreDirector(boolean lookUpEnabled, boolean constraintMatchEnabledPreference,
             boolean expectShadowVariablesInCorrectState);
 
+    /**
+     * Like {@link #buildScoreDirector(boolean, boolean)}, but makes the score director a derived one.
+     * Derived score directors may make choices which the main score director can not make, such as reducing logging.
+     * Derived score directors are typically used for multithreaded solving, testing and assert modes.
+     *
+     * @param lookUpEnabled true if a {@link ScoreDirector} implementation should track all working objects
+     *        for {@link ScoreDirector#lookUpWorkingObject(Object)}
+     * @param constraintMatchEnabledPreference false if a {@link ScoreDirector} implementation
+     *        should not do {@link ConstraintMatch} tracking even if it supports it.
+     * @return never null
+     * @see InnerScoreDirector#isConstraintMatchEnabled()
+     * @see InnerScoreDirector#getConstraintMatchTotalMap()
+     */
+    default InnerScoreDirector<Solution_, Score_> buildDerivedScoreDirector(boolean lookUpEnabled,
+            boolean constraintMatchEnabledPreference) {
+        // Most score directors don't need derived status; CS will override this.
+        return buildScoreDirector(lookUpEnabled, constraintMatchEnabledPreference, true);
+    }
+
     /**
      * @return never null
      */
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/stream/BavetConstraintStreamScoreDirector.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/stream/BavetConstraintStreamScoreDirector.java
@@ -25,11 +25,19 @@
 public final class BavetConstraintStreamScoreDirector<Solution_, Score_ extends Score<Score_>>
         extends AbstractScoreDirector<Solution_, Score_, BavetConstraintStreamScoreDirectorFactory<Solution_, Score_>> {
 
+    private final boolean derived;
     private BavetConstraintSession<Score_> session;
 
     public BavetConstraintStreamScoreDirector(BavetConstraintStreamScoreDirectorFactory<Solution_, Score_> scoreDirectorFactory,
             boolean lookUpEnabled, boolean constraintMatchEnabledPreference, boolean expectShadowVariablesInCorrectState) {
+        this(scoreDirectorFactory, lookUpEnabled, constraintMatchEnabledPreference, expectShadowVariablesInCorrectState, false);
+    }
+
+    public BavetConstraintStreamScoreDirector(BavetConstraintStreamScoreDirectorFactory<Solution_, Score_> scoreDirectorFactory,
+            boolean lookUpEnabled, boolean constraintMatchEnabledPreference, boolean expectShadowVariablesInCorrectState,
+            boolean derived) {
         super(scoreDirectorFactory, lookUpEnabled, constraintMatchEnabledPreference, expectShadowVariablesInCorrectState);
+        this.derived = derived;
     }
 
     // ************************************************************************
@@ -38,7 +46,7 @@ public BavetConstraintStreamScoreDirector(BavetConstraintStreamScoreDirectorFact
 
     @Override
     public void setWorkingSolution(Solution_ workingSolution) {
-        session = scoreDirectorFactory.newSession(workingSolution, constraintMatchEnabledPreference);
+        session = scoreDirectorFactory.newSession(workingSolution, constraintMatchEnabledPreference, derived);
         getSolutionDescriptor().visitAll(workingSolution, session::insert);
         super.setWorkingSolution(workingSolution);
     }
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/director/stream/BavetConstraintStreamScoreDirectorFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/director/stream/BavetConstraintStreamScoreDirectorFactory.java
@@ -13,6 +13,7 @@
 import ai.timefold.solver.core.config.util.ConfigUtils;
 import ai.timefold.solver.core.enterprise.TimefoldSolverEnterpriseService;
 import ai.timefold.solver.core.impl.domain.solution.descriptor.SolutionDescriptor;
+import ai.timefold.solver.core.impl.score.director.InnerScoreDirector;
 import ai.timefold.solver.core.impl.score.stream.bavet.BavetConstraintFactory;
 import ai.timefold.solver.core.impl.score.stream.bavet.BavetConstraintSession;
 import ai.timefold.solver.core.impl.score.stream.bavet.BavetConstraintSessionFactory;
@@ -72,13 +73,21 @@ public BavetConstraintStreamScoreDirector<Solution_, Score_> buildScoreDirector(
                 expectShadowVariablesInCorrectState);
     }
 
-    public BavetConstraintSession<Score_> newSession(Solution_ workingSolution, boolean constraintMatchEnabled) {
-        return constraintSessionFactory.buildSession(workingSolution, constraintMatchEnabled);
+    @Override
+    public InnerScoreDirector<Solution_, Score_> buildDerivedScoreDirector(boolean lookUpEnabled,
+            boolean constraintMatchEnabledPreference) {
+        return new BavetConstraintStreamScoreDirector<>(this, lookUpEnabled, constraintMatchEnabledPreference,
+                true, true);
+    }
+
+    public BavetConstraintSession<Score_> newSession(Solution_ workingSolution, boolean constraintMatchEnabled,
+            boolean scoreDirectorDerived) {
+        return constraintSessionFactory.buildSession(workingSolution, constraintMatchEnabled, scoreDirectorDerived);
     }
 
     @Override
     public AbstractScoreInliner<Score_> fireAndForget(Object... facts) {
-        var session = newSession(null, true);
+        var session = newSession(null, true, true);
         Arrays.stream(facts).forEach(session::insert);
         session.calculateScore(0);
         return session.getScoreInliner();
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintFactory.java
@@ -65,11 +65,10 @@ public <Stream_ extends BavetAbstractConstraintStream<Solution_>> Stream_ share(
 
     /**
      * Enables node sharing.
-     * If a constraint already exists in this factory, it replaces it by the old copy.
+     * If a constraint already exists in this factory, it replaces it with the old copy.
      * {@link BavetAbstractConstraintStream} implement equals/hashcode ignoring child streams.
      * <p>
-     * {@link BavetConstraintSessionFactory#buildSession(Object, boolean)} relies on this
-     * occurring for all streams.
+     * {@link BavetConstraintSessionFactory#buildSession(Object, boolean, boolean)} needs this to happen for all streams.
      * <p>
      * This must be called before the stream receives child streams.
      *
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintSession.java b/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintSession.java
@@ -16,7 +16,7 @@
 
 /**
  * The type is public to make it easier for Bavet-specific minimal bug reproducers to be created.
- * Instances should be created through {@link BavetConstraintStreamScoreDirectorFactory#newSession(Object, boolean)}.
+ * Instances should be created through {@link BavetConstraintStreamScoreDirectorFactory#newSession(Object, boolean, boolean)}.
  *
  * @see PropagationQueue Description of the tuple propagation mechanism.
  * @param <Score_>
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintSessionFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/stream/bavet/BavetConstraintSessionFactory.java
@@ -31,10 +31,13 @@
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.event.Level;
 
 public final class BavetConstraintSessionFactory<Solution_, Score_ extends Score<Score_>> {
 
     private static final Logger LOGGER = LoggerFactory.getLogger(BavetConstraintSessionFactory.class);
+    private static final Level CONSTRAINT_WEIGHT_LOGGING_LEVEL = Level.DEBUG;
+
     private final SolutionDescriptor<Solution_> solutionDescriptor;
     private final ConstraintLibrary<Score_> constraintLibrary;
 
@@ -50,7 +53,8 @@ public BavetConstraintSessionFactory(SolutionDescriptor<Solution_> solutionDescr
     // ************************************************************************
 
     @SuppressWarnings("unchecked")
-    public BavetConstraintSession<Score_> buildSession(Solution_ workingSolution, boolean constraintMatchEnabled) {
+    public BavetConstraintSession<Score_> buildSession(Solution_ workingSolution, boolean constraintMatchEnabled,
+            boolean scoreDirectorDerived) {
         var constraintWeightSupplier = solutionDescriptor.getConstraintWeightSupplier();
         if (constraintWeightSupplier != null) { // Fail fast on unknown constraints.
             var knownConstraints = constraintLibrary.getConstraints()
@@ -63,16 +67,28 @@ public BavetConstraintSession<Score_> buildSession(Solution_ workingSolution, bo
         var zeroScore = scoreDefinition.getZeroScore();
         var constraintStreamSet = new LinkedHashSet<BavetAbstractConstraintStream<Solution_>>();
         var constraintWeightMap = new HashMap<Constraint, Score_>(constraintLibrary.getConstraints().size());
-        LOGGER.debug("Constraint weights for solution ({}):", workingSolution);
+
+        // Only log constraint weights if logging is enabled; otherwise we don't need to build the string.
+        var constraintWeightLoggingEnabled = !scoreDirectorDerived && LOGGER.isEnabledForLevel(CONSTRAINT_WEIGHT_LOGGING_LEVEL);
+        var constraintWeightString = constraintWeightLoggingEnabled
+                ? new StringBuilder("Constraint weights for solution (%s):%n"
+                        .formatted(workingSolution))
+                : null;
+
         for (var constraint : constraintLibrary.getConstraints()) {
             var constraintRef = constraint.getConstraintRef();
             var castConstraint = (BavetConstraint<Solution_>) constraint;
             var defaultConstraintWeight = castConstraint.getDefaultConstraintWeight();
             var constraintWeight = (Score_) castConstraint.extractConstraintWeight(workingSolution);
             if (!constraintWeight.equals(zeroScore)) {
-                if (defaultConstraintWeight != null && !defaultConstraintWeight.equals(constraintWeight)) {
-                    LOGGER.debug("  Constraint ({}) weight overridden to ({}) from ({}).", constraintRef, constraintWeight,
-                            defaultConstraintWeight);
+                if (constraintWeightLoggingEnabled) {
+                    if (defaultConstraintWeight != null && !defaultConstraintWeight.equals(constraintWeight)) {
+                        constraintWeightString.append("  Constraint (%s) weight overridden to (%s) from (%s).%n"
+                                .formatted(constraintRef, constraintWeight, defaultConstraintWeight));
+                    } else {
+                        constraintWeightString.append("  Constraint (%s) weight set to (%s).%n"
+                                .formatted(constraintRef, constraintWeight));
+                    }
                 }
                 /*
                  * Relies on BavetConstraintFactory#share(Stream_) occurring for all constraint stream instances
@@ -81,18 +97,27 @@ public BavetConstraintSession<Score_> buildSession(Solution_ workingSolution, bo
                 castConstraint.collectActiveConstraintStreams(constraintStreamSet);
                 constraintWeightMap.put(constraint, constraintWeight);
             } else {
-                /*
-                 * Filter out nodes that only lead to constraints with zero weight.
-                 * Note: Node sharing happens earlier, in BavetConstraintFactory#share(Stream_).
-                 */
-                LOGGER.debug("  Constraint ({}) disabled.", constraintRef);
+                if (constraintWeightLoggingEnabled) {
+                    /*
+                     * Filter out nodes that only lead to constraints with zero weight.
+                     * Note: Node sharing happens earlier, in BavetConstraintFactory#share(Stream_).
+                     */
+                    constraintWeightString.append("  Constraint (%s) disabled.%n"
+                            .formatted(constraintRef));
+                }
             }
         }
 
         var scoreInliner = AbstractScoreInliner.buildScoreInliner(scoreDefinition, constraintWeightMap, constraintMatchEnabled);
-        if (constraintStreamSet.isEmpty()) { // All constraints were disabled.
+        if (constraintStreamSet.isEmpty()) {
+            LOGGER.warn("No constraints enabled for solution ({}).", workingSolution);
             return new BavetConstraintSession<>(scoreInliner);
         }
+
+        if (constraintWeightLoggingEnabled) {
+            LOGGER.atLevel(CONSTRAINT_WEIGHT_LOGGING_LEVEL)
+                    .log(constraintWeightString.toString().trim());
+        }
         /*
          * Build constraintStreamSet in reverse order to create downstream nodes first
          * so every node only has final variables (some of which have downstream node method references).
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/score/stream/common/AbstractConstraintStreamScoreDirectorFactory.java b/core/src/main/java/ai/timefold/solver/core/impl/score/stream/common/AbstractConstraintStreamScoreDirectorFactory.java
@@ -4,6 +4,7 @@
 import ai.timefold.solver.core.api.score.Score;
 import ai.timefold.solver.core.impl.domain.solution.descriptor.SolutionDescriptor;
 import ai.timefold.solver.core.impl.score.director.AbstractScoreDirectorFactory;
+import ai.timefold.solver.core.impl.score.director.InnerScoreDirector;
 import ai.timefold.solver.core.impl.score.director.ScoreDirectorFactory;
 import ai.timefold.solver.core.impl.score.stream.common.inliner.AbstractScoreInliner;
 
@@ -35,4 +36,9 @@ protected AbstractConstraintStreamScoreDirectorFactory(SolutionDescriptor<Soluti
     public boolean supportsConstraintMatching() {
         return true;
     }
+
+    @Override
+    public abstract InnerScoreDirector<Solution_, Score_> buildDerivedScoreDirector(boolean lookUpEnabled,
+            boolean constraintMatchEnabledPreference);
+
 }
diff --git a/core/src/main/java/ai/timefold/solver/core/impl/solver/DefaultSolutionManager.java b/core/src/main/java/ai/timefold/solver/core/impl/solver/DefaultSolutionManager.java
@@ -48,7 +48,7 @@ public Score_ update(Solution_ solution, SolutionUpdatePolicy solutionUpdatePoli
                     + ".update() with this solutionUpdatePolicy (" + solutionUpdatePolicy + ").");
         }
         return callScoreDirector(solution, solutionUpdatePolicy,
-                s -> (Score_) s.getSolutionDescriptor().getScore(s.getWorkingSolution()), false, false);
+                s -> s.getSolutionDescriptor().getScore(s.getWorkingSolution()), false, false);
     }
 
     private <Result_> Result_ callScoreDirector(Solution_ solution,
diff --git a/core/src/test/java/ai/timefold/solver/core/api/solver/SolverFactoryTest.java b/core/src/test/java/ai/timefold/solver/core/api/solver/SolverFactoryTest.java
diff --git a/test/src/main/java/ai/timefold/solver/test/impl/score/stream/DefaultMultiConstraintVerification.java b/test/src/main/java/ai/timefold/solver/test/impl/score/stream/DefaultMultiConstraintVerification.java
diff --git a/test/src/main/java/ai/timefold/solver/test/impl/score/stream/DefaultSingleConstraintVerification.java b/test/src/main/java/ai/timefold/solver/test/impl/score/stream/DefaultSingleConstraintVerification.java

Original file line number	Diff line number	Diff line change
`@@ -16,7 +16,7 @@`
`16`	`16`
`17`	`17`	`/**`
`18`	`18`	`* The type is public to make it easier for Bavet-specific minimal bug reproducers to be created.`
`19`		`- * Instances should be created through {@link BavetConstraintStreamScoreDirectorFactory#newSession(Object, boolean)}.`
	`19`	`+ * Instances should be created through {@link BavetConstraintStreamScoreDirectorFactory#newSession(Object, boolean, boolean)}.`
`20`	`20`	`*`
`21`	`21`	`* @see PropagationQueue Description of the tuple propagation mechanism.`
`22`	`22`	`* @param <Score_>`