Write execution logs to a named log file (#409)

This patch adds a --log argument to spike. If not given, the behaviour
is unchanged: messages logging execution of instructions and (if
commit logging is enabled) commits go to stderr.

If --log=P is given, Spike now writes these messages to a log file at
the path P. This is nice, because they are no longer tangled up with
other errors and warnings.

The code is mostly plumbing: passing a FILE* object through to the
functions that were using stderr. I've written a simple "log_file_t"
class, which opens a log file if necessary and yields it or stderr.

6 files changed, 144 insertions, 78 deletions

diff --git a/riscv/execute.cc b/riscv/execute.cc
index 2d84242..ec0f479 100644
--- a/riscv/execute.cc
+++ b/riscv/execute.cc
@@ -20,41 +20,47 @@ static void commit_log_stash_privilege(processor_t* p)
   state->last_inst_flen = p->get_flen();
 }
 
-static void commit_log_print_value(int width, const void *data)
+static void commit_log_print_value(FILE *log_file, int width, const void *data)
 {
+  assert(log_file);
   const uint64_t *arr = (const uint64_t *)data;
 
-  fprintf(stderr, "0x");
+  fprintf(log_file, "0x");
   for (int idx = width / 64 - 1; idx >= 0; --idx) {
-    fprintf(stderr, "%016" PRIx64, arr[idx]);
+    fprintf(log_file, "%016" PRIx64, arr[idx]);
   }
 }
 
-static void commit_log_print_value(int width, uint64_t hi, uint64_t lo)
+static void commit_log_print_value(FILE *log_file,
+                                   int width, uint64_t hi, uint64_t lo)
 {
+  assert(log_file);
+
   switch (width) {
     case 8:
-      fprintf(stderr, "0x%01" PRIx8, (uint8_t)lo);
+      fprintf(log_file, "0x%01" PRIx8, (uint8_t)lo);
       break;
     case 16:
-      fprintf(stderr, "0x%04" PRIx16, (uint16_t)lo);
+      fprintf(log_file, "0x%04" PRIx16, (uint16_t)lo);
       break;
     case 32:
-      fprintf(stderr, "0x%08" PRIx32, (uint32_t)lo);
+      fprintf(log_file, "0x%08" PRIx32, (uint32_t)lo);
       break;
     case 64:
-      fprintf(stderr, "0x%016" PRIx64, lo);
+      fprintf(log_file, "0x%016" PRIx64, lo);
       break;
     case 128:
-      fprintf(stderr, "0x%016" PRIx64 "%016" PRIx64, hi, lo);
+      fprintf(log_file, "0x%016" PRIx64 "%016" PRIx64, hi, lo);
       break;
     default:
       abort();
   }
 }
 
-static void commit_log_print_insn(processor_t* p, reg_t pc, insn_t insn)
+static void commit_log_print_insn(processor_t *p, reg_t pc, insn_t insn)
 {
+  FILE *log_file = p->get_log_file();
+
   auto& reg = p->get_state()->log_reg_write;
   auto& load = p->get_state()->log_mem_read;
   auto& store = p->get_state()->log_mem_write;
@@ -62,11 +68,11 @@ static void commit_log_print_insn(processor_t* p, reg_t pc, insn_t insn)
   int xlen = p->get_state()->last_inst_xlen;
   int flen = p->get_state()->last_inst_flen;
 
-  fprintf(stderr, "%1d ", priv);
-  commit_log_print_value(xlen, 0, pc);
-  fprintf(stderr, " (");
-  commit_log_print_value(insn.length() * 8, 0, insn.bits());
-  fprintf(stderr, ")");
+  fprintf(log_file, "%1d ", priv);
+  commit_log_print_value(log_file, xlen, 0, pc);
+  fprintf(log_file, " (");
+  commit_log_print_value(log_file, insn.length() * 8, 0, insn.bits());
+  fprintf(log_file, ")");
   bool show_vec = false;
 
   for (auto item : reg) {
@@ -101,31 +107,31 @@ static void commit_log_print_insn(processor_t* p, reg_t pc, insn_t insn)
     }
 
     if (!show_vec && (is_vreg || is_vec)) {
-        fprintf(stderr, " e%ld m%ld l%ld", p->VU.vsew, p->VU.vlmul, p->VU.vl);
+        fprintf(log_file, " e%ld m%ld l%ld", p->VU.vsew, p->VU.vlmul, p->VU.vl);
         show_vec = true;
     }
 
     if (!is_vec) {
-      fprintf(stderr, " %c%2d ", prefix, rd);
+      fprintf(log_file, " %c%2d ", prefix, rd);
       if (is_vreg)
-        commit_log_print_value(size, &p->VU.elt<uint8_t>(rd, 0));
+        commit_log_print_value(log_file, size, &p->VU.elt<uint8_t>(rd, 0));
       else
-        commit_log_print_value(size, item.second.v[1], item.second.v[0]);
+        commit_log_print_value(log_file, size, item.second.v[1], item.second.v[0]);
     }
   }
 
   for (auto item : load) {
-    fprintf(stderr, " mem ");
-    commit_log_print_value(xlen, 0, std::get<0>(item));
+    fprintf(log_file, " mem ");
+    commit_log_print_value(log_file, xlen, 0, std::get<0>(item));
   }
 
   for (auto item : store) {
-    fprintf(stderr, " mem ");
-    commit_log_print_value(xlen, 0, std::get<0>(item));
-    fprintf(stderr, " ");
-    commit_log_print_value(std::get<2>(item) << 3, 0, std::get<1>(item));
+    fprintf(log_file, " mem ");
+    commit_log_print_value(log_file, xlen, 0, std::get<0>(item));
+    fprintf(log_file, " ");
+    commit_log_print_value(log_file, std::get<2>(item) << 3, 0, std::get<1>(item));
   }
