Browse Source

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.
pull/436/head
Rupert Swarbrick 6 years ago
committed by GitHub
parent
commit
bf296ca064
No known key found for this signature in database GPG Key ID: 4AEE18F83AFDEB23
  1. 62
      riscv/execute.cc
  2. 37
      riscv/log_file.h
  3. 26
      riscv/processor.cc
  4. 12
      riscv/processor.h
  5. 58
      riscv/sim.cc
  6. 23
      riscv/sim.h
  7. 2
      spike_main/spike-log-parser.cc
  8. 11
      spike_main/spike.cc

62
riscv/execute.cc

@ -20,33 +20,37 @@ 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();
@ -55,6 +59,8 @@ static void commit_log_print_value(int width, uint64_t hi, uint64_t lo)
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;

37
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

26
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();
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;

12
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;

58
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)

23
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;

2
spike_main/spike-log-parser.cc

@ -27,7 +27,7 @@ int main(int argc, char** argv)
parser.option(0, "isa", 1, [&](const char* s){isa = s;});
parser.parse(argv);
processor_t p(isa, DEFAULT_PRIV, DEFAULT_VARCH, 0, 0);
processor_t p(isa, DEFAULT_PRIV, DEFAULT_VARCH, 0, 0, false, nullptr);
if (extension) {
p.register_extension(extension());
}

11
spike_main/spike.cc

@ -144,6 +144,7 @@ int main(int argc, char** argv)
std::unique_ptr<cache_sim_t> l2;
bool log_cache = false;
bool log_commits = false;
const char *log_path = nullptr;
std::function<extension_t*()> extension;
const char* initrd = NULL;
const char* isa = DEFAULT_ISA;
@ -267,7 +268,10 @@ int main(int argc, char** argv)
[&](const char* s){dm_config.support_abstract_csr_access = false;});
parser.option(0, "dm-no-halt-groups", 0,
[&](const char* s){dm_config.support_haltgroups = false;});
parser.option(0, "log-commits", 0, [&](const char* s){log_commits = true;});
parser.option(0, "log-commits", 0,
[&](const char* s){log_commits = true;});
parser.option(0, "log", 1,
[&](const char* s){log_path = s;});
auto argv1 = parser.parse(argv);
std::vector<std::string> htif_args(argv1, (const char*const*)argv + argc);
@ -291,7 +295,7 @@ int main(int argc, char** argv)
sim_t s(isa, priv, varch, nprocs, halted, real_time_clint,
initrd_start, initrd_end, start_pc, mems, plugin_devices, htif_args,
std::move(hartids), dm_config);
std::move(hartids), dm_config, log_path);
std::unique_ptr<remote_bitbang_t> remote_bitbang((remote_bitbang_t *) NULL);
std::unique_ptr<jtag_dtm_t> jtag_dtm(
new jtag_dtm_t(&s.debug_module, dmi_rti));
@ -318,9 +322,8 @@ int main(int argc, char** argv)
}
s.set_debug(debug);
s.set_log(log);
s.configure_log(log, log_commits);
s.set_histogram(histogram);
s.set_log_commits(log_commits);
auto return_code = s.run();

Loading…
Cancel
Save