Merge pull request #951 from YosysHQ/clifford/logdebug

Add log_debug() framework

diff --git a/frontends/aiger/aigerparse.cc b/frontends/aiger/aigerparse.cc
index cf7950c85557a300f2d4f88fe2d4d3d848e19be7..2e4774dfdc32433feb3f2a63f3499953c2a91c02 100644 (file)
--- a/frontends/aiger/aigerparse.cc
+++ b/frontends/aiger/aigerparse.cc
@@ -33,8 +33,6 @@
 
 YOSYS_NAMESPACE_BEGIN
 
-#define log_debug log
-
 AigerReader::AigerReader(RTLIL::Design *design, std::istream &f, RTLIL::IdString module_name, RTLIL::IdString clk_name)
     : design(design), f(f), clk_name(clk_name)
 {

diff --git a/kernel/driver.cc b/kernel/driver.cc
index c539ba56976e691c039aabde3fddfeabd9943dbb..1bc7a5935a41541b7114ea7dadeee00f90d7be7d 100644 (file)
--- a/kernel/driver.cc
+++ b/kernel/driver.cc
@@ -295,6 +295,9 @@ int main(int argc, char **argv)
                printf("    -E <depsfile>\n");
                printf("        write a Makefile dependencies file with in- and output file names\n");
                printf("\n");
+               printf("    -g\n");
+               printf("        globally enable debug log messages\n");
+               printf("\n");
                printf("    -V\n");
                printf("        print version information and exit\n");
                printf("\n");
@@ -315,7 +318,7 @@ int main(int argc, char **argv)
        }
 
        int opt;
-       while ((opt = getopt(argc, argv, "MXAQTVSm:f:Hh:b:o:p:l:L:qv:tds:c:W:w:e:D:P:E:")) != -1)
+       while ((opt = getopt(argc, argv, "MXAQTVSgm:f:Hh:b:o:p:l:L:qv:tds:c:W:w:e:D:P:E:")) != -1)
        {
                switch (opt)
                {
@@ -340,6 +343,9 @@ int main(int argc, char **argv)
                case 'S':
                        passes_commands.push_back("synth");
                        break;
+               case 'g':
+                       log_force_debug++;
+                       break;
                case 'm':
                        plugin_filenames.push_back(optarg);
                        break;

diff --git a/kernel/log.cc b/kernel/log.cc
index 400a549dd90486e6dad9cb9c9876b864ae04c78f..9a9104e265e379ac19652e3c42414d4727eb18aa 100644 (file)
--- a/kernel/log.cc
+++ b/kernel/log.cc
@@ -56,6 +56,10 @@ int log_verbose_level;
 string log_last_error;
 void (*log_error_atexit)() = NULL;
 
+int log_make_debug = 0;
+int log_force_debug = 0;
+int log_debug_suppressed = 0;
+
 vector<int> header_count;
 pool<RTLIL::IdString> log_id_cache;
 vector<shared_str> string_buf;
@@ -92,6 +96,9 @@ void logv(const char *format, va_list ap)
                format++;
        }
 
+       if (log_make_debug && !ys_debug(1))
+               return;
+
        std::string str = vstringf(format, ap);
 
        if (str.empty())

diff --git a/kernel/log.h b/kernel/log.h
index 759939025bc41862e41782859e2005853ffcc47b..e6afae716a3cb0e88054437be7f99382fe242b8f 100644 (file)
--- a/kernel/log.h
+++ b/kernel/log.h
@@ -64,6 +64,10 @@ extern int log_verbose_level;
 extern string log_last_error;
 extern void (*log_error_atexit)();
 
+extern int log_make_debug;
+extern int log_force_debug;
+extern int log_debug_suppressed;
+
 void logv(const char *format, va_list ap);
 void logv_header(RTLIL::Design *design, const char *format, va_list ap);
 void logv_warning(const char *format, va_list ap);
@@ -82,6 +86,45 @@ YS_NORETURN void log_error(const char *format, ...) YS_ATTRIBUTE(format(printf,
 void log_file_error(const string &filename, int lineno, const char *format, ...) YS_ATTRIBUTE(format(printf, 3, 4), noreturn);
 YS_NORETURN void log_cmd_error(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2), noreturn);
 
+#ifndef NDEBUG
+static inline bool ys_debug(int n = 0) { if (log_force_debug) return true; log_debug_suppressed += n; return false; }
+#  define log_debug(...) do { if (ys_debug(1)) log(__VA_ARGS__); } while (0)
+#else
+static inline bool ys_debug(int n = 0) { return false; }
+#  define log_debug(_fmt, ...) do { } while (0)
+#endif
+
+static inline void log_suppressed() {
+       if (log_debug_suppressed && !log_make_debug) {
+               log("<suppressed ~%d debug messages>\n", log_debug_suppressed);
+               log_debug_suppressed = 0;
+       }
+}
+
+struct LogMakeDebugHdl {
+       bool status = false;
+       LogMakeDebugHdl(bool start_on = false) {
+               if (start_on)
+                       on();
+       }
+       ~LogMakeDebugHdl() {
+               off();
+       }
+       void on() {
+               if (status) return;
+               status=true;
+               log_make_debug++;
+       }
+       void off_silent() {
+               if (!status) return;
+               status=false;
+               log_make_debug--;
+       }
+       void off() {
+               off_silent();
+       }
+};
+
 void log_spacer();
 void log_push();
 void log_pop();

diff --git a/kernel/register.cc b/kernel/register.cc
index 64956401f2348bcb19a376d38e383c75bf78ab24..71eb6b1870808219bc74edea57c930d4577e79a2 100644 (file)
--- a/kernel/register.cc
+++ b/kernel/register.cc
@@ -87,6 +87,7 @@ Pass::pre_post_exec_state_t Pass::pre_execute()
 void Pass::post_execute(Pass::pre_post_exec_state_t state)
 {
        IdString::checkpoint();
+       log_suppressed();
 
        int64_t time_ns = PerformanceTimer::query() - state.begin_ns;
        runtime_ns += time_ns;

diff --git a/passes/cmds/trace.cc b/passes/cmds/trace.cc
index f5305cde95768220ecb99d85fa62a0eb4eac49ce..cf3e46ace2d6992adf88ea1f9d749cebac599542 100644 (file)
--- a/passes/cmds/trace.cc
+++ b/passes/cmds/trace.cc
@@ -94,4 +94,38 @@ struct TracePass : public Pass {
        }
 } TracePass;
 
+struct DebugPass : public Pass {
+       DebugPass() : Pass("debug", "run command with debug log messages enabled") { }
+       void help() YS_OVERRIDE
+       {
+               //   |---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|
+               log("\n");
+               log("    debug cmd\n");
+               log("\n");
+               log("Execute the specified command with debug log messages enabled\n");
+               log("\n");
+       }
+       void execute(std::vector<std::string> args, RTLIL::Design *design) YS_OVERRIDE
+       {
+               size_t argidx;
+               for (argidx = 1; argidx < args.size(); argidx++)
+               {
+                       // .. parse options ..
+                       break;
+               }
+
+               log_force_debug++;
+
+               try {
+                       std::vector<std::string> new_args(args.begin() + argidx, args.end());
+                       Pass::call(design, new_args);
+               } catch (...) {
+                       log_force_debug--;
+                       throw;
+               }
+
+               log_force_debug--;
+       }
+} DebugPass;
+
 PRIVATE_NAMESPACE_END

diff --git a/passes/opt/opt_clean.cc b/passes/opt/opt_clean.cc
index c3b13acaf3951f276624f8d30569222fdec44e53..c38e9df5e7db7fead4804f1bf8b0cecc90bc0a23 100644 (file)
--- a/passes/opt/opt_clean.cc
+++ b/passes/opt/opt_clean.cc
@@ -137,7 +137,7 @@ void rmunused_module_cells(Module *module, bool verbose)
 
        for (auto cell : unused) {
                if (verbose)
-                       log("  removing unused `%s' cell `%s'.\n", cell->type.c_str(), cell->name.c_str());
+                       log_debug("  removing unused `%s' cell `%s'.\n", cell->type.c_str(), cell->name.c_str());
                module->design->scratchpad_set_bool("opt.did_something", true);
                module->remove(cell);
                count_rm_cells++;
@@ -326,7 +326,7 @@ void rmunused_module_signals(RTLIL::Module *module, bool purge_mode, bool verbos
        for (auto wire : maybe_del_wires)
                if (!used_signals.check_any(RTLIL::SigSpec(wire))) {
                        if (check_public_name(wire->name) && verbose) {
-                               log("  removing unused non-port wire %s.\n", wire->name.c_str());
+                               log_debug("  removing unused non-port wire %s.\n", wire->name.c_str());
                        }
                        del_wires.insert(wire);
                        del_wires_count++;
@@ -336,7 +336,7 @@ void rmunused_module_signals(RTLIL::Module *module, bool purge_mode, bool verbos
        count_rm_wires += del_wires.size();
 
        if (verbose && del_wires_count > 0)
-               log("  removed %d unused temporary wires.\n", del_wires_count);
+               log_debug("  removed %d unused temporary wires.\n", del_wires_count);
 }
 
 bool rmunused_module_init(RTLIL::Module *module, bool purge_mode, bool verbose)
@@ -399,7 +399,7 @@ bool rmunused_module_init(RTLIL::Module *module, bool purge_mode, bool verbose)
                }
 
                if (verbose)
-                       log("  removing redundant init attribute on %s.\n", log_id(wire));
+                       log_debug("  removing redundant init attribute on %s.\n", log_id(wire));
 
                wire->attributes.erase("\\init");
                did_something = true;
@@ -426,7 +426,7 @@ void rmunused_module(RTLIL::Module *module, bool purge_mode, bool verbose, bool
                }
        for (auto cell : delcells) {
                if (verbose)
-                       log("  removing buffer cell `%s': %s = %s\n", cell->name.c_str(),
+                       log_debug("  removing buffer cell `%s': %s = %s\n", cell->name.c_str(),
                                        log_signal(cell->getPort("\\Y")), log_signal(cell->getPort("\\A")));
                module->remove(cell);
        }
@@ -551,6 +551,7 @@ struct CleanPass : public Pass {
                        rmunused_module(module, purge_mode, false, false);
                }
 
+               log_suppressed();
                if (count_rm_cells > 0 || count_rm_wires > 0)
                        log("Removed %d unused cells and %d unused wires.\n", count_rm_cells, count_rm_wires);
 

diff --git a/passes/opt/opt_expr.cc b/passes/opt/opt_expr.cc
index a05db2a4fdf86d72a1ab75f4fcb9dfc6a19987af..af6d352afa04e6a4cf7612451f664d0a27f3587b 100644 (file)
--- a/passes/opt/opt_expr.cc
+++ b/passes/opt/opt_expr.cc
@@ -67,7 +67,7 @@ void replace_undriven(RTLIL::Design *design, RTLIL::Module *module)
                if (sig.size() == 0)
                        continue;
 
-               log("Setting undriven signal in %s to undef: %s\n", RTLIL::id2cstr(module->name), log_signal(c));
+               log_debug("Setting undriven signal in %s to undef: %s\n", RTLIL::id2cstr(module->name), log_signal(c));
                module->connect(RTLIL::SigSig(c, RTLIL::SigSpec(RTLIL::State::Sx, c.width)));
                did_something = true;
        }
@@ -78,7 +78,7 @@ void replace_cell(SigMap &assign_map, RTLIL::Module *module, RTLIL::Cell *cell,
        RTLIL::SigSpec Y = cell->getPort(out_port);
        out_val.extend_u0(Y.size(), false);
 
-       log("Replacing %s cell `%s' (%s) in module `%s' with constant driver `%s = %s'.\n",
+       log_debug("Replacing %s cell `%s' (%s) in module `%s' with constant driver `%s = %s'.\n",
                        cell->type.c_str(), cell->name.c_str(), info.c_str(),
                        module->name.c_str(), log_signal(Y), log_signal(out_val));
        // log_cell(cell);
@@ -134,7 +134,7 @@ bool group_cell_inputs(RTLIL::Module *module, RTLIL::Cell *cell, bool commutativ
                if (GetSize(grouped_bits[i]) == GetSize(bits_y))
                        return false;
 
-       log("Replacing %s cell `%s' in module `%s' with cells using grouped bits:\n",
+       log_debug("Replacing %s cell `%s' in module `%s' with cells using grouped bits:\n",
                        log_id(cell->type), log_id(cell), log_id(module));
 
        for (int i = 0; i < GRP_N; i++)
@@ -156,7 +156,7 @@ bool group_cell_inputs(RTLIL::Module *module, RTLIL::Cell *cell, bool commutativ
                }
 
                if (cell->type.in("$and", "$or") && i == GRP_CONST_A) {
-                       log("  Direct Connection: %s (%s with %s)\n", log_signal(new_b), log_id(cell->type), log_signal(new_a));
+                       log_debug("  Direct Connection: %s (%s with %s)\n", log_signal(new_b), log_id(cell->type), log_signal(new_a));
                        module->connect(new_y, new_b);
                        module->connect(new_conn);
                        continue;
@@ -180,10 +180,10 @@ bool group_cell_inputs(RTLIL::Module *module, RTLIL::Cell *cell, bool commutativ
 
                module->connect(new_conn);
 
-               log("  New cell `%s': A=%s", log_id(c), log_signal(new_a));
+               log_debug("  New cell `%s': A=%s", log_id(c), log_signal(new_a));
                if (b_name == "\\B")
-                       log(", B=%s", log_signal(new_b));
-               log("\n");
+                       log_debug(", B=%s", log_signal(new_b));
+               log_debug("\n");
        }
 
        cover_list("opt.opt_expr.fine.group", "$not", "$pos", "$and", "$or", "$xor", "$xnor", cell->type.str());
@@ -197,7 +197,7 @@ void handle_polarity_inv(Cell *cell, IdString port, IdString param, const SigMap
 {
        SigSpec sig = assign_map(cell->getPort(port));
        if (invert_map.count(sig)) {
-               log("Inverting %s of %s cell `%s' in module `%s': %s -> %s\n",
+               log_debug("Inverting %s of %s cell `%s' in module `%s': %s -> %s\n",
                                log_id(port), log_id(cell->type), log_id(cell), log_id(cell->module),
                                log_signal(sig), log_signal(invert_map.at(sig)));
                cell->setPort(port, (invert_map.at(sig)));
@@ -226,7 +226,7 @@ void handle_clkpol_celltype_swap(Cell *cell, string type1, string type2, IdStrin
        if (cell->type.in(type1, type2)) {
                SigSpec sig = assign_map(cell->getPort(port));
                if (invert_map.count(sig)) {
-                       log("Inverting %s of %s cell `%s' in module `%s': %s -> %s\n",
+                       log_debug("Inverting %s of %s cell `%s' in module `%s': %s -> %s\n",
                                        log_id(port), log_id(cell->type), log_id(cell), log_id(cell->module),
                                        log_signal(sig), log_signal(invert_map.at(sig)));
                        cell->setPort(port, (invert_map.at(sig)));
@@ -455,9 +455,10 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                {
                        if (cell->type == "$reduce_xnor") {
                                cover("opt.opt_expr.reduce_xnor_not");
-                               log("Replacing %s cell `%s' in module `%s' with $not cell.\n",
+                               log_debug("Replacing %s cell `%s' in module `%s' with $not cell.\n",
                                                log_id(cell->type), log_id(cell->name), log_id(module));
                                cell->type = "$not";
+                               did_something = true;
                        } else {
                                cover("opt.opt_expr.unary_buffer");
                                replace_cell(assign_map, module, cell, "unary_buffer", "\\Y", cell->getPort("\\A"));
@@ -488,7 +489,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (GetSize(new_sig_a) < GetSize(sig_a)) {
                                        cover_list("opt.opt_expr.fine.neutral_A", "$logic_not", "$logic_and", "$logic_or", "$reduce_or", "$reduce_and", "$reduce_bool", cell->type.str());
-                                       log("Replacing port A of %s cell `%s' in module `%s' with shorter expression: %s -> %s\n",
+                                       log_debug("Replacing port A of %s cell `%s' in module `%s' with shorter expression: %s -> %s\n",
                                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), log_signal(sig_a), log_signal(new_sig_a));
                                        cell->setPort("\\A", new_sig_a);
                                        cell->parameters.at("\\A_WIDTH") = GetSize(new_sig_a);
@@ -511,7 +512,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (GetSize(new_sig_b) < GetSize(sig_b)) {
                                        cover_list("opt.opt_expr.fine.neutral_B", "$logic_and", "$logic_or", cell->type.str());
-                                       log("Replacing port B of %s cell `%s' in module `%s' with shorter expression: %s -> %s\n",
+                                       log_debug("Replacing port B of %s cell `%s' in module `%s' with shorter expression: %s -> %s\n",
                                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), log_signal(sig_b), log_signal(new_sig_b));
                                        cell->setPort("\\B", new_sig_b);
                                        cell->parameters.at("\\B_WIDTH") = GetSize(new_sig_b);
@@ -537,7 +538,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (new_a != RTLIL::State::Sm && RTLIL::SigSpec(new_a) != sig_a) {
                                        cover("opt.opt_expr.fine.$reduce_and");
-                                       log("Replacing port A of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
+                                       log_debug("Replacing port A of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
                                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), log_signal(sig_a), log_signal(new_a));
                                        cell->setPort("\\A", sig_a = new_a);
                                        cell->parameters.at("\\A_WIDTH") = 1;
@@ -563,7 +564,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (new_a != RTLIL::State::Sm && RTLIL::SigSpec(new_a) != sig_a) {
                                        cover_list("opt.opt_expr.fine.A", "$logic_not", "$logic_and", "$logic_or", "$reduce_or", "$reduce_bool", cell->type.str());
-                                       log("Replacing port A of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
+                                       log_debug("Replacing port A of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
                                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), log_signal(sig_a), log_signal(new_a));
                                        cell->setPort("\\A", sig_a = new_a);
                                        cell->parameters.at("\\A_WIDTH") = 1;
@@ -589,7 +590,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (new_b != RTLIL::State::Sm && RTLIL::SigSpec(new_b) != sig_b) {
                                        cover_list("opt.opt_expr.fine.B", "$logic_and", "$logic_or", cell->type.str());
-                                       log("Replacing port B of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
+                                       log_debug("Replacing port B of %s cell `%s' in module `%s' with constant driver: %s -> %s\n",
                                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), log_signal(sig_b), log_signal(new_b));
                                        cell->setPort("\\B", sig_b = new_b);
                                        cell->parameters.at("\\B_WIDTH") = 1;
@@ -640,7 +641,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                if ((cell->type == "$_MUX_" || cell->type == "$mux") && invert_map.count(assign_map(cell->getPort("\\S"))) != 0) {
                        cover_list("opt.opt_expr.invert.muxsel", "$_MUX_", "$mux", cell->type.str());
-                       log("Optimizing away select inverter for %s cell `%s' in module `%s'.\n", log_id(cell->type), log_id(cell), log_id(module));
+                       log_debug("Optimizing away select inverter for %s cell `%s' in module `%s'.\n", log_id(cell->type), log_id(cell), log_id(module));
                        RTLIL::SigSpec tmp = cell->getPort("\\A");
                        cell->setPort("\\A", cell->getPort("\\B"));
                        cell->setPort("\\B", tmp);
@@ -750,7 +751,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                ACTION_DO("\\Y", cell->getPort("\\A"));
                        if (input == State::S0 && !a.is_fully_undef()) {
                                cover("opt.opt_expr.action_" S__LINE__);
-                               log("Replacing data input of %s cell `%s' in module `%s' with constant undef.\n",
+                               log_debug("Replacing data input of %s cell `%s' in module `%s' with constant undef.\n",
                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str());
                                cell->setPort("\\A", SigSpec(State::Sx, GetSize(a)));
                                did_something = true;
@@ -822,7 +823,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                        ACTION_DO("\\Y", cell->getPort("\\A"));
                                } else {
                                        cover_list("opt.opt_expr.eqneq.isnot", "$eq", "$ne", cell->type.str());
-                                       log("Replacing %s cell `%s' in module `%s' with inverter.\n", log_id(cell->type), log_id(cell), log_id(module));
+                                       log_debug("Replacing %s cell `%s' in module `%s' with inverter.\n", log_id(cell->type), log_id(cell), log_id(module));
                                        cell->type = "$not";
                                        cell->parameters.erase("\\B_WIDTH");
                                        cell->parameters.erase("\\B_SIGNED");
@@ -837,7 +838,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                (assign_map(cell->getPort("\\A")).is_fully_zero() || assign_map(cell->getPort("\\B")).is_fully_zero()))
                {
                        cover_list("opt.opt_expr.eqneq.cmpzero", "$eq", "$ne", cell->type.str());
-                       log("Replacing %s cell `%s' in module `%s' with %s.\n", log_id(cell->type), log_id(cell),
+                       log_debug("Replacing %s cell `%s' in module `%s' with %s.\n", log_id(cell->type), log_id(cell),
                                        log_id(module), "$eq" ? "$logic_not" : "$reduce_bool");
                        cell->type = cell->type == "$eq" ? "$logic_not" : "$reduce_bool";
                        if (assign_map(cell->getPort("\\A")).is_fully_zero()) {
@@ -876,7 +877,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                        cover_list("opt.opt_expr.constshift", "$shl", "$shr", "$sshl", "$sshr", "$shift", "$shiftx", cell->type.str());
 
-                       log("Replacing %s cell `%s' (B=%s, SHR=%d) in module `%s' with fixed wiring: %s\n",
+                       log_debug("Replacing %s cell `%s' (B=%s, SHR=%d) in module `%s' with fixed wiring: %s\n",
                                        log_id(cell->type), log_id(cell), log_signal(assign_map(cell->getPort("\\B"))), shift_bits, log_id(module), log_signal(sig_y));
 
                        module->connect(cell->getPort("\\Y"), sig_y);
@@ -939,7 +940,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                if (identity_wrt_b)
                                        cover_list("opt.opt_expr.identwrt.b", "$add", "$sub", "$or", "$xor", "$shl", "$shr", "$sshl", "$sshr", "$shift", "$shiftx", "$mul", "$div", cell->type.str());
 
-                               log("Replacing %s cell `%s' in module `%s' with identity for port %c.\n",
+                               log_debug("Replacing %s cell `%s' in module `%s' with identity for port %c.\n",
                                        cell->type.c_str(), cell->name.c_str(), module->name.c_str(), identity_wrt_a ? 'A' : 'B');
 
                                if (!identity_wrt_a) {
@@ -969,7 +970,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                if (mux_bool && (cell->type == "$mux" || cell->type == "$_MUX_") &&
                                cell->getPort("\\A") == RTLIL::SigSpec(1, 1) && cell->getPort("\\B") == RTLIL::SigSpec(0, 1)) {
                        cover_list("opt.opt_expr.mux_invert", "$mux", "$_MUX_", cell->type.str());
-                       log("Replacing %s cell `%s' in module `%s' with inverter.\n", log_id(cell->type), log_id(cell), log_id(module));
+                       log_debug("Replacing %s cell `%s' in module `%s' with inverter.\n", log_id(cell->type), log_id(cell), log_id(module));
                        cell->setPort("\\A", cell->getPort("\\S"));
                        cell->unsetPort("\\B");
                        cell->unsetPort("\\S");
@@ -988,7 +989,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                if (consume_x && mux_bool && (cell->type == "$mux" || cell->type == "$_MUX_") && cell->getPort("\\A") == RTLIL::SigSpec(0, 1)) {
                        cover_list("opt.opt_expr.mux_and", "$mux", "$_MUX_", cell->type.str());
-                       log("Replacing %s cell `%s' in module `%s' with and-gate.\n", log_id(cell->type), log_id(cell), log_id(module));
+                       log_debug("Replacing %s cell `%s' in module `%s' with and-gate.\n", log_id(cell->type), log_id(cell), log_id(module));
                        cell->setPort("\\A", cell->getPort("\\S"));
                        cell->unsetPort("\\S");
                        if (cell->type == "$mux") {
@@ -1008,7 +1009,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                if (consume_x && mux_bool && (cell->type == "$mux" || cell->type == "$_MUX_") && cell->getPort("\\B") == RTLIL::SigSpec(1, 1)) {
                        cover_list("opt.opt_expr.mux_or", "$mux", "$_MUX_", cell->type.str());
-                       log("Replacing %s cell `%s' in module `%s' with or-gate.\n", log_id(cell->type), log_id(cell), log_id(module));
+                       log_debug("Replacing %s cell `%s' in module `%s' with or-gate.\n", log_id(cell->type), log_id(cell), log_id(module));
                        cell->setPort("\\B", cell->getPort("\\S"));
                        cell->unsetPort("\\S");
                        if (cell->type == "$mux") {
@@ -1061,7 +1062,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                        }
                        if (cell->getPort("\\S").size() != new_s.size()) {
                                cover_list("opt.opt_expr.mux_reduce", "$mux", "$pmux", cell->type.str());
-                               log("Optimized away %d select inputs of %s cell `%s' in module `%s'.\n",
+                               log_debug("Optimized away %d select inputs of %s cell `%s' in module `%s'.\n",
                                                GetSize(cell->getPort("\\S")) - GetSize(new_s), log_id(cell->type), log_id(cell), log_id(module));
                                cell->setPort("\\A", new_a);
                                cell->setPort("\\B", new_b);
@@ -1179,7 +1180,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                {
                                        cover("opt.opt_expr.mul_shift.zero");
 
-                                       log("Replacing multiply-by-zero cell `%s' in module `%s' with zero-driver.\n",
+                                       log_debug("Replacing multiply-by-zero cell `%s' in module `%s' with zero-driver.\n",
                                                        cell->name.c_str(), module->name.c_str());
 
                                        module->connect(RTLIL::SigSig(sig_y, RTLIL::SigSpec(0, sig_y.size())));
@@ -1197,7 +1198,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                                else
                                                        cover("opt.opt_expr.mul_shift.unswapped");
 
-                                               log("Replacing multiply-by-%d cell `%s' in module `%s' with shift-by-%d.\n",
+                                               log_debug("Replacing multiply-by-%d cell `%s' in module `%s' with shift-by-%d.\n",
                                                                a_val, cell->name.c_str(), module->name.c_str(), i);
 
                                                if (!swapped_ab) {
@@ -1237,7 +1238,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                {
                                        cover("opt.opt_expr.divmod_zero");
 
-                                       log("Replacing divide-by-zero cell `%s' in module `%s' with undef-driver.\n",
+                                       log_debug("Replacing divide-by-zero cell `%s' in module `%s' with undef-driver.\n",
                                                        cell->name.c_str(), module->name.c_str());
 
                                        module->connect(RTLIL::SigSig(sig_y, RTLIL::SigSpec(State::Sx, sig_y.size())));
@@ -1254,7 +1255,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                                {
                                                        cover("opt.opt_expr.div_shift");
 
-                                                       log("Replacing divide-by-%d cell `%s' in module `%s' with shift-by-%d.\n",
+                                                       log_debug("Replacing divide-by-%d cell `%s' in module `%s' with shift-by-%d.\n",
                                                                        b_val, cell->name.c_str(), module->name.c_str(), i);
 
                                                        std::vector<RTLIL::SigBit> new_b = RTLIL::SigSpec(i, 6);
@@ -1272,7 +1273,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                                {
                                                        cover("opt.opt_expr.mod_mask");
 
-                                                       log("Replacing modulo-by-%d cell `%s' in module `%s' with bitmask.\n",
+                                                       log_debug("Replacing modulo-by-%d cell `%s' in module `%s' with bitmask.\n",
                                                                        b_val, cell->name.c_str(), module->name.c_str());
 
                                                        std::vector<RTLIL::SigBit> new_b = RTLIL::SigSpec(State::S1, i);
@@ -1342,7 +1343,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
                                SigSpec y_sig = cell->getPort("\\Y");
                                Const y_value(cell->type.in("$eq", "$eqx") ? 0 : 1, GetSize(y_sig));
 
-                               log("Replacing cell `%s' in module `%s' with constant driver %s.\n",
+                               log_debug("Replacing cell `%s' in module `%s' with constant driver %s.\n",
                                        log_id(cell), log_id(module), log_signal(y_value));
 
                                module->connect(y_sig, y_value);
@@ -1354,7 +1355,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                        if (redundant_bits)
                        {
-                               log("Removed %d redundant input bits from %s cell `%s' in module `%s'.\n",
+                               log_debug("Removed %d redundant input bits from %s cell `%s' in module `%s'.\n",
                                                redundant_bits, log_id(cell->type), log_id(cell), log_id(module));
 
                                cell->setPort("\\A", sig_a);
@@ -1493,7 +1494,7 @@ void replace_const_cells(RTLIL::Design *design, RTLIL::Module *module, bool cons
 
                                if (replace || remove)
                                {
-                                       log("Replacing %s cell `%s' (implementing %s) with %s.\n",
+                                       log_debug("Replacing %s cell `%s' (implementing %s) with %s.\n",
                                                        log_id(cell->type), log_id(cell), condition.c_str(), replacement.c_str());
                                        if (replace)
                                                module->connect(cell->getPort("\\Y"), replace_sig);
@@ -1599,8 +1600,14 @@ struct OptExprPass : public Pass {
 
                for (auto module : design->selected_modules())
                {
-                       if (undriven)
+                       log("Optimizing module %s.\n", log_id(module));
+
+                       if (undriven) {
+                               did_something = false;
                                replace_undriven(design, module);
+                               if (did_something)
+                                       design->scratchpad_set_bool("opt.did_something", true);
+                       }
 
                        do {
                                do {
@@ -1610,7 +1617,11 @@ struct OptExprPass : public Pass {
                                                design->scratchpad_set_bool("opt.did_something", true);
                                } while (did_something);
                                replace_const_cells(design, module, true, mux_undef, mux_bool, do_fine, keepdc, clkinv);
+                               if (did_something)
+                                       design->scratchpad_set_bool("opt.did_something", true);
                        } while (did_something);
+
+                       log_suppressed();
                }
 
                log_pop();

diff --git a/passes/opt/opt_merge.cc b/passes/opt/opt_merge.cc
index eedf88904d5afe8838288df79ee6452ea7e4f267..7567d4657cd93a51bf055502741dbdc3ef920374 100644 (file)
--- a/passes/opt/opt_merge.cc
+++ b/passes/opt/opt_merge.cc
@@ -315,17 +315,17 @@ struct OptMergeWorker
                        {
                                if (sharemap.count(cell) > 0) {
                                        did_something = true;
-                                       log("  Cell `%s' is identical to cell `%s'.\n", cell->name.c_str(), sharemap[cell]->name.c_str());
+                                       log_debug("  Cell `%s' is identical to cell `%s'.\n", cell->name.c_str(), sharemap[cell]->name.c_str());
                                        for (auto &it : cell->connections()) {
                                                if (cell->output(it.first)) {
                                                        RTLIL::SigSpec other_sig = sharemap[cell]->getPort(it.first);
-                                                       log("    Redirecting output %s: %s = %s\n", it.first.c_str(),
+                                                       log_debug("    Redirecting output %s: %s = %s\n", it.first.c_str(),
                                                                        log_signal(it.second), log_signal(other_sig));
                                                        module->connect(RTLIL::SigSig(it.second, other_sig));
                                                        assign_map.add(it.second, other_sig);
                                                }
                                        }
-                                       log("    Removing %s cell `%s' from module `%s'.\n", cell->type.c_str(), cell->name.c_str(), module->name.c_str());
+                                       log_debug("    Removing %s cell `%s' from module `%s'.\n", cell->type.c_str(), cell->name.c_str(), module->name.c_str());
 #ifdef USE_CELL_HASH_CACHE
                                        cell_hash_cache.erase(cell);
 #endif
@@ -336,6 +336,8 @@ struct OptMergeWorker
                                }
                        }
                }
+
+               log_suppressed();
        }
 };
 

diff --git a/passes/opt/opt_muxtree.cc b/passes/opt/opt_muxtree.cc
index 375697dc8dd5f2a44446c6c8414b641d9684df73..dbebf21e04bb3ba402c4f97d7da021294be76055 100644 (file)
--- a/passes/opt/opt_muxtree.cc
+++ b/passes/opt/opt_muxtree.cc
@@ -181,14 +181,14 @@ struct OptMuxtreeWorker
 
                for (int mux_idx = 0; mux_idx < GetSize(root_muxes); mux_idx++)
                        if (root_muxes.at(mux_idx)) {
-                               log("    Root of a mux tree: %s%s\n", log_id(mux2info[mux_idx].cell), root_enable_muxes.at(mux_idx) ? " (pure)" : "");
+                               log_debug("    Root of a mux tree: %s%s\n", log_id(mux2info[mux_idx].cell), root_enable_muxes.at(mux_idx) ? " (pure)" : "");
                                root_mux_rerun.erase(mux_idx);
                                eval_root_mux(mux_idx);
                        }
 
                while (!root_mux_rerun.empty()) {
                        int mux_idx = *root_mux_rerun.begin();
-                       log("    Root of a mux tree: %s (rerun as non-pure)\n", log_id(mux2info[mux_idx].cell));
+                       log_debug("    Root of a mux tree: %s (rerun as non-pure)\n", log_id(mux2info[mux_idx].cell));
                        log_assert(root_enable_muxes.at(mux_idx));
                        root_mux_rerun.erase(mux_idx);
                        eval_root_mux(mux_idx);
@@ -326,7 +326,7 @@ struct OptMuxtreeWorker
                                if (abort_count == 0) {
                                        root_mux_rerun.insert(m);
                                        root_enable_muxes.at(m) = true;
-                                       log("      Removing pure flag from root mux %s.\n", log_id(mux2info[m].cell));
+                                       log_debug("      Removing pure flag from root mux %s.\n", log_id(mux2info[m].cell));
                                } else
                                        eval_mux(knowledge, m, false, do_enable_ports, abort_count - 1);
                        } else

diff --git a/passes/techmap/techmap.cc b/passes/techmap/techmap.cc
index 1a431846034ede0125478fd581c3901866a0ae64..ab0bd3b54f034361ae8cf68083e1fda8bf3ad317 100644 (file)
--- a/passes/techmap/techmap.cc
+++ b/passes/techmap/techmap.cc
@@ -72,6 +72,8 @@ struct TechmapWorker
        pool<IdString> flatten_done_list;
        pool<Cell*> flatten_keep_list;
 
+       pool<string> log_msg_cache;
+
        struct TechmapWireData {
                RTLIL::Wire *wire;
                RTLIL::SigSpec value;
@@ -390,6 +392,7 @@ struct TechmapWorker
 
                bool log_continue = false;
                bool did_something = false;
+               LogMakeDebugHdl mkdebug;
 
                SigMap sigmap(module);
 
@@ -547,6 +550,7 @@ struct TechmapWorker
                                                                if (extmapper_name == "wrap") {
                                                                        std::string cmd_string = tpl->attributes.at("\\techmap_wrap").decode_string();
                                                                        log("Running \"%s\" on wrapper %s.\n", cmd_string.c_str(), log_id(extmapper_module));
+                                                                       mkdebug.on();
                                                                        Pass::call_on_module(extmapper_design, extmapper_module, cmd_string);
                                                                        log_continue = true;
                                                                }
@@ -560,11 +564,21 @@ struct TechmapWorker
                                                                goto use_wrapper_tpl;
                                                        }
 
-                                                       log("%s %s.%s (%s) to %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(cell->type), log_id(extmapper_module));
+                                                       auto msg = stringf("Using extmapper %s for cells of type %s.", log_id(extmapper_module), log_id(cell->type));
+                                                       if (!log_msg_cache.count(msg)) {
+                                                               log_msg_cache.insert(msg);
+                                                               log("%s\n", msg.c_str());
+                                                       }
+                                                       log_debug("%s %s.%s (%s) to %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(cell->type), log_id(extmapper_module));
                                                }
                                                else
                                                {
-                                                       log("%s %s.%s (%s) with %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(cell->type), extmapper_name.c_str());
+                                                       auto msg = stringf("Using extmapper %s for cells of type %s.", extmapper_name.c_str(), log_id(cell->type));
+                                                       if (!log_msg_cache.count(msg)) {
+                                                               log_msg_cache.insert(msg);
+                                                               log("%s\n", msg.c_str());
+                                                       }
+                                                       log_debug("%s %s.%s (%s) with %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(cell->type), extmapper_name.c_str());
 
                                                        if (extmapper_name == "simplemap") {
                                                                if (simplemap_mappers.count(cell->type) == 0)
@@ -662,6 +676,7 @@ struct TechmapWorker
                                                tpl = techmap_cache[key];
                                        } else {
                                                if (parameters.size() != 0) {
+                                                       mkdebug.on();
                                                        derived_name = tpl->derive(map, dict<RTLIL::IdString, RTLIL::Const>(parameters.begin(), parameters.end()));
                                                        tpl = map->module(derived_name);
                                                        log_continue = true;
@@ -831,6 +846,7 @@ struct TechmapWorker
                                                if (log_continue) {
                                                        log_header(design, "Continuing TECHMAP pass.\n");
                                                        log_continue = false;
+                                                       mkdebug.off();
                                                }
                                                while (techmap_module(map, tpl, map, handled_cells, celltypeMap, true)) { }
                                        }
@@ -842,6 +858,7 @@ struct TechmapWorker
                                if (log_continue) {
                                        log_header(design, "Continuing TECHMAP pass.\n");
                                        log_continue = false;
+                                       mkdebug.off();
                                }
 
                                if (extern_mode && !in_recursion)
@@ -861,13 +878,18 @@ struct TechmapWorker
                                                module_queue.insert(m);
                                        }
 
-                                       log("%s %s.%s to imported %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(m_name));
+                                       log_debug("%s %s.%s to imported %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(m_name));
                                        cell->type = m_name;
                                        cell->parameters.clear();
                                }
                                else
                                {
-                                       log("%s %s.%s using %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(tpl));
+                                       auto msg = stringf("Using template %s for cells of type %s.", log_id(tpl), log_id(cell->type));
+                                       if (!log_msg_cache.count(msg)) {
+                                               log_msg_cache.insert(msg);
+                                               log("%s\n", msg.c_str());
+                                       }
+                                       log_debug("%s %s.%s (%s) using %s.\n", mapmsg_prefix.c_str(), log_id(module), log_id(cell), log_id(cell->type), log_id(tpl));
                                        techmap_module_worker(design, module, cell, tpl);
                                        cell = NULL;
                                }
@@ -885,6 +907,7 @@ struct TechmapWorker
                if (log_continue) {
                        log_header(design, "Continuing TECHMAP pass.\n");
                        log_continue = false;
+                       mkdebug.off();
                }
 
                return did_something;
@@ -1085,7 +1108,7 @@ struct TechmapPass : public Pass {
                if (map_files.empty()) {
                        std::istringstream f(stdcells_code);
                        Frontend::frontend_call(map, &f, "<techmap.v>", verilog_frontend);
-               } else
+               } else {
                        for (auto &fn : map_files)
                                if (fn.substr(0, 1) == "%") {
                                        if (!saved_designs.count(fn.substr(1))) {
@@ -1104,6 +1127,9 @@ struct TechmapPass : public Pass {
                                                log_cmd_error("Can't open map file `%s'\n", fn.c_str());
                                        Frontend::frontend_call(map, &f, fn, (fn.size() > 3 && fn.substr(fn.size()-3) == ".il") ? "ilang" : verilog_frontend);
                                }
+               }
+
+               log_header(design, "Continuing TECHMAP pass.\n");
 
                std::map<RTLIL::IdString, std::set<RTLIL::IdString, RTLIL::sort_by_id_str>> celltypeMap;
                for (auto &it : map->modules_) {
@@ -1211,6 +1237,7 @@ struct FlattenPass : public Pass {
                        }
                }
 
+               log_suppressed();
                log("No more expansions possible.\n");
 
                if (top_mod != NULL)