Add log_debug() framework

Signed-off-by: Clifford Wolf <clifford@clifford.at>

11 files changed, 183 insertions, 53 deletions

diff --git a/frontends/aiger/aigerparse.cc b/frontends/aiger/aigerparse.cc
index cf7950c85..2e4774dfd 100644
--- 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 c539ba569..1bc7a5935 100644
--- 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 400a549dd..9a9104e26 100644
--- 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 759939025..e6afae716 100644
--- 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 64956401f..71eb6b187 100644
--- 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 f5305cde9..cf3e46ace 100644
--- 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 c3b13acaf..c38e9df5e 100644
--- 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 a05db2a4f..af6d352af 100644
--- 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 eedf88904..7567d4657 100644
--- 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 375697dc8..dbebf21e0 100644
--- 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 1a4318460..ab0bd3b54 100644
--- 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)