Add more logging to polysat (#5186)

* Add polysat logging support

* Don't really need the usual log levels

* Indent log headings

* Add display method to ptr_vector

* Add some logging to solver

* Use __FUNCSIG__ on MSVC

src/math/polysat/CMakeLists.txt

@@ -3,6 +3,7 @@ z3_add_component(polysat
     solver.cpp
     constraint.cpp
     justification.cpp
+    log.cpp
   COMPONENT_DEPENDENCIES
     util
     dd

src/math/polysat/log.cpp

@@ -0,0 +1,92 @@
+#include <unistd.h>
+#include <utility>
+
+#include "math/polysat/log.h"
+
+#if POLYSAT_LOGGING_ENABLED
+
+static LogLevel
+get_max_log_level(std::string const& fn, std::string const& pretty_fn)
+{
+  (void)fn;
+  (void)pretty_fn;
+
+  // bool const from_decision_queue = pretty_fn.find("DecisionQueue") != std::string::npos;
+  // if (from_decision_queue) {
+  //   return LogLevel::Info;
+  // }
+
+  // if (pretty_fn.find("add_") != std::string::npos) {
+  //   return LogLevel::Info;
+  // }
+
+  // if (fn == "analyze") {
+  //   return LogLevel::Trace;
+  // }
+  // if (fn.find("minimize") != std::string::npos) {
+  //   return LogLevel::Trace;
+  // }
+  // if (fn == "propagate_literal") {
+  //     return LogLevel::Trace;
+  // }
+
+  return LogLevel::Verbose;
+  // return LogLevel::Warn;
+}
+
+/// Filter log messages
+bool
+polysat_should_log(LogLevel msg_level, std::string fn, std::string pretty_fn)
+{
+  LogLevel max_log_level = get_max_log_level(fn, pretty_fn);
+  return msg_level <= max_log_level;
+}
+
+static char const*
+level_color(LogLevel msg_level)
+{
+  switch (msg_level) {
+    case LogLevel::Heading1:
+      return "\x1B[31m"; // red
+    case LogLevel::Heading2:
+      return "\x1B[33m"; // yellow
+    case LogLevel::Heading3:
+      return "\x1B[34m"; // blue
+    default:
+      return nullptr;
+  }
+}
+
+int polysat_log_indent_level = 0;
+
+std::pair<std::ostream&, bool>
+polysat_log(LogLevel msg_level, std::string fn, std::string /* pretty_fn */)
+{
+  std::ostream& os = std::cerr;
+  int const fd = fileno(stderr);
+
+  size_t width = 20;
+  size_t padding = width - std::min(width, fn.size());
+
+  char const* color = level_color(msg_level);
+  if (color && !isatty(fd)) { color = nullptr; }
+
+  if (color) { os << color; }
+  os << "[" << fn << "] " << std::string(padding, ' ');
+  os << std::string(polysat_log_indent_level, ' ');
+  return {os, (bool)color};
+}
+
+polysat_log_indent::polysat_log_indent(int amount)
+  : m_amount{amount}
+{
+  polysat_log_indent_level += m_amount;
+}
+
+polysat_log_indent::~polysat_log_indent()
+{
+  polysat_log_indent_level -= m_amount;
+}
+
+
+#endif  // POLYSAT_LOGGING_ENABLED

src/math/polysat/log.h

@@ -0,0 +1,106 @@
+#ifndef POLYSAT_LOG_HPP
+#define POLYSAT_LOG_HPP
+
+
+// By default, enable logging only in debug mode
+#ifndef POLYSAT_LOGGING_ENABLED
+#   ifndef NDEBUG
+#       define POLYSAT_LOGGING_ENABLED 1
+#   else
+#       define POLYSAT_LOGGING_ENABLED 0
+#   endif
+#endif
+
+
+#if POLYSAT_LOGGING_ENABLED
+
+
+#include <cstdint>
+#include <iostream>
+#include <string>
+
+class polysat_log_indent
+{
+  int m_amount;
+public:
+  polysat_log_indent(int amount);
+  ~polysat_log_indent();
+};
+
+/// Lower log level means more important
+enum class LogLevel : int {
+  None = 0,
+  Heading1 = 1,
+  Heading2 = 2,
+  Heading3 = 3,
+  Default = 4,
+  Verbose = 5,
+};
+
+/// Filter log messages
+bool
+polysat_should_log(LogLevel msg_level, std::string fn, std::string pretty_fn);
+
+std::pair<std::ostream&, bool>
+polysat_log(LogLevel msg_level, std::string fn, std::string pretty_fn);
+
+#ifdef _MSC_VER
+#define __PRETTY_FUNCTION__ __FUNCSIG__
+#endif
+
+#define LOG_(lvl, x)                                               \
+  do {                                                             \
+    if (polysat_should_log(lvl, __func__, __PRETTY_FUNCTION__)) {  \
+      auto pair = polysat_log(lvl, __func__, __PRETTY_FUNCTION__); \
+      std::ostream& os = pair.first;                               \
+      bool should_reset = pair.second;                             \
+      os << x;                                                     \
+      if (should_reset) {                                          \
+        os << "\x1B[0m"; /* reset color */                         \
+      }                                                            \
+      os << std::endl;                                             \
+    }                                                              \
+  } while (false)
+
+#define LOG_CONCAT_HELPER(a,b) a ## b
+#define LOG_CONCAT(a,b) LOG_CONCAT_HELPER(a,b)
+
+#define LOG_INDENT(lvl, x)  \
+  LOG_(lvl, x);             \
+  polysat_log_indent LOG_CONCAT(polysat_log_indent_obj_, __LINE__) (4);
+
+#define LOG_H1(x) LOG_INDENT(LogLevel::Heading1, x)
+#define LOG_H2(x) LOG_INDENT(LogLevel::Heading2, x)
+#define LOG_H3(x) LOG_INDENT(LogLevel::Heading3, x)
+#define LOG(x)    LOG_(LogLevel::Default , x)
+#define LOG_V(x)  LOG_(LogLevel::Verbose , x)
+
+#define IF_LOGGING(x) \
+  do {                \
+    x;                \
+  } while (false)
+
+
+#else  // POLYSAT_LOGGING_ENABLED
+
+
+#define LOG_(lvl, x)  \
+  do {               \
+    /* do nothing */ \
+  } while (false)
+
+#define LOG_H1(x) LOG_(0, x)
+#define LOG_H2(x) LOG_(0, x)
+#define LOG_H3(x) LOG_(0, x)
+#define LOG(x)    LOG_(0, x)
+#define LOG_V(x)  LOG_(0, x)
+
+#define IF_LOGGING(x) \
+  do {                \
+    /* do nothing */  \
+  } while (false)
+
+#endif  // POLYSAT_LOGGING_ENABLED
+
+
+#endif  // POLYSAT_LOG_HPP

src/math/polysat/solver.cpp

@@ -16,6 +16,7 @@ Author:
 --*/
 
 #include "math/polysat/solver.h"
+#include "math/polysat/log.h"
 
 namespace polysat {
 
@@ -82,13 +83,39 @@ namespace polysat {
 
     solver::~solver() {}
 
+#if POLYSAT_LOGGING_ENABLED
+    void solver::log_viable(pvar v) {
+        if (size(v) <= 5) {
+            vector<rational> xs;
+            for (rational x = rational::zero(); x < rational::power_of_two(size(v)); x += 1) {
+                if (is_viable(v, x)) {
+                    xs.push_back(x);
+                }
+            }
+            LOG("Viable for pvar " << v << ": " << xs);
+        } else {
+            LOG("Viable for pvar " << v << ": <range too big>");
+        }
+    }
+#endif
+    
     lbool solver::check_sat() { 
         TRACE("polysat", tout << "check\n";);
         while (m_lim.inc()) {
-            if (is_conflict() && at_base_level()) return l_false;
+            LOG_H1("Next solving loop iteration");
+            LOG("Free variables: " << m_free_vars);
+            LOG("Assignments:    " << m_search);
+            LOG("Conflict:       " << m_conflict);
+            IF_LOGGING({
+                for (pvar v = 0; v < m_viable.size(); ++v) {
+                    log_viable(v);
+                }
+            });
+
+            if (is_conflict() && at_base_level()) { LOG_H2("UNSAT"); return l_false; }
             else if (is_conflict()) resolve_conflict();
             else if (can_propagate()) propagate();
-            else if (!can_decide()) return l_true;
+            else if (!can_decide()) { LOG_H2("SAT"); return l_true; }
             else decide();
         }
         return l_undef;
@@ -127,6 +154,7 @@ namespace polysat {
     void solver::add_eq(pdd const& p, unsigned dep) {
         p_dependency_ref d(mk_dep(dep), m_dm);
         constraint* c = constraint::eq(m_level, p, d);
+        LOG("Adding constraint: " << *c);
         m_constraints.push_back(c);
         add_watch(*c);
     }
@@ -169,6 +197,7 @@ namespace polysat {
     }
 
     void solver::propagate(pvar v) {
+        LOG_H2("Propagate pvar " << v);
         auto& wlist = m_watch[v];
         unsigned i = 0, j = 0, sz = wlist.size();
         for (; i < sz && !is_conflict(); ++i) 
@@ -179,6 +208,9 @@ namespace polysat {
         wlist.shrink(j);
     }
 
+    /**
+     * Return true iff the constraint should be removed from the current watch list.
+     */
     bool solver::propagate(pvar v, constraint& c) {
         switch (c.kind()) {
         case ckind_t::eq_t:
@@ -193,6 +225,7 @@ namespace polysat {
     }
 
     bool solver::propagate_eq(pvar v, constraint& c) {
+        LOG_H3("Propagate " << m_vars[v] << " in " << c);
         SASSERT(c.kind() == ckind_t::eq_t);
         SASSERT(!c.vars().empty());
         auto var = m_vars[v].var();
@@ -210,11 +243,14 @@ namespace polysat {
         }        
         
 
+        LOG("Assignments: " << m_search);
         auto p = c.p().subst_val(m_search);
+        LOG("Substituted: " << c.p() << " := " << p);
         TRACE("polysat", tout << c.p() << " := " << p << "\n";);
         if (p.is_zero()) 
             return false;
         if (p.is_never_zero()) {
+            LOG("Conflict (never zero under current assignment)");
             // we could tag constraint to allow early substitution before 
             // swapping watch variable in case we can detect conflict earlier.
             set_conflict(c);
@@ -334,20 +370,25 @@ namespace polysat {
     }
 
     void solver::decide() {
+        LOG_H2("Decide");
         SASSERT(can_decide());
         decide(m_free_vars.next_var());
     }
 
     void solver::decide(pvar v) {
+        IF_LOGGING(log_viable(v));
         rational val;
         switch (find_viable(v, val)) {
         case l_false:
+            LOG("Conflict: no value for pvar " << v);
             set_conflict(v);
             break;
         case l_true:
+            LOG("Propagation: pvar " << v << " := " << val << " (due to unique value)");
             assign_core(v, val, justification::propagation(m_level));
             break;
         case l_undef:
+            LOG("Decision: pvar " << v << " := " << val);
             push_level();
             assign_core(v, val, justification::decision(m_level));
             break;
@@ -360,6 +401,7 @@ namespace polysat {
         else 
             ++m_stats.m_num_propagations;
         TRACE("polysat", tout << "v" << v << " := " << val << " " << j << "\n";);
+        LOG("pvar " << v << " := " << val << " by " << j);
         SASSERT(is_viable(v, val));
         m_value[v] = val;
         m_search.push_back(std::make_pair(v, val));
@@ -400,6 +442,7 @@ namespace polysat {
      * 
      */
     void solver::resolve_conflict() {
+        LOG_H2("Resolve conflict");
         ++m_stats.m_num_conflicts;
 
         SASSERT(!m_conflict.empty());
@@ -413,6 +456,7 @@ namespace polysat {
         reset_marks();
         for (constraint* c : m_conflict) {
             SASSERT(c);
+            LOG("Conflicting: " << *c);
             for (auto v : c->vars()) 
                 set_mark(v);
         }
@@ -540,6 +584,7 @@ namespace polysat {
     }
     
     void solver::backjump(unsigned new_level) {
+        LOG_H3("Backjumping to level " << new_level << " from level " << m_level);
         unsigned num_levels = m_level - new_level;
         if (num_levels > 0) 
             pop_levels(num_levels);        
@@ -596,6 +641,7 @@ namespace polysat {
     void solver::add_lemma(constraint* c) {
         if (!c)
             return;
+        LOG("Lemma: " << *c);
         add_watch(*c);
         m_redundant.push_back(c);
         for (unsigned i = m_redundant.size() - 1; i-- > 0; ) {

src/math/polysat/solver.h

@@ -87,13 +87,18 @@ namespace polysat {
 
         
         /**
-         * Find a next viable value for varible.
+         * Find a next viable value for variable.
          * l_false - there are no viable values.
          * l_true  - there is only one viable value left.
          * l_undef - there are multiple viable values, return a guess
          */
         lbool find_viable(pvar v, rational & val);
 
+        /** Log all viable values for the given variable.
+         * (Inefficient, but useful for debugging small instances.)
+         */
+        void log_viable(pvar v);
+
         /**
          * undo trail operations for backtracking.
          * Each struct is a subclass of trail and implements undo().

src/util/vector.h

@@ -609,6 +609,19 @@ public:
     ptr_vector(unsigned s):vector<T *, false>(s) {}
     ptr_vector(unsigned s, T * elem):vector<T *, false>(s, elem) {}
     ptr_vector(unsigned s, T * const * data):vector<T *, false>(s, const_cast<T**>(data)) {}
+    std::ostream& display(std::ostream& out, char const* delim = " ") const {
+        bool first = true;
+        for (auto const* u : *this) {
+            if (!first)
+                out << delim;
+            first = false;
+            if (u)
+                out << *u;
+            else
+                out << "<NULL>";
+        }
+        return out;
+    }
 };
 
 template<typename T, typename SZ = unsigned>
@@ -635,6 +648,11 @@ inline std::ostream& operator<<(std::ostream& out, svector<T> const& v) {
     return out;
 }
 
+template<typename T>
+inline std::ostream& operator<<(std::ostream& out, ptr_vector<T> const& v) {
+    return v.display(out);
+}
+
 
 template<typename Hash, typename Vec>
 struct vector_hash_tpl {