-  fprintf(stderr, "\n");
+  fprintf(log_file, "\n");
 }
 #else
 static void commit_log_reset(processor_t* p) {}
@@ -150,9 +156,13 @@ static reg_t execute_insn(processor_t* p, reg_t pc, insn_fetch_t fetch)
 
   reg_t npc = fetch.func(p, fetch.insn, pc);
   if (npc != PC_SERIALIZE_BEFORE) {
-    if (p->get_log_commits()) {
+
+#ifdef RISCV_ENABLE_COMMITLOG
+    if (p->get_log_commits_enabled()) {
       commit_log_print_insn(p, pc, fetch.insn);
     }
+#endif
+
     p->update_histogram(pc);
   }
   return npc;
diff --git a/riscv/log_file.h b/riscv/log_file.h
new file mode 100644
index 0000000..d039859
--- /dev/null
+++ b/riscv/log_file.h
@@ -0,0 +1,37 @@
+// See LICENSE for license details.
+#ifndef _RISCV_LOGFILE_H
+#define _RISCV_LOGFILE_H
+
+#include <stdio.h>
+#include <memory>
+#include <sstream>
+#include <stdexcept>
+
+// Header-only class wrapping a log file. When constructed with an
+// actual path, it opens the named file for writing. When constructed
+// with the null path, it wraps stderr.
+class log_file_t
+{
+public:
+  log_file_t(const char *path)
+    : wrapped_file (nullptr, &fclose)
+  {
+    if (!path)
+      return;
+
+    wrapped_file.reset(fopen(path, "w"));
+    if (! wrapped_file) {
+      std::ostringstream oss;
+      oss << "Failed to open log file at `" << path << "': "
+          << strerror (errno);
+      throw std::runtime_error(oss.str());
+    }
+  }
+
+  FILE *get() { return wrapped_file ? wrapped_file.get() : stderr; }
+
+private:
+  std::unique_ptr<FILE, decltype(&fclose)> wrapped_file;
+};
+
+#endif
diff --git a/riscv/processor.cc b/riscv/processor.cc
index 7ecdba0..a0ec42a 100644
--- a/riscv/processor.cc
+++ b/riscv/processor.cc
@@ -21,10 +21,11 @@
 #define STATE state
 
 processor_t::processor_t(const char* isa, const char* priv, const char* varch,
-                         simif_t* sim, uint32_t id, bool halt_on_reset)
+                         simif_t* sim, uint32_t id, bool halt_on_reset,
+                         FILE* log_file)
   : debug(false), halt_request(false), sim(sim), ext(NULL), id(id), xlen(0),
   histogram_enabled(false), log_commits_enabled(false),
-  halt_on_reset(halt_on_reset), last_pc(1), executions(1)
+  log_file(log_file), halt_on_reset(halt_on_reset), last_pc(1), executions(1)
 {
   VU.p = this;
   parse_isa_string(isa);
@@ -357,17 +358,12 @@ void processor_t::set_histogram(bool value)
 #endif
 }
 
-void processor_t::set_log_commits(bool value)
+#ifdef RISCV_ENABLE_COMMITLOG
+void processor_t::enable_log_commits()
 {
-  log_commits_enabled = value;
-#ifndef RISCV_ENABLE_COMMITLOG
-  if (value) {
-    fprintf(stderr, "Commit logging support has not been properly enabled;");
-    fprintf(stderr, " please re-build the riscv-isa-sim project using \"configure --enable-commitlog\".\n");
-    abort();
-  }
-#endif
+  log_commits_enabled = true;
 }
+#endif
 
 void processor_t::reset()
 {
@@ -477,11 +473,11 @@ void processor_t::enter_debug_mode(uint8_t cause)
 void processor_t::take_trap(trap_t& t, reg_t epc)
 {
   if (debug) {
-    fprintf(stderr, "core %3d: exception %s, epc 0x%016" PRIx64 "\n",
+    fprintf(log_file, "core %3d: exception %s, epc 0x%016" PRIx64 "\n",
             id, t.name(), epc);
     if (t.has_tval())
-      fprintf(stderr, "core %3d:           tval 0x%016" PRIx64 "\n", id,
-          t.get_tval());
+      fprintf(log_file, "core %3d:           tval 0x%016" PRIx64 "\n",
+              id, t.get_tval());
   }
 
   if (state.debug_mode) {
@@ -542,10 +538,10 @@ void processor_t::disasm(insn_t insn)
   uint64_t bits = insn.bits() & ((1ULL << (8 * insn_length(insn.bits()))) - 1);
   if (last_pc != state.pc || last_bits != bits) {
     if (executions != 1) {
-      fprintf(stderr, "core %3d: Executed %" PRIx64 " times\n", id, executions);
+      fprintf(log_file, "core %3d: Executed %" PRIx64 " times\n", id, executions);
     }
 
-    fprintf(stderr, "core %3d: 0x%016" PRIx64 " (0x%08" PRIx64 ") %s\n",
+    fprintf(log_file, "core %3d: 0x%016" PRIx64 " (0x%08" PRIx64 ") %s\n",
             id, state.pc, bits, disassembler->disassemble(insn).c_str());
     last_pc = state.pc;
     last_bits = bits;
diff --git a/riscv/processor.h b/riscv/processor.h
index 63c885b..fbe27bd 100644
--- a/riscv/processor.h
+++ b/riscv/processor.h
@@ -239,13 +239,16 @@ class processor_t : public abstract_device_t
 {
 public:
   processor_t(const char* isa, const char* priv, const char* varch,
-              simif_t* sim, uint32_t id, bool halt_on_reset=false);
+              simif_t* sim, uint32_t id, bool halt_on_reset,
+              FILE *log_file);
   ~processor_t();
 
   void set_debug(bool value);
   void set_histogram(bool value);
-  void set_log_commits(bool value);
-  bool get_log_commits() { return log_commits_enabled; }
+#ifdef RISCV_ENABLE_COMMITLOG
+  void enable_log_commits();
+  bool get_log_commits_enabled() const { return log_commits_enabled; }
+#endif
   void reset();
   void step(size_t n); // run for n cycles
   void set_csr(int which, reg_t val);
@@ -277,6 +280,8 @@ public:
   void update_histogram(reg_t pc);
   const disassembler_t* get_disassembler() { return disassembler; }
 
+  FILE *get_log_file() { return log_file; }
+
   void register_insn(insn_desc_t);
   void register_extension(extension_t*);
 
@@ -386,6 +391,7 @@ private:
   std::string isa_string;
   bool histogram_enabled;
   bool log_commits_enabled;
+  FILE *log_file;
   bool halt_on_reset;
 
   std::vector<insn_desc_t> instructions;
diff --git a/riscv/sim.cc b/riscv/sim.cc
index dd7b35d..3a0ad73 100644
--- a/riscv/sim.cc
+++ b/riscv/sim.cc
@@ -32,11 +32,13 @@ sim_t::sim_t(const char* isa, const char* priv, const char* varch,
              std::vector<std::pair<reg_t, abstract_device_t*>> plugin_devices,
              const std::vector<std::string>& args,
              std::vector<int> const hartids,
-             const debug_module_config_t &dm_config)
+             const debug_module_config_t &dm_config,
+             const char *log_path)
   : htif_t(args), mems(mems), plugin_devices(plugin_devices),
-    procs(std::max(nprocs, size_t(1))), initrd_start(initrd_start), initrd_end(initrd_end), start_pc(start_pc), current_step(0),
-    current_proc(0), debug(false), histogram_enabled(false),
-    log_commits_enabled(false), dtb_enabled(true),
+    initrd_start(initrd_start), initrd_end(initrd_end), start_pc(start_pc),
+    log_file(log_path),
+    current_step(0), current_proc(0), debug(false), histogram_enabled(false),
+    log(false), dtb_enabled(true),
     remote_bitbang(NULL), debug_module(this, dm_config)
 {
   signal(SIGINT, &handle_signal);
@@ -51,19 +53,18 @@ sim_t::sim_t(const char* isa, const char* priv, const char* varch,
 
   debug_mmu = new mmu_t(this, NULL);
 
-  if (hartids.size() == 0) {
-    for (size_t i = 0; i < procs.size(); i++) {
-      procs[i] = new processor_t(isa, priv, varch, this, i, halted);
-    }
-  }
-  else {
-    if (hartids.size() != procs.size()) {
-      std::cerr << "Number of specified hartids doesn't match number of processors" << strerror(errno) << std::endl;
+  if (! (hartids.empty() || hartids.size() == nprocs)) {
+      std::cerr << "Number of specified hartids ("
+                << hartids.size()
+                << ") doesn't match number of processors ("
+                << nprocs << ").\n";
       exit(1);
-    }
-    for (size_t i = 0; i < procs.size(); i++) {
-      procs[i] = new processor_t(isa, priv, varch, this, hartids[i], halted);
-    }
+  }
+
+  for (size_t i = 0; i < nprocs; i++) {
+    int hart_id = hartids.empty() ? i : hartids[i];
+    procs.push_back(new processor_t (isa, priv, varch, this,
+                                     hart_id, halted, log_file.get()));
   }
 
   clint.reset(new clint_t(procs, CPU_HZ / INSNS_PER_RTC_TICK, real_time_clint));
@@ -133,11 +134,6 @@ void sim_t::set_debug(bool value)
   debug = value;
 }
 
-void sim_t::set_log(bool value)
-{
-  log = value;
-}
-
 void sim_t::set_histogram(bool value)
 {
   histogram_enabled = value;
@@ -146,12 +142,24 @@ void sim_t::set_histogram(bool value)
   }
 }
 
-void sim_t::set_log_commits(bool value)
+void sim_t::configure_log(bool enable_log, bool enable_commitlog)
 {
-  log_commits_enabled = value;
-  for (size_t i = 0; i < procs.size(); i++) {
-    procs[i]->set_log_commits(log_commits_enabled);
+  log = enable_log;
+
+  if (!enable_commitlog)
+    return;
+
+#ifndef RISCV_ENABLE_COMMITLOG
+  fputs("Commit logging support has not been properly enabled; "
+        "please re-build the riscv-isa-sim project using "
+        "\"configure --enable-commitlog\".\n",
+        stderr);
+  abort();
+#else
+  for (processor_t *proc : procs) {
+    proc->enable_log_commits();
   }
+#endif
 }
 
 void sim_t::set_procs_debug(bool value)
diff --git a/riscv/sim.h b/riscv/sim.h
index a9d4923..91aedab 100644
--- a/riscv/sim.h
+++ b/riscv/sim.h
@@ -3,10 +3,12 @@
 #ifndef _RISCV_SIM_H
 #define _RISCV_SIM_H
 
-#include "processor.h"
-#include "devices.h"
 #include "debug_module.h"
+#include "devices.h"
+#include "log_file.h"
+#include "processor.h"
 #include "simif.h"
+
 #include <fesvr/htif.h>
 #include <fesvr/context.h>
 #include <vector>
@@ -27,15 +29,22 @@ public:
         reg_t start_pc, std::vector<std::pair<reg_t, mem_t*>> mems,
         std::vector<std::pair<reg_t, abstract_device_t*>> plugin_devices,
         const std::vector<std::string>& args, const std::vector<int> hartids,
-        const debug_module_config_t &dm_config);
+        const debug_module_config_t &dm_config, const char *log_path);
   ~sim_t();
 
   // run the simulation to completion
   int run();
   void set_debug(bool value);
-  void set_log(bool value);
   void set_histogram(bool value);
-  void set_log_commits(bool value);
+
+  // Configure logging
+  //
+  // If enable_log is true, an instruction trace will be generated. If
+  // enable_commitlog is true, so will the commit results (if this
+  // build was configured without support for commit logging, the
+  // function will print an error message and abort).
+  void configure_log(bool enable_log, bool enable_commitlog);
+
   void set_procs_debug(bool value);
   void set_dtb_enabled(bool value) {
     this->dtb_enabled = value;
@@ -62,6 +71,7 @@ private:
   std::unique_ptr<rom_device_t> boot_rom;
   std::unique_ptr<clint_t> clint;
   bus_t bus;
+  log_file_t log_file;
 
   processor_t* get_core(const std::string& i);
   void step(size_t n); // step through simulation
@@ -71,9 +81,8 @@ private:
   size_t current_step;
   size_t current_proc;
   bool debug;
-  bool log;
   bool histogram_enabled; // provide a histogram of PCs
-  bool log_commits_enabled;
+  bool log;
   bool dtb_enabled;
   remote_bitbang_t* remote_bitbang;