[cosim] support print call frame

ipemu/csrc/elf.cc

@@ -2,40 +2,126 @@
 
 #include <fmt/core.h>
 #include <linux/elf.h>
+#include <endian.h>
 
-simple_sim::load_elf_result_t simple_sim::load_elf(const std::string &fname) {
+// convert little-endian integral type to host-endian
+template<typename T>
+T from_le(T value) {
+  static_assert(std::is_integral<T>::value, "T must be an integral type");
+
+  if constexpr (sizeof(T) == 1) {
+    return value;
+  } else if constexpr (sizeof(T) == 2) {
+    return le16toh(value);
+  } else if constexpr (sizeof(T) == 4) {
+    return le32toh(value);
+  } else if constexpr (sizeof(T) == 8) {
+    return le64toh(value);
+  } else {
+    static_assert(sizeof(T) <= 8, "Unsupported type size");
+  }
+}
+
+void copy_from_fs(std::ifstream &ifs, std::streamoff offset, std::streamoff size, void *dst) {
+  ifs.clear();
+  ifs.seekg(offset);
+  ifs.read(reinterpret_cast<char *>(dst), size);
+}
+
+template<typename T>
+T read_from_fs(std::ifstream &ifs, std::streamoff offset) {
+  T t{};
+  copy_from_fs(ifs, offset, sizeof(T), &t);
+  return t;
+}
+
+simple_sim::load_elf_result_t simple_sim::load_elf32_little_endian(const std::string &fname) {
   try {
     std::ifstream fs(fname, std::ios::binary);
     fs.exceptions(std::ios::failbit);
 
-    Elf32_Ehdr ehdr;
-    fs.read(reinterpret_cast<char *>(&ehdr), sizeof(ehdr));
-    CHECK(ehdr.e_machine == EM_RISCV && ehdr.e_type == ET_EXEC &&
-              ehdr.e_ident[EI_CLASS] == ELFCLASS32,
-          "ehdr check failed when loading elf");
-    CHECK_EQ(ehdr.e_phentsize, sizeof(elf32_phdr),
-             "ehdr.e_phentsize does not equal to elf32_phdr");
-
-    for (size_t i = 0; i < ehdr.e_phnum; i++) {
-      auto phdr_offset = ehdr.e_phoff + i * ehdr.e_phentsize;
-      Elf32_Phdr phdr;
-      fs.seekg((long)phdr_offset)
-          .read(reinterpret_cast<char *>(&phdr), sizeof(phdr));
-      if (phdr.p_type == PT_LOAD) {
-        CHECK(phdr.p_paddr + phdr.p_filesz < mem_size,
+    auto ehdr = read_from_fs<Elf32_Ehdr>(fs, 0);
+    CHECK(std::memcmp(ehdr.e_ident, ELFMAG, SELFMAG) == 0, "elf magic not match");
+    CHECK(ehdr.e_machine == EM_RISCV, "elf not in RISCV");
+    CHECK(ehdr.e_type == ET_EXEC, "elf not executable");
+    CHECK(ehdr.e_ident[EI_DATA] == ELFDATA2LSB, "elf not little endian");
+    CHECK(ehdr.e_ident[EI_CLASS] == ELFCLASS32, "elf not in 32bit");
+
+    for (size_t i = 0; i < from_le(ehdr.e_phnum); i++) {
+      auto phdr_offset = from_le(ehdr.e_phoff) + i * from_le(ehdr.e_phentsize);
+      auto phdr = read_from_fs<Elf32_Phdr>(fs, (std::streamoff) phdr_offset);
+      if (from_le(phdr.p_type) == PT_LOAD) {
+        auto paddr = from_le(phdr.p_paddr);
+        auto filesz = from_le(phdr.p_filesz);
+
+        CHECK(paddr + filesz < mem_size,
               "phdr p_paddr + p_filesz check failed");
-        fs.seekg((long)phdr.p_offset)
-            .read(reinterpret_cast<char *>(&mem[phdr.p_paddr]), phdr.p_filesz);
-        Log("LoadElfResult")
-            .with("segment", i)
-            .with("phdr_offset", fmt::format("{:08X}", phdr.p_offset))
-            .with("paddr_range", fmt::format("{:08X}-{:08X}", phdr.p_paddr,
-                                             phdr.p_paddr + phdr.p_memsz))
-            .trace();
+        fs.clear();
+        fs.seekg(from_le(phdr.p_offset))
+          .read(reinterpret_cast<char *>(&mem[paddr]), filesz);
+        Log("LoadElf")
+          .with("segment", i)
+          .with("phdr_offset", fmt::format("{:08X}", phdr.p_offset))
+          .with("paddr_range", fmt::format("{:08X}-{:08X}", phdr.p_paddr,
+                                           phdr.p_paddr + phdr.p_memsz))
+          .warn();
       }
     }
+
+    // read section string section
+    auto shoff = from_le(ehdr.e_shoff);
+    auto shentsize = from_le(ehdr.e_shentsize);
+    auto shstrndx = from_le(ehdr.e_shstrndx);
+    auto section_string_shdr_offset = shoff + shstrndx * shentsize;
+    auto section_string_shdr = read_from_fs<Elf32_Shdr>(fs, section_string_shdr_offset);
+    std::vector<char> section_string_table(from_le(section_string_shdr.sh_size));
+    copy_from_fs(fs,
+                 from_le(section_string_shdr.sh_offset),
+                 from_le(section_string_shdr.sh_size),
+                 section_string_table.data());
+
+    // iterate over section headers to find the symbol string table
+    std::vector<char> string_table;
+    for (int i = 0; i < from_le(ehdr.e_shnum); ++i) {
+      auto shdr = read_from_fs<Elf32_Shdr>(fs, shoff + i * shentsize);
+      if (from_le(shdr.sh_type) == SHT_STRTAB &&
+          std::string(&section_string_table[from_le(shdr.sh_name)]) == ".strtab") {
+        Log("size").with("size", shdr.sh_size).warn();
+        string_table.resize(from_le(shdr.sh_size));
+        copy_from_fs(fs, from_le(shdr.sh_offset), from_le(shdr.sh_size), string_table.data());
+      }
+    }
+
+    if (string_table.empty()) {
+      Log("LoadElf").warn("failed to find .strtab");
+    } else {
+      // iterate over section headers to find the symbol table
+      for (int i = 0; i < from_le(ehdr.e_shnum); ++i) {
+        auto shdr = read_from_fs<Elf32_Shdr>(fs, shoff + i * shentsize);
+        if (from_le(shdr.sh_type) == SHT_SYMTAB && std::string(&section_string_table[shdr.sh_name]) == ".symtab") {
+          auto entsize = from_le(shdr.sh_entsize);
+          unsigned int num_sym = from_le(shdr.sh_size) / entsize;
+          for (int j = 0; j < num_sym; ++j) {
+            auto offset = from_le(shdr.sh_offset) + j * entsize;
+            auto sym = read_from_fs<Elf32_Sym>(fs, (std::streamoff) offset);
+
+            if (ELF32_ST_TYPE(from_le(sym.st_info)) == STT_FUNC) { // Only considering function symbols
+              // read the name from the string table
+              std::string name(&string_table.at(from_le(sym.st_name)));
+              function_symtab[from_le(sym.st_value)] = {.name = name, .info = from_le(sym.st_info)}; // Add to map
+            }
+          }
+          break;
+        }
+      }
+    }
+
     return {.entry_addr = ehdr.e_entry};
-  } catch (std::ios_base::failure &) {
-    throw std::system_error{errno, std::generic_category(), fname};
+  } catch (std::ios_base::failure &f) {
+    Log("LoadElf")
+      .with("errno", errno)
+      .with("fname", fname)
+      .with("reason", f.what())
+      .fatal();
   }
 }

ipemu/csrc/simple_sim.h

@@ -15,6 +15,12 @@ class simple_sim : public simif_t {
   uartlite uart;
   reg_t uart_addr = 0x10000000;
 
+  struct function_sym {
+    std::string name;
+    uint8_t info;
+  };
+  std::map<uint32_t, function_sym> function_symtab;
+
 public:
   explicit simple_sim(size_t mem_size) : mem_size(mem_size) {
     mem = new char[mem_size];
@@ -25,7 +31,8 @@ class simple_sim : public simif_t {
   struct load_elf_result_t {
     uint32_t entry_addr;
   };
-  load_elf_result_t load_elf(const std::string &fname);
+
+  load_elf_result_t load_elf32_little_endian(const std::string &fname);
 
   // should return NULL for MMIO addresses
   char *addr_to_mem(reg_t addr) override {
@@ -71,5 +78,12 @@ class simple_sim : public simif_t {
     // maybe nothing to do
   }
 
-  const char *get_symbol(uint64_t addr) override { FATAL("Unimplemented"); }
+  const char *get_symbol(uint64_t addr) override {
+    auto find = this->function_symtab.find(addr);
+    if (find != this->function_symtab.end()) {
+      return find->second.name.c_str();
+    } else {
+      return nullptr;
+    }
+  }
 };

ipemu/csrc/spdlog_ext.cc

@@ -60,6 +60,7 @@ ConsoleSink::ConsoleSink() {
   whitelist = get_set_from_env("EMULATOR_LOG_WHITELIST", ',');
   whitelist.insert("DPIInitCosim");
   whitelist.insert("SpikeStep");
+  whitelist.insert("FunctionCall");
   whitelist.insert("SimulationExit");
   whitelist.insert("DPIPeekIssue");
   whitelist.insert("DPIPokeInst");
@@ -75,44 +76,56 @@ inline bool ConsoleSink::is_module_enabled(const std::string &module) {
 void ConsoleSink::sink_it_(const spdlog::details::log_msg &msg) {
   json payload = json::parse(msg.payload);
 
+  if (msg.level < this->level()) {
+    return;
+  }
+
   // filter message matching the current level
   if (msg.level == this->level()) {
     if (!is_module_enabled(payload["_module"])) return;
   }
 
   fmt::text_style level_color;
   switch (msg.level) {
-  case spdlog::level::debug:
-  case spdlog::level::trace:
-    level_color = fmt::fg(fmt::color::gray);
-    break;
-  case spdlog::level::info:
-    level_color = fmt::fg(fmt::color::white);
-    break;
-  case spdlog::level::warn:
-    level_color = fmt::fg(fmt::color::yellow);
-    break;
-  case spdlog::level::err:
-    level_color = fmt::fg(fmt::color::red);
+    case spdlog::level::debug:
+    case spdlog::level::trace:
+      level_color = fmt::fg(fmt::color::gray);
+      break;
+    case spdlog::level::info:
+      level_color = fmt::fg(fmt::color::white);
+      break;
+    case spdlog::level::warn:
+      level_color = fmt::fg(fmt::color::yellow);
+      break;
+    case spdlog::level::err:
+      level_color = fmt::fg(fmt::color::red);
+      break;
+    case spdlog::level::critical:
+      level_color = fmt::bg(fmt::color::red) | fmt::fg(fmt::color::white);
+      break;
+    default:
+      level_color = fmt::fg(fmt::color::white);
       break;
-  case spdlog::level::critical:
-    level_color = fmt::bg(fmt::color::red) | fmt::fg(fmt::color::white);
-    break;
-  default:
-    level_color = fmt::fg(fmt::color::white);
-    break;
   }
 
   std::cerr << fmt::format("{} {}",
                            fmt::styled(payload["_cycle"].get<int64_t>(), level_color),
                            fmt::styled(payload["_module"].get<std::string>(), fmt::fg(fmt::color::violet))
-                           );
+  );
   if (payload.contains("_msg")) {
     std::cerr << fmt::format(" {}", fmt::styled(payload["_msg"].get<std::string>(), fmt::fg(fmt::color::green)));
   }
   if (payload.contains("_with")) {
     std::cerr << fmt::format(" {}", fmt::styled(payload["_with"].dump(), fmt::fg(fmt::color::gray)));
   }
+  if (msg.level > spdlog::level::err) {
+    std::cerr << "\n";
+    const auto frames = vbridge_impl_instance.frames;
+    for (auto frame = frames.rbegin(); frame != frames.rend(); frame++) {
+      std::cerr << fmt::format(fmt::fg(fmt::color::gray), "  call by {}(...) at {:08X}\n",
+                               frame->func_name, frame->func_addr);
+    }
+  }
   std::cerr << "\n";
 }
 
@@ -160,7 +173,7 @@ JsonLogger::JsonLogger(bool no_logging, bool no_file_logging, bool no_console_lo
   }
 }
 
-JsonLogger::JsonLogger(): do_logging(false) { }
+JsonLogger::JsonLogger() : do_logging(false) {}
 
 // We can only implement a class method with template inside the class
 // declaration

ipemu/csrc/vbridge_impl.cc

@@ -40,7 +40,7 @@ void VBridgeImpl::dpiInitCosim() {
   proc.get_state()->sstatus->write(proc.get_state()->sstatus->read() |
                                    SSTATUS_VS | SSTATUS_FS);
 
-  auto load_result = sim.load_elf(bin);
+  auto load_result = sim.load_elf32_little_endian(bin);
 
   proc.get_state()->pc = load_result.entry_addr;
 
@@ -369,6 +369,7 @@ std::optional<SpikeEvent> VBridgeImpl::spike_step() {
 
   clear_state(proc);
 
+  reg_t old_pc = state->pc;
   reg_t new_pc;
   if (event) {
     auto &se = event.value();
@@ -386,13 +387,39 @@ std::optional<SpikeEvent> VBridgeImpl::spike_step() {
     new_pc = fetch.func(&proc, fetch.insn, state->pc);
     se.log_arch_changes();
   } else {
+    auto disasm = proc.get_disassembler()->disassemble(fetch.insn);
     Log("SpikeStep")
         .with("pc", fmt::format("{:08X}", state->pc))
         .with("bits", fmt::format("{:08X}", fetch.insn.bits()))
-        .with("disasm", proc.get_disassembler()->disassemble(fetch.insn))
+        .with("disasm", disasm)
         .with("spike_cycles", spike_cycles)
         .info("spike run scalar insn");
     new_pc = fetch.func(&proc, fetch.insn, state->pc);
+
+    if (disasm == "ret" && new_pc == frames.back().return_addr) {
+      Log("FunctionCall")
+        .with("old_pc", fmt::format("{:08X}", old_pc))
+        .with("new_pc", fmt::format("{:08X}", new_pc))
+        .with("spike_cycles", spike_cycles)
+        .with("depth", frames.size())
+        .info("return");
+      frames.pop_back();
+    }
+  }
+
+  if (new_pc - state->pc != 2 && new_pc - state->pc != 4) {
+    auto sym_find = sim.get_symbol(new_pc);
+    if (sym_find != nullptr) {
+      Log("FunctionCall")
+        .with("func_name", sym_find)
+        .with("old_pc", fmt::format("{:08X}", old_pc))
+        .with("new_pc", fmt::format("{:08X}", new_pc))
+        .with("spike_cycles", spike_cycles)
+        .with("depth", frames.size())
+        .info("call");
+      reg_t return_addr = state->XPR[1];
+      frames.emplace_back(CallFrame{sym_find, new_pc, return_addr, spike_cycles});
+    }
   }
 
   // Bypass CSR insns commitlog stuff.

ipemu/csrc/vbridge_impl.h

@@ -265,6 +265,15 @@ class VBridgeImpl {
 
   int64_t spike_cycles = 0;
 
+  struct CallFrame {
+    std::string func_name;
+    reg_t func_addr;
+    reg_t return_addr;
+    int64_t spike_cycle;
+  };
+  std::vector<CallFrame> frames;
+  friend class ConsoleSink;
+
   std::optional<SpikeEvent> create_spike_event(insn_fetch_t fetch);
 
   std::optional<SpikeEvent> spike_step();