added debug logging

added debug pass stats to recc

CMakeLists.txt

@@ -114,7 +114,7 @@ list(APPEND REDREAM_INCLUDE_DIRS deps/xbyak-4.901)
 find_package(ClangFormat)
 
 if(CLANG_FORMAT_FOUND)
-file(GLOB_RECURSE CLANG_FORMAT_ARGS "src/*.cc" "src/*.h" "test/*.cc" "test/*.h")
+file(GLOB_RECURSE CLANG_FORMAT_ARGS "src/*.cc" "src/*.h" "test/*.cc" "test/*.h", "tools/*.cc" "tools/*.h")
 
 add_custom_target(format ${CLANG_FORMAT_EXECUTABLE} -style=Google -i ${CLANG_FORMAT_ARGS})
 endif()
@@ -169,6 +169,7 @@ set(REDREAM_SOURCES
   src/jit/ir/passes/dead_code_elimination_pass.cc
   src/jit/ir/passes/load_store_elimination_pass.cc
   src/jit/ir/passes/pass_runner.cc
+  src/jit/ir/passes/pass_stats.cc
   src/jit/ir/passes/register_allocation_pass.cc
   src/renderer/gl_backend.cc
   src/renderer/gl_shader.cc

src/core/log.cc

@@ -2,6 +2,8 @@
 #include <stdio.h>
 #include "core/log.h"
 
+DEFINE_bool(debug, false, "Enable debug logging");
+
 namespace re {
 
 void Log(LogLevel level, const char *format, ...) {
@@ -25,6 +27,7 @@ void Log(LogLevel level, const char *format, ...) {
 
 #if defined(PLATFORM_LINUX) || defined(PLATFORM_DARWIN)
   switch (level) {
+    case LOG_LEVEL_DEBUG:
     case LOG_LEVEL_INFO:
       printf("%s\n", buffer);
       break;

src/core/log.h

@@ -2,10 +2,14 @@
 #define REDREAM_LOG_H
 
 #include <stdlib.h>
+#include <gflags/gflags.h>
+
+DECLARE_bool(debug);
 
 namespace re {
 
 enum LogLevel {
+  LOG_LEVEL_DEBUG,
   LOG_LEVEL_INFO,
   LOG_LEVEL_WARNING,
   LOG_LEVEL_FATAL,
@@ -21,6 +25,11 @@ enum LogLevel {
 
 void Log(LogLevel level, const char *format, ...);
 
+#define LOG_DEBUG(...)                   \
+  if (FLAGS_debug) {                     \
+    Log(LOG_LEVEL_DEBUG, ##__VA_ARGS__); \
+  }
+
 #define LOG_INFO(...)                   \
   do {                                  \
     Log(LOG_LEVEL_INFO, ##__VA_ARGS__); \

src/hw/machine.cc

@@ -8,7 +8,7 @@ using namespace re;
 using namespace re::hw;
 using namespace re::ui;
 
-DEFINE_bool(debug, false, "Run debug server");
+DEFINE_bool(gdb, false, "Run gdb debug server");
 
 DebugInterface::DebugInterface(Device *device) { device->debug_ = this; }
 
@@ -26,7 +26,7 @@ Device::Device(Machine &machine)
 bool Device::Init() { return true; }
 
 Machine::Machine() : suspended_(false) {
-  debugger = FLAGS_debug ? new Debugger(*this) : nullptr;
+  debugger = FLAGS_gdb ? new Debugger(*this) : nullptr;
   memory = new Memory(*this);
   scheduler = new Scheduler(*this);
 }

src/hw/sh4/sh4_code_cache.cc

@@ -36,7 +36,8 @@ SH4CodeCache::SH4CodeCache(const MemoryInterface &memif,
   // setup optimization passes
   pass_runner_.AddPass(std::unique_ptr<Pass>(new LoadStoreEliminationPass()));
   // pass_runner_.AddPass(std::unique_ptr<Pass>(new ConstantPropagationPass()));
-  // pass_runner_.AddPass(std::unique_ptr<Pass>(new ConversionEliminationPass()));
+  // pass_runner_.AddPass(std::unique_ptr<Pass>(new
+  // ConversionEliminationPass()));
   pass_runner_.AddPass(std::unique_ptr<Pass>(new DeadCodeEliminationPass()));
   pass_runner_.AddPass(
       std::unique_ptr<Pass>(new RegisterAllocationPass(*backend_)));
@@ -85,7 +86,7 @@ SH4BlockEntry *SH4CodeCache::CompileBlock(uint32_t guest_addr,
   // compile the SH4 into IR
   IRBuilder &builder = frontend_->BuildBlock(guest_addr, host_addr, flags);
 
-  pass_runner_.Run(builder, false);
+  pass_runner_.Run(builder);
 
   // assemble the IR into native code
   BlockPointer run = backend_->AssembleBlock(builder, block->flags);

src/jit/ir/passes/constant_propagation_pass.cc

@@ -89,7 +89,7 @@ static int GetConstantSig(Instr *instr) {
   return cnst_sig;
 }
 
-void ConstantPropagationPass::Run(IRBuilder &builder, bool debug) {
+void ConstantPropagationPass::Run(IRBuilder &builder) {
   auto it = builder.instrs().begin();
   auto end = builder.instrs().end();
 

src/jit/ir/passes/constant_propagation_pass.h

@@ -12,7 +12,7 @@ class ConstantPropagationPass : public Pass {
  public:
   const char *name() { return "constprop"; }
 
-  void Run(IRBuilder &builder, bool debug);
+  void Run(IRBuilder &builder);
 };
 }
 }

src/jit/ir/passes/dead_code_elimination_pass.cc

@@ -4,7 +4,9 @@ using namespace re::jit::backend;
 using namespace re::jit::ir;
 using namespace re::jit::ir::passes;
 
-void DeadCodeEliminationPass::Run(IRBuilder &builder, bool debug) {
+DEFINE_STAT(num_dead_removed, "Number of dead instructions eliminated");
+
+void DeadCodeEliminationPass::Run(IRBuilder &builder) {
   // iterate in reverse in order to remove groups of dead instructions that
   // only use eachother
   auto it = builder.instrs().rbegin();
@@ -19,6 +21,8 @@ void DeadCodeEliminationPass::Run(IRBuilder &builder, bool debug) {
 
     if (!instr->uses().head()) {
       builder.RemoveInstr(instr);
+
+      num_dead_removed++;
     }
   }
 }

src/jit/ir/passes/dead_code_elimination_pass.h

@@ -13,7 +13,7 @@ class DeadCodeEliminationPass : public Pass {
  public:
   const char *name() { return "dce"; }
 
-  void Run(IRBuilder &builder, bool debug);
+  void Run(IRBuilder &builder);
 };
 }
 }

src/jit/ir/passes/load_store_elimination_pass.cc

@@ -3,10 +3,13 @@
 using namespace re::jit::ir;
 using namespace re::jit::ir::passes;
 
+DEFINE_STAT(num_loads_removed, "Number of loads eliminated");
+DEFINE_STAT(num_stores_removed, "Number of stores eliminated");
+
 LoadStoreEliminationPass::LoadStoreEliminationPass()
     : available_(nullptr), num_available_(0) {}
 
-void LoadStoreEliminationPass::Run(IRBuilder &builder, bool debug) {
+void LoadStoreEliminationPass::Run(IRBuilder &builder) {
   Reset();
 
   // eliminate redundant loads
@@ -28,6 +31,9 @@ void LoadStoreEliminationPass::Run(IRBuilder &builder, bool debug) {
         if (available && available->type() == instr->type()) {
           instr->ReplaceRefsWith(available);
           builder.RemoveInstr(instr);
+
+          num_loads_removed++;
+
           continue;
         }
 
@@ -67,6 +73,9 @@ void LoadStoreEliminationPass::Run(IRBuilder &builder, bool debug) {
 
         if (available_size >= store_size) {
           builder.RemoveInstr(instr);
+
+          num_stores_removed++;
+
           continue;
         }
 

src/jit/ir/passes/load_store_elimination_pass.h

@@ -19,7 +19,7 @@ class LoadStoreEliminationPass : public Pass {
 
   const char *name() { return "lse"; }
 
-  void Run(IRBuilder &builder, bool debug);
+  void Run(IRBuilder &builder);
 
  private:
   void Reset();

src/jit/ir/passes/pass_runner.cc

@@ -11,24 +11,12 @@ void PassRunner::AddPass(std::unique_ptr<Pass> pass) {
   passes_.push_back(std::move(pass));
 }
 
-void PassRunner::Run(IRBuilder &builder, bool debug) {
+void PassRunner::Run(IRBuilder &builder) {
   PROFILER_RUNTIME("PassRunner::Run");
 
-  if (debug) {
-    LOG_INFO("original:");
-    builder.Dump();
-    LOG_INFO("");
-  }
-
   for (auto &pass : passes_) {
     PROFILER_RUNTIME(pass->name());
 
-    pass->Run(builder, debug);
-
-    if (debug) {
-      LOG_INFO("%s:", pass->name());
-      builder.Dump();
-      LOG_INFO("");
-    }
+    pass->Run(builder);
   }
 }

src/jit/ir/passes/pass_runner.h

@@ -3,6 +3,7 @@
 
 #include <memory>
 #include <vector>
+#include "jit/ir/passes/pass_stats.h"
 #include "jit/ir/ir_builder.h"
 
 namespace re {
@@ -16,7 +17,7 @@ class Pass {
 
   virtual const char *name() = 0;
 
-  virtual void Run(IRBuilder &builder, bool debug) = 0;
+  virtual void Run(IRBuilder &builder) = 0;
 };
 
 class PassRunner {
@@ -24,7 +25,7 @@ class PassRunner {
   PassRunner();
 
   void AddPass(std::unique_ptr<Pass> pass);
-  void Run(IRBuilder &builder, bool debug);
+  void Run(IRBuilder &builder);
 
  private:
   std::vector<std::unique_ptr<Pass>> passes_;

src/jit/ir/passes/pass_stats.cc

@@ -0,0 +1,57 @@
+#include <vector>
+#include "core/assert.h"
+#include "jit/ir/passes/pass_stats.h"
+
+using namespace re::jit::ir;
+using namespace re::jit::ir::passes;
+
+namespace re {
+namespace jit {
+namespace ir {
+namespace passes {
+
+static std::vector<const Stat *> *s_stats = nullptr;
+
+static void RegisterStat(const Stat *stat) {
+  // lazily initialize to avoid static initialization ordering problems
+  if (!s_stats) {
+    s_stats = new std::vector<const Stat *>();
+  }
+
+  s_stats->push_back(stat);
+}
+
+static void UnregisterStat(const Stat *stat) {
+  auto it = std::find(s_stats->begin(), s_stats->end(), stat);
+  CHECK_NE(it, s_stats->end());
+  s_stats->erase(it);
+
+  if (!s_stats->size()) {
+    delete s_stats;
+    s_stats = nullptr;
+  }
+}
+
+Stat::Stat(const char *desc) : desc(desc), n(0) { RegisterStat(this); }
+
+Stat::~Stat() { UnregisterStat(this); }
+
+void DumpStats() {
+  LOG_INFO("===-----------------------------------------------------===");
+  LOG_INFO("Pass stats");
+  LOG_INFO("===-----------------------------------------------------===");
+
+  int w = 0;
+  for (auto stat : *s_stats) {
+    int l = static_cast<int>(strlen(stat->desc));
+    w = std::max(l, w);
+  }
+
+  for (auto stat : *s_stats) {
+    LOG_INFO("%-*s  %d", w, stat->desc, stat->n);
+  }
+}
+}
+}
+}
+}

src/jit/ir/passes/pass_stats.h

@@ -0,0 +1,45 @@
+#ifndef PASS_STATS_H
+#define PASS_STATS_H
+
+namespace re {
+namespace jit {
+namespace ir {
+namespace passes {
+
+#define DEFINE_STAT(name, desc) static Stat name(desc);
+
+struct Stat {
+  const char *desc;
+  int n;
+
+  Stat(const char *desc);
+  ~Stat();
+
+  const Stat &operator++(int v) {
+    n++;
+    return *this;
+  }
+
+  const Stat &operator+=(int v) {
+    n += v;
+    return *this;
+  }
+
+  const Stat &operator--() {
+    n--;
+    return *this;
+  }
+
+  const Stat &operator-=(int v) {
+    n -= v;
+    return *this;
+  }
+};
+
+void DumpStats();
+}
+}
+}
+}
+
+#endif

src/jit/ir/passes/register_allocation_pass.cc

@@ -91,7 +91,7 @@ RegisterAllocationPass::RegisterAllocationPass(const Backend &backend)
 
 RegisterAllocationPass::~RegisterAllocationPass() { delete[] intervals_; }
 
-void RegisterAllocationPass::Run(IRBuilder &builder, bool debug) {
+void RegisterAllocationPass::Run(IRBuilder &builder) {
   Reset();
 
   AssignOrdinals(builder);

src/jit/ir/passes/register_allocation_pass.h

@@ -51,7 +51,7 @@ class RegisterAllocationPass : public Pass {
 
   const char *name() { return "ra"; }
 
-  void Run(IRBuilder &builder, bool debug);
+  void Run(IRBuilder &builder);
 
  private:
   const backend::Register *registers_;

test/test_dead_code_elimination_pass.cc

@@ -66,7 +66,7 @@ TEST(DeadCodeEliminationPassTest, Sanity) {
   reader.Parse(input_stream, builder);
 
   DeadCodeEliminationPass pass;
-  pass.Run(builder, false);
+  pass.Run(builder);
 
   IRWriter writer;
   std::stringstream output_stream;

test/test_load_store_elimination_pass.cc

@@ -67,7 +67,7 @@ TEST(LoadStoreEliminationPassTest, Aliasing) {
   reader.Parse(input_stream, builder);
 
   LoadStoreEliminationPass pass;
-  pass.Run(builder, false);
+  pass.Run(builder);
 
   IRWriter writer;
   std::stringstream output_stream;

tools/recc.cc

@@ -1,4 +1,5 @@
 #include <fstream>
+#include <iostream>
 #include <memory>
 #include <sstream>
 #include <gflags/gflags.h>
@@ -14,7 +15,10 @@ using namespace re::jit::ir;
 using namespace re::jit::ir::passes;
 
 DEFINE_string(pass, "lse,dce", "Comma-separated list of passes to run");
-DEFINE_bool(debug, false, "Enable debug spew for passes");
+DEFINE_bool(print_after_all, true, "Print IR after each pass");
+DEFINE_bool(stats, true, "Display pass stats");
+
+DEFINE_STAT(num_instrs_removed, "Number of instructions removed");
 
 static std::vector<std::string> split(const std::string &s, char delim) {
   std::stringstream ss(s);
@@ -37,7 +41,9 @@ static int get_num_instrs(IRBuilder &builder) {
   return n;
 }
 
-int main(int argc, const char **argv) {
+int main(int argc, char **argv) {
+  google::ParseCommandLineFlags(&argc, &argv, true);
+
   const char *file = argv[1];
 
   Arena arena(4096);
@@ -48,13 +54,14 @@ int main(int argc, const char **argv) {
   std::ifstream input_stream(file);
   CHECK(reader.Parse(input_stream, builder));
 
+  // track total # of instructions removed
+  int num_instrs_before = get_num_instrs(builder);
+
   // run optimization passes
   std::vector<std::string> passes = split(FLAGS_pass, ',');
   for (auto name : passes) {
     std::unique_ptr<Pass> pass;
 
-    int num_instrs_before = get_num_instrs(builder);
-
     if (name == "lse") {
       pass = std::unique_ptr<Pass>(new LoadStoreEliminationPass());
     } else if (name == "dce") {
@@ -62,26 +69,31 @@ int main(int argc, const char **argv) {
     } else {
       LOG_WARNING("Unknown pass %s", name.c_str());
     }
-    pass->Run(builder, FLAGS_debug);
+    pass->Run(builder);
 
-    int num_instrs_after = get_num_instrs(builder);
-
-    // print out the resulting ir
-    LOG_INFO("%s:", pass->name());
-    builder.Dump();
-
-    // print out stats about the optimization pass
-    if (num_instrs_after <= num_instrs_before) {
-      int delta = num_instrs_before - num_instrs_after;
-      LOG_INFO(ANSI_COLOR_GREEN "%d (%.2f%%) instructions removed" ANSI_COLOR_RESET,
-        delta, (delta / static_cast<float>(num_instrs_before)) * 100.0f);
-    } else {
-      int delta = num_instrs_after - num_instrs_before;
-      LOG_INFO(ANSI_COLOR_RED "%d (%.2f%%) instructions added" ANSI_COLOR_RESET,
-        delta, (delta / static_cast<float>(num_instrs_before)) * 100.0f);
+    // print IR after each pass if requested
+    if (FLAGS_print_after_all) {
+      LOG_INFO("===-----------------------------------------------------===");
+      LOG_INFO("IR after %s", pass->name());
+      LOG_INFO("===-----------------------------------------------------===");
+      builder.Dump();
     }
-    LOG_INFO("");
   }
 
+  // print out the final IR
+  if (!FLAGS_print_after_all) {
+    builder.Dump();
+  }
+
+  int num_instrs_after = get_num_instrs(builder);
+  num_instrs_removed += num_instrs_before - num_instrs_after;
+
+  // print stats if requested
+  if (FLAGS_stats) {
+    DumpStats();
+  }
+
+  google::ShutDownCommandLineFlags();
+
   return 0;
 }