diff options
author | Rupert Swarbrick <rswarbrick@gmail.com> | 2020-03-27 10:25:20 +0000 |
---|---|---|
committer | GitHub <noreply@github.com> | 2020-03-27 03:25:20 -0700 |
commit | bf296ca0643fa445b83d8bd45eefa3fca02d9921 (patch) | |
tree | 69222028c8870f885e7207959cafa8a83e4cbfce /riscv | |
parent | 66b44bfbedda562a32e4a2cd0716afbf731b69cd (diff) | |
download | riscv-isa-sim-bf296ca0643fa445b83d8bd45eefa3fca02d9921.zip riscv-isa-sim-bf296ca0643fa445b83d8bd45eefa3fca02d9921.tar.gz riscv-isa-sim-bf296ca0643fa445b83d8bd45eefa3fca02d9921.tar.bz2 |
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.
Diffstat (limited to 'riscv')
-rw-r--r-- | riscv/execute.cc | 64 | ||||
-rw-r--r-- | riscv/log_file.h | 37 | ||||
-rw-r--r-- | riscv/processor.cc | 28 | ||||
-rw-r--r-- | riscv/processor.h | 12 | ||||
-rw-r--r-- | riscv/sim.cc | 58 | ||||
-rw-r--r-- | riscv/sim.h | 23 |
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; |