From 1f6bf0b79682d88dc3e95c24c9567a584d6fd9dd Mon Sep 17 00:00:00 2001 From: Avimitin Date: Thu, 26 Oct 2023 18:10:56 +0800 Subject: [PATCH 1/2] [emulator] improve emulator logging performance - allow disable logging functionality - display cycle data for all log entry - use global logger to avoid construct/deconstruct thousands of logger instance Signed-off-by: Avimitin --- emulator/src/spdlog-ext.cc | 135 ++----------------- emulator/src/spdlog-ext.h | 246 +++++++++++++++++++++++++++-------- emulator/src/vbridge_impl.cc | 65 ++++----- 3 files changed, 225 insertions(+), 221 deletions(-) diff --git a/emulator/src/spdlog-ext.cc b/emulator/src/spdlog-ext.cc index 205c92bb5..ef7082513 100644 --- a/emulator/src/spdlog-ext.cc +++ b/emulator/src/spdlog-ext.cc @@ -8,106 +8,8 @@ #include #include -#include -#include -#include -#include -#include - #include "spdlog-ext.h" - -/** - * Get environment variable by the given `env` key or fallback to a default - * value. - */ -std::string getenv_or(const char *env, std::string fallback) { - char *env_var = std::getenv(env); - if (env_var && strlen(env_var) > 0) { - return std::string{env_var}; - } - - return fallback; -} - -/** - * Get environment variable and split them into std::vector by the given - * `delimiter` - */ -std::set get_set_from_env(const char *env, const char delimiter) { - std::set set; - - auto raw = getenv_or(env, ""); - if (raw.empty()) { - return set; - } - - std::stringstream ss(raw); - std::string token; - // Use `delimiter` instead of '\n' to split element in string. - while (std::getline(ss, token, delimiter)) { - set.insert(token); - } - - return set; -} - -/** - * Filter logging message by module type. Filter should be set by environment - * `EMULATOR_BLACKLIST_MODULE` and `EMULATOR_WHITELIST_MODULE`. Module should be - * separate by column `,`. When you set both env, only blacklist will have - * effect. - */ -class ConsoleSink : public spdlog::sinks::base_sink { -private: - std::set blacklist; - std::set whitelist; - - bool is_expected_module(std::string &module) { - if (!blacklist.empty() && blacklist.find(module) != blacklist.end()) { - return false; - } - if (!whitelist.empty() && whitelist.find(module) == whitelist.end()) { - return false; - } - - return true; - } - -public: - ConsoleSink() - : blacklist{get_set_from_env("EMULATOR_BLACKLIST_MODULE", ',')}, - whitelist{get_set_from_env("EMULATOR_WHITELIST_MODULE", ',')} {} - -protected: - void sink_it_(const spdlog::details::log_msg &msg) override { - auto data = std::string(msg.payload.data(), msg.payload.size()); - // Don't touch error message - if (msg.level == spdlog::level::info) { - std::string module_name; - try { - json payload = json::parse(data); - payload["name"].get_to(module_name); - } catch (const json::parse_error &ex) { - throw std::runtime_error( - fmt::format("Fail to convert msg {} to json: {}", data, ex.what())); - } catch (const json::type_error &ex) { - throw std::runtime_error( - fmt::format("Fail to get field name from: {}", data)); - } - - if (!is_expected_module(module_name)) { - return; - } - } - - spdlog::memory_buf_t formatted; - spdlog::sinks::base_sink::formatter_->format(msg, formatted); - // stdout will be captured by mill, so we need to print them into stderr - std::cerr << fmt::to_string(formatted); - } - - void flush_() override { std::cerr << std::flush; } -}; +#include "vbridge_impl.h" /** * Create two logging sink, one for creating JSON format logging file, another @@ -117,36 +19,11 @@ class ConsoleSink : public spdlog::sinks::base_sink { void setup_logger() { std::string log_path = getenv_or("EMULATOR_LOG_PATH", "emulator-log.json"); - // Pre-process the file so that after program exit, it can be a valid JSON - // array. - spdlog::file_event_handlers f_handlers; - f_handlers.after_open = [](spdlog::filename_t _, std::FILE *fstream) { - fputs("[\n", fstream); - }; - f_handlers.after_close = [](spdlog::filename_t log_path) { - std::ifstream old_log_file(log_path); - std::ofstream temp_file("temp-log.json"); - std::string line; - while (std::getline(old_log_file, line)) { - temp_file << line; - } - // Drop the last ',' - temp_file.seekp(-1, std::ios::cur); - temp_file.write("]\n", 2); - temp_file.close(); - old_log_file.close(); - std::filesystem::rename("temp-log.json", log_path); - }; - auto file_sink = std::make_shared( - log_path, /*truncate=*/true, f_handlers); - // Basic logging information, other data are nested in the `log` attribute - // set. - file_sink->set_pattern( - "{ \"timestamp\": \"%E\", \"level\": \"%l\", \"log\": %v },"); + auto file_sink = std::make_shared(log_path, /*truncate=*/true); + file_sink->set_pattern("%v"); auto console_sink = std::make_shared(); - // %T: "23:55:59" (We don't need other information.) - console_sink->set_pattern("%T %v"); + console_sink->set_pattern("- %v"); // One thread with 8192 queue size spdlog::init_thread_pool(8192, 1); @@ -169,3 +46,7 @@ void setup_logger() { return; } + +uint64_t JsonLogger::get_cycle() { + return vbridge_impl_instance.get_t(); +} diff --git a/emulator/src/spdlog-ext.h b/emulator/src/spdlog-ext.h index f8da717a8..c9009f48a 100644 --- a/emulator/src/spdlog-ext.h +++ b/emulator/src/spdlog-ext.h @@ -1,45 +1,133 @@ #pragma once +#include #include -#include #include + #include +#include +#include +#include +#include +#include + +#include using json = nlohmann::json; -// Exported symbols -#define FATAL(context) \ - auto _fatal_fmt_msg = fmt::format("{}", context); \ - spdlog::critical("{}", context); \ - spdlog::shutdown(); \ - throw std::runtime_error(_fatal_fmt_msg); +/** + * Get environment variable by the given `env` key or fallback to a default + * value. + */ +inline std::string getenv_or(const char *env, std::string fallback) { + char *env_var = std::getenv(env); + if (env_var && strlen(env_var) > 0) { + return std::string{env_var}; + } -#define CHECK(cond, context) \ - if (!(cond)) { \ - auto _f_msg = \ - fmt::format("check failed: {} : Assertion ({}) failed at {}:{}", \ - context, #cond, __FILE__, __LINE__); \ - json _j; \ - _j["message"] = _f_msg; \ - FATAL(_j.dump()); \ + return fallback; +} + +/** + * Get environment variable and split them into std::vector by the given + * `delimiter` + */ +inline std::set get_set_from_env(const char *env, const char delimiter) { + std::set set; + + auto raw = getenv_or(env, ""); + if (raw.empty()) { + return set; } -#define CHECK_EQ(val1, val2, context) CHECK(val1 == val2, context) -#define CHECK_NE(val1, val2, context) CHECK(val1 != val2, context) -#define CHECK_LE(val1, val2, context) CHECK(val1 <= val2, context) -#define CHECK_LT(val1, val2, context) CHECK(val1 < val2, context) -#define CHECK_GE(val1, val2, context) CHECK(val1 >= val2, context) -#define CHECK_GT(val1, val2, context) CHECK(val1 > val2, context) + std::stringstream ss(raw); + std::string token; + // Use `delimiter` instead of '\n' to split element in string. + while (std::getline(ss, token, delimiter)) { + set.insert(token); + } -void setup_logger(); + return set; +} + +/** + * Filter logging message by module type. Filter should be set by environment + * `EMULATOR_BLACKLIST_MODULE` and `EMULATOR_WHITELIST_MODULE`. Module should be + * separate by column `,`. When you set both env, only blacklist will have + * effect. + */ +class ConsoleSink : public spdlog::sinks::base_sink { +private: + std::set whitelist; + bool enable_sink; + + bool is_expected_module(std::string &module) { + if (!whitelist.empty() && whitelist.find(module) == whitelist.end()) { + return false; + } + + return true; + } + +public: + ConsoleSink() { + auto no_log = getenv_or("EMULATOR_NO_LOG", "false"); + enable_sink = (no_log == "false"); + + whitelist = get_set_from_env("EMULATOR_WHITELIST_MODULE", ','); + whitelist.insert("DPIInitCosim"); + whitelist.insert("SpikeStep"); + whitelist.insert("SimulationExit"); + } + +protected: + void sink_it_(const spdlog::details::log_msg &msg) override { + if (!enable_sink) { return; }; + + auto data = std::string(msg.payload.data(), msg.payload.size()); + // Don't touch error message + if (msg.level == spdlog::level::info) { + std::string module_name; + try { + json payload = json::parse(data); + payload["name"].get_to(module_name); + } catch (const json::parse_error &ex) { + throw std::runtime_error( + fmt::format("Fail to convert msg {} to json: {}", data, ex.what())); + } catch (const json::type_error &ex) { + throw std::runtime_error( + fmt::format("Fail to get field name from: {}", data)); + } + + if (!is_expected_module(module_name)) { + return; + } + } + + spdlog::memory_buf_t formatted; + spdlog::sinks::base_sink::formatter_->format(msg, formatted); + // stdout will be captured by mill, so we need to print them into stderr + std::cerr << fmt::to_string(formatted); + } -class Log { + void flush_() override { std::cerr << std::flush; } +}; + +enum class LogType { + Info, + Warn, + Trace, + Fatal, +}; + +class JsonLogger { private: json internal; + bool do_logging; inline std::string dump() { std::string ret; try { - ret = internal.dump(/*indent=*/2); + ret = internal.dump(); } catch (json::type_error &ex) { throw std::runtime_error(fmt::format("JSON error for log '{}': {}", internal["name"], ex.what())); @@ -47,11 +135,51 @@ class Log { return ret; } + uint64_t get_cycle(); + + template + inline void try_log(LogType log_type, std::optional> fmt, Arg &&...args) { + if (!do_logging) return; + + if (fmt.has_value()) { + auto msg = fmt::format(fmt.value(), args...); + internal["message"] = msg; + } + + internal["cycle"] = get_cycle(); + + switch(log_type) { + case LogType::Info : spdlog::info("{}", this->dump()); break; + case LogType::Warn : spdlog::warn("{}", this->dump()); break; + case LogType::Trace : spdlog::trace("{}", this->dump()); break; + case LogType::Fatal : { + spdlog::critical("{}", this->dump()); + spdlog::shutdown(); + + throw std::runtime_error(internal["message"]); + } + } + + } + public: - Log(const char *n) { internal["name"] = n; } - ~Log() = default; + JsonLogger() { + auto no_log = getenv_or("EMULATOR_NO_LOG", "false"); + do_logging = (no_log == "false"); + } + ~JsonLogger() = default; + + JsonLogger operator()(const char*n) { + if (!do_logging) return *this; + + internal.clear(); + internal["name"] = n; + return *this; + } + + template JsonLogger &with(const char *key, T value) { + if (!do_logging) return *this; - template Log &with(const char *key, T value) { internal["data"][key] = value; return *this; } @@ -59,45 +187,59 @@ class Log { // Overload the index operator json &operator[](const char *key) { return internal["info"][key]; }; - inline void info() { spdlog::info("{}", this->dump()); } - inline void trace() { spdlog::trace("{}", this->dump()); } + inline void info() { + try_log(LogType::Info, std::nullopt); + } + inline void trace() { + try_log(LogType::Trace, std::nullopt); + } template inline void info(fmt::format_string fmt, Arg &&...args) { - auto msg = fmt::format(fmt, args...); - internal["message"] = msg; - spdlog::info("{}", this->dump()); + try_log(LogType::Info, fmt, args...); } template inline void warn(fmt::format_string fmt, Arg &&...args) { - auto msg = fmt::format(fmt, args...); - internal["message"] = msg; - spdlog::warn("{}", this->dump()); - } - - template - inline void critical(fmt::format_string fmt, Arg &&...args) { - auto msg = fmt::format(fmt, args...); - internal["message"] = msg; - spdlog::critical("{}", this->dump()); + try_log(LogType::Warn, fmt, args...); } template inline void trace(fmt::format_string fmt, Arg &&...args) { - auto msg = fmt::format(fmt, args...); - internal["message"] = msg; - spdlog::trace("{}", this->dump()); + try_log(LogType::Trace, fmt, args...); }; template inline void fatal(fmt::format_string fmt, Arg &&...args) { - auto msg = fmt::format(fmt, args...); - internal["message"] = msg; + try_log(LogType::Fatal, fmt, args...); + }; + }; - spdlog::critical("{}", this->dump()); - spdlog::shutdown(); - throw std::runtime_error(msg); - }; -}; +// Exported symbols +#define FATAL(context) \ + auto _fatal_fmt_msg = fmt::format("{}", context); \ + spdlog::critical("{}", context); \ + spdlog::shutdown(); \ + throw std::runtime_error(_fatal_fmt_msg); + +#define CHECK(cond, context) \ + if (!(cond)) { \ + auto _f_msg = \ + fmt::format("check failed: {} : Assertion ({}) failed at {}:{}", \ + context, #cond, __FILE__, __LINE__); \ + json _j; \ + _j["message"] = _f_msg; \ + FATAL(_j.dump()); \ + } + +#define CHECK_EQ(val1, val2, context) CHECK(val1 == val2, context) +#define CHECK_NE(val1, val2, context) CHECK(val1 != val2, context) +#define CHECK_LE(val1, val2, context) CHECK(val1 <= val2, context) +#define CHECK_LT(val1, val2, context) CHECK(val1 < val2, context) +#define CHECK_GE(val1, val2, context) CHECK(val1 >= val2, context) +#define CHECK_GT(val1, val2, context) CHECK(val1 > val2, context) + +void setup_logger(); + +inline JsonLogger Log; diff --git a/emulator/src/vbridge_impl.cc b/emulator/src/vbridge_impl.cc index c4b0ab5a3..0c5d8d9d3 100644 --- a/emulator/src/vbridge_impl.cc +++ b/emulator/src/vbridge_impl.cc @@ -19,10 +19,8 @@ inline bool is_pow2(uint32_t n) { return n && !(n & (n - 1)); } void VBridgeImpl::timeoutCheck() { getCoverage(); if (get_t() > timeout + last_commit_time) { - auto t = get_t(); Log("VBridgeImplTimeoutCheck") .with("last_commit", last_commit_time) - .with("cycle", t) .fatal("Simulation timeout"); } } @@ -32,7 +30,6 @@ void VBridgeImpl::dpiInitCosim() { ctx = Verilated::threadContextp(); Log("DPIInitCosim") - .with("cycle", getCycle()) .info("Initializing simulation environment"); proc.reset(); @@ -77,13 +74,13 @@ void VBridgeImpl::dpiInitCosim() { //================== void VBridgeImpl::dpiPeekLsuEnq(const VLsuReqEnqPeek &lsu_req_enq) { - Log("DPIPeekLSUEnq").with("cycle", get_t()).trace(); + Log("DPIPeekLSUEnq").trace(); update_lsu_idx(lsu_req_enq); } void VBridgeImpl::dpiPeekVrfWrite(const VrfWritePeek &vrf_write) { - Log("DPIPeekVRFWrite").with("cycle", get_t()).trace(); + Log("DPIPeekVRFWrite").trace(); CHECK(0 <= vrf_write.lane_index && vrf_write.lane_index < config.lane_number, "vrf_write have unexpected land index"); @@ -93,7 +90,7 @@ void VBridgeImpl::dpiPeekVrfWrite(const VrfWritePeek &vrf_write) { void VBridgeImpl::dpiPokeInst(const VInstrInterfacePoke &v_instr, const VCsrInterfacePoke &v_csr, const VRespInterface &v_resp) { - Log("DPIPokeInst").with("cycle", get_t()).trace(); + Log("DPIPokeInst").trace(); for (auto &se : to_rtl_queue) { Log("DPIPokeInst") @@ -104,14 +101,13 @@ void VBridgeImpl::dpiPokeInst(const VInstrInterfacePoke &v_instr, } if (v_resp.valid) { - Log("DPIPokeInst").with("cycle", get_t()).info("prepare to commit"); + Log("DPIPokeInst").info("prepare to commit"); SpikeEvent &se = to_rtl_queue.back(); se.record_rd_write(v_resp); se.check_is_ready_for_commit(); Log("DPIPokeInst") - .with("cycle", get_t()) .with("insn", to_rtl_queue.back().jsonify_insn()) .info("rtl commit insn"); @@ -126,7 +122,6 @@ void VBridgeImpl::dpiPokeInst(const VInstrInterfacePoke &v_instr, if (se_to_issue->is_exit_insn) { Log("DPIPokeInst") .with("insn", se_to_issue->jsonify_insn()) - .with("cycle", get_t()) .info("reaching exit insturction"); throw ReturnException(); } @@ -142,16 +137,14 @@ void VBridgeImpl::dpiPokeInst(const VInstrInterfacePoke &v_instr, // se_to_issue should not be issued CHECK_GT(to_rtl_queue.size(), 1, "to_rtl_queue are smaller than expected"); if (se_to_issue->is_exit_insn) { - Log("DPIPokeInst").with("cycle", get_t()).info("exit waiting for fence"); + Log("DPIPokeInst").info("exit waiting for fence"); } else { Log("DPIPokeInst") - .with("cycle", get_t()) .info("waiting for fence, no issuing new instruction"); } *v_instr.valid = false; } else { Log("DPIPokeInst") - .with("cycle", get_t()) .with("inst", se_to_issue->jsonify_insn()) .with("rs1", fmt::format("{:08x}", se_to_issue->rs1_bits)) .with("rs2", fmt::format("{:08x}", se_to_issue->rs2_bits)) @@ -166,12 +159,11 @@ void VBridgeImpl::dpiPokeInst(const VInstrInterfacePoke &v_instr, //================== void VBridgeImpl::dpiPeekIssue(svBit ready, svBitVecVal issueIdx) { - Log("DPIPeekIssue").with("cycle", get_t()).with("func", __func__).trace(); + Log("DPIPeekIssue").with("func", __func__).trace(); if (ready && !(se_to_issue->is_vfence_insn || se_to_issue->is_exit_insn)) { se_to_issue->is_issued = true; se_to_issue->issue_idx = issueIdx; Log("DPIPeekIssue") - .with("cycle", get_t()) .with("insn", se_to_issue->jsonify_insn()) .with("issue_idx", issueIdx) .info("issue to rtl"); @@ -179,7 +171,7 @@ void VBridgeImpl::dpiPeekIssue(svBit ready, svBitVecVal issueIdx) { } void VBridgeImpl::dpiPokeTL(const VTlInterfacePoke &v_tl_resp) { - Log("DPIPokeTL").with("cycle", get_t()).trace(); + Log("DPIPokeTL").trace(); CHECK(0 <= v_tl_resp.channel_id && v_tl_resp.channel_id < config.tl_bank_number, "invalid v_tl_resp channel id"); @@ -191,7 +183,7 @@ void VBridgeImpl::dpiPokeTL(const VTlInterfacePoke &v_tl_resp) { //================== void VBridgeImpl::dpiPeekTL(const VTlInterface &v_tl) { - Log("DPIPeekTL").with("cycle", get_t()).trace(); + Log("DPIPeekTL").trace(); CHECK(0 <= v_tl.channel_id && v_tl.channel_id < config.tl_bank_number, "invalid v_tl channel id"); receive_tl_d_ready(v_tl); @@ -203,7 +195,7 @@ void VBridgeImpl::dpiPeekTL(const VTlInterface &v_tl) { //================== void VBridgeImpl::dpiPeekWriteQueue(const VLsuWriteQueuePeek &lsu_queue) { - Log("DPIPeekWriteQueue").with("cycle", get_t()).trace(); + Log("DPIPeekWriteQueue").trace(); CHECK(0 <= lsu_queue.mshr_index && lsu_queue.mshr_index < config.lane_number, "invalid lsu_queue mshr index"); record_rf_queue_accesses(lsu_queue); @@ -357,11 +349,11 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { se = &(*se_iter); } } - CHECK(se, fmt::format(": [{}] cannot find SpikeEvent with lsu_idx={}", - get_t(), lsu_index)); + CHECK(se, fmt::format("cannot find SpikeEvent with lsu_idx={}", + lsu_index)); CHECK_EQ((base_addr & (size - 1)), 0, - fmt::format(": [{}] unaligned access (addr={:08X}, size={})", - get_t(), base_addr, size)); + fmt::format("unaligned access (addr={:08X}, size={})", + base_addr, size)); switch (opcode) { @@ -377,7 +369,6 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { } else { // TODO: check if the cache line should be accessed Log("ReceiveTLReq") - .with("cycle", get_t()) .with("addr", fmt::format("{:08x}", addr)) .trace(); actual_data[offset] = 0xDE; // falsy data @@ -385,7 +376,6 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { } Log("ReceiveTLReq") - .with("cycle", get_t()) .with("channel", tlIdx) .with("bass_addr", fmt::format("{:08x}", base_addr)) .with("size_by_byte", size) @@ -413,7 +403,6 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { CHECK_EQ(record.addr, base_addr, "inconsistent burst addr"); CHECK_EQ(record.size_by_byte, size, "inconsistent burst size"); Log("ReceiveTLReq") - .with("cycle", get_t()) .with("channel", tlIdx) .with("base_addr", fmt::format("{:08X}", base_addr)) .with("offset", record.bytes_received) @@ -442,7 +431,6 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { data[data_begin_pos + offset] = n_th_byte(tl.a_bits_data, offset); } Log("RTLMemPutReq") - .with("cycle", get_t()) .with("channel", tlIdx) .with("addr", fmt::format("{:08X}", base_addr)) .with("size_by_byte", size) @@ -466,8 +454,8 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { uint8_t tl_data_byte = n_th_byte(tl.a_bits_data, byte_lane_idx); auto mem_write = se->mem_access_record.all_writes.find(byte_addr); CHECK_NE(mem_write, se->mem_access_record.all_writes.end(), - fmt::format(": [{}] cannot find mem write of byte_addr {:08X}", - get_t(), byte_addr)); + fmt::format("cannot find mem write of byte_addr {:08X}", + byte_addr)); // for (auto &w : mem_write->second.writes) { // LOG(INFO) << fmt::format("write addr={:08X}, byte={:02X}", // byte_addr, w.val); @@ -478,9 +466,9 @@ void VBridgeImpl::receive_tl_req(const VTlInterface &tl) { auto single_mem_write = mem_write->second.writes.at( mem_write->second.num_completed_writes++); CHECK_EQ(single_mem_write.val, tl_data_byte, - fmt::format(": [{}] expect mem write of byte {:02X}, actual " + fmt::format("expect mem write of byte {:02X}, actual " "byte {:02X} (channel={}, byte_addr={:08X}, {})", - get_t(), single_mem_write.val, tl_data_byte, tlIdx, + single_mem_write.val, tl_data_byte, tlIdx, byte_addr, se->describe_insn())); } } @@ -513,8 +501,8 @@ void VBridgeImpl::receive_tl_d_ready(const VTlInterface &tl) { auto find = tl_req_record_of_bank[tlIdx].find(addr); CHECK_NE( find, tl_req_record_of_bank[tlIdx].end(), - fmt::format(": [{}] cannot find current request with addr {:08X}", - get_t(), addr)); + fmt::format("cannot find current request with addr {:08X}", + addr)); auto &req_record = find->second; req_record.bytes_sent += std::min(config.datapath_width_in_bytes, req_record.size_by_byte); @@ -522,7 +510,6 @@ void VBridgeImpl::receive_tl_d_ready(const VTlInterface &tl) { tl_req_waiting_ready[tlIdx].reset(); tl_req_record_of_bank[tlIdx].erase(find); Log("ReceiveTlDReady") - .with("cycle", get_t()) .with("channel", tlIdx) .with("addr", fmt::format("{:08X}", addr)) .info("-> tl response reaches d_ready"); @@ -548,7 +535,6 @@ void VBridgeImpl::return_tl_response(const VTlInterfacePoke &tl_poke) { size_t actual_beat_size = std::min(config.datapath_width_in_bytes, record.size_by_byte); Log("ReturnTlResponse") - .with("cycle", get_t()) .with("channel", i) .with("addr", fmt::format("{:08x}", record.addr)) .with("size_by_byte", record.size_by_byte) @@ -607,13 +593,11 @@ void VBridgeImpl::update_lsu_idx(const VLsuReqEnqPeek &enq) { } if (index == lsu_idx_default) { Log("UpdateLSUIdx") - .with("cycle", get_t()) .info("waiting for lsu request to fire"); break; } se->lsu_idx = index; Log("UpdateLSUIdx") - .with("cycle", get_t()) .with("insn", se->jsonify_insn()) .with("lsu_idx", index) .info("Instruction is allocated"); @@ -666,13 +650,11 @@ void VBridgeImpl::record_rf_accesses(const VrfWritePeek &rf_write) { } if (se_vrf_write == nullptr) { Log("RecordRFAccess") - .with("cycle", get_t()) .with("index", idx) .warn("rtl detect vrf write which cannot find se, maybe from " "committed load insn"); } else if (!se_vrf_write->is_load) { Log("RecordRFAccess") - .with("cycle", get_t()) .with("lane", lane_idx) .with("vd", vd) .with("offset", offset) @@ -703,7 +685,6 @@ void VBridgeImpl::record_rf_queue_accesses( } } Log("RecordRFAccesses") - .with("cycle", get_t()) .with("lane", lane_idx) .with("vd", vd) .with("offset", offset) @@ -733,20 +714,20 @@ void VBridgeImpl::add_rtl_write(SpikeEvent *se, uint32_t lane_idx, uint32_t vd, auto &record = record_iter->second; CHECK_EQ((int)record.byte, (int)written_byte, fmt::format( // convert to int to avoid stupid printing - ": [{}] {}th byte incorrect ({:02X} != {:02X}) for vrf " + "{}th byte incorrect ({:02X} != {:02X}) for vrf " "write (lane={}, vd={}, offset={}, mask={:04b}) " "[vrf_idx={}]", - get_t(), j, record.byte, written_byte, lane_idx, vd, + j, record.byte, written_byte, lane_idx, vd, offset, mask, record_idx_base + j)); record.executed = true; } else if (uint8_t original_byte = vrf_shadow[record_idx_base + j]; original_byte != written_byte) { FATAL(fmt::format( - ": [{}] vrf writes {}th byte (lane={}, vd={}, offset={}, " + "vrf writes {}th byte (lane={}, vd={}, offset={}, " "mask={:04b}, data={}, original_data={}), " "but not recorded by spike ({}) [{}]", - get_t(), j, lane_idx, vd, offset, mask, written_byte, original_byte, + j, lane_idx, vd, offset, mask, written_byte, original_byte, se->describe_insn(), record_idx_base + j)); } else { // no spike record and rtl written byte is identical as the byte before From e257a32f6c53479eb54ce9b629b5f3ba10f11dbb Mon Sep 17 00:00:00 2001 From: github-actions Date: Thu, 26 Oct 2023 17:51:09 +0000 Subject: [PATCH 2/2] [ci] update test case cycle data --- .../passed/v1024l8b2-test/debug/passed.json | 62 +++++++++---------- 1 file changed, 31 insertions(+), 31 deletions(-) diff --git a/.github/passed/v1024l8b2-test/debug/passed.json b/.github/passed/v1024l8b2-test/debug/passed.json index d609cb6be..22d759f57 100644 --- a/.github/passed/v1024l8b2-test/debug/passed.json +++ b/.github/passed/v1024l8b2-test/debug/passed.json @@ -144,16 +144,16 @@ "vluxseg8ei16.v-codegen": 10673, "vluxseg8ei32.v-codegen": 5350, "vluxseg8ei8.v-codegen": 19493, - "vmacc.vv-codegen": 43678, - "vmacc.vx-codegen": 119289, + "vmacc.vv-codegen": 43680, + "vmacc.vx-codegen": 116642, "vmadc.vi-codegen": 52084, "vmadc.vim-codegen": 50942, "vmadc.vv-codegen": 16267, "vmadc.vvm-codegen": 18182, "vmadc.vx-codegen": 67405, "vmadc.vxm-codegen": 73757, - "vmadd.vv-codegen": 43678, - "vmadd.vx-codegen": 119289, + "vmadd.vv-codegen": 43680, + "vmadd.vx-codegen": 116642, "vmand.mm-codegen": 15637, "vmandn.mm-codegen": 15637, "vmax.vv-codegen": 38466, @@ -200,14 +200,14 @@ "vmsne.vv-codegen": 39939, "vmsne.vx-codegen": 144294, "vmsof.m-codegen": 1007, - "vmul.vv-codegen": 38550, - "vmul.vx-codegen": 159646, - "vmulh.vv-codegen": 38550, - "vmulh.vx-codegen": 159646, - "vmulhsu.vv-codegen": 38550, - "vmulhsu.vx-codegen": 159646, - "vmulhu.vv-codegen": 38550, - "vmulhu.vx-codegen": 159646, + "vmul.vv-codegen": 38466, + "vmul.vx-codegen": 155966, + "vmulh.vv-codegen": 38466, + "vmulh.vx-codegen": 155966, + "vmulhsu.vv-codegen": 38466, + "vmulhsu.vx-codegen": 155966, + "vmulhu.vv-codegen": 38466, + "vmulhu.vx-codegen": 155966, "vmv.s.x-codegen": 759, "vmv.v.i-codegen": 25764, "vmv.v.v-codegen": 11858, @@ -225,10 +225,10 @@ "vnclipu.wi-codegen": 61631, "vnclipu.wv-codegen": 18337, "vnclipu.wx-codegen": 84824, - "vnmsac.vv-codegen": 43678, - "vnmsac.vx-codegen": 119289, - "vnmsub.vv-codegen": 43678, - "vnmsub.vx-codegen": 119289, + "vnmsac.vv-codegen": 43680, + "vnmsac.vx-codegen": 116642, + "vnmsub.vv-codegen": 43680, + "vnmsub.vx-codegen": 116642, "vnsra.wi-codegen": 61631, "vnsra.wv-codegen": 18337, "vnsra.wx-codegen": 84824, @@ -286,8 +286,8 @@ "vsll.vv-codegen": 38550, "vsll.vx-codegen": 118978, "vsm.v-codegen": 276, - "vsmul.vv-codegen": 38550, - "vsmul.vx-codegen": 118978, + "vsmul.vv-codegen": 38466, + "vsmul.vx-codegen": 116398, "vsoxei16.v-codegen": 16092, "vsoxei32.v-codegen": 11996, "vsoxei8.v-codegen": 21779, @@ -407,19 +407,19 @@ "vwaddu.vx-codegen": 89464, "vwaddu.wv-codegen": 22975, "vwaddu.wx-codegen": 108533, - "vwmacc.vv-codegen": 28732, - "vwmacc.vx-codegen": 107197, - "vwmaccsu.vv-codegen": 28732, - "vwmaccsu.vx-codegen": 107197, - "vwmaccu.vv-codegen": 28732, - "vwmaccu.vx-codegen": 107197, - "vwmaccus.vx-codegen": 107197, - "vwmul.vv-codegen": 20180, - "vwmul.vx-codegen": 127420, - "vwmulsu.vv-codegen": 20180, - "vwmulsu.vx-codegen": 127420, - "vwmulu.vv-codegen": 20180, - "vwmulu.vx-codegen": 127420, + "vwmacc.vv-codegen": 28702, + "vwmacc.vx-codegen": 106982, + "vwmaccsu.vv-codegen": 28702, + "vwmaccsu.vx-codegen": 106982, + "vwmaccu.vv-codegen": 28702, + "vwmaccu.vx-codegen": 106982, + "vwmaccus.vx-codegen": 106982, + "vwmul.vv-codegen": 20212, + "vwmul.vx-codegen": 127468, + "vwmulsu.vv-codegen": 20212, + "vwmulsu.vx-codegen": 127468, + "vwmulu.vv-codegen": 20212, + "vwmulu.vx-codegen": 127468, "vwredsum.vs-codegen": 19461, "vwredsumu.vs-codegen": 19461, "vwsub.vv-codegen": 20212,