diff --git a/kernel/log.cc b/kernel/log.cc index 2fad52109..6502bcdc2 100644 --- a/kernel/log.cc +++ b/kernel/log.cc @@ -40,7 +40,6 @@ YOSYS_NAMESPACE_BEGIN std::vector log_files; std::vector log_streams; -std::vector log_sinks; std::vector log_scratchpads; std::map> log_hdump; std::vector log_warn_regexes, log_nowarn_regexes, log_werror_regexes; @@ -70,7 +69,7 @@ int log_debug_suppressed = 0; vector header_count; vector log_id_cache; -static struct timeval initial_tv = { 0, 0 }; +static std::optional initial_time; static bool next_print_log = false; static int log_newline_count = 0; @@ -81,37 +80,57 @@ static void log_id_cache_clear() log_id_cache.clear(); } -#if defined(_WIN32) && !defined(__MINGW32__) -// this will get time information and return it in timeval, simulating gettimeofday() -int gettimeofday(struct timeval *tv, struct timezone *tz) +static void log_default_callback(LogMessage msg) { - LARGE_INTEGER counter; - LARGE_INTEGER freq; + std::string time_str; + if (log_time) + { + if (next_print_log || !initial_time) { + next_print_log = false; + if (!initial_time) + initial_time = std::chrono::steady_clock::now(); + auto elapsed = std::chrono::steady_clock::now() - *initial_time; + auto us = std::chrono::duration_cast(elapsed); + time_str += stringf("[%05d.%06d] ", int(us.count() / 1'000'000),int(us.count() % 1'000'000)); + } - QueryPerformanceFrequency(&freq); - QueryPerformanceCounter(&counter); + if (!msg.format.empty() && msg.format.back() == '\n') + next_print_log = true; - counter.QuadPart *= 1'000'000; - counter.QuadPart /= freq.QuadPart; + // Special case to detect newlines in Python log output, since + // the binding always calls `log("%s", payload)` and the newline + // is then in the first formatted argument + if (msg.format == "%s" && msg.message.back() == '\n') + next_print_log = true; + } - tv->tv_sec = long(counter.QuadPart / 1000000); - tv->tv_usec = counter.QuadPart % 1'000'000; + std::string str = stringf("%s%s%s", time_str, msg.prefix, msg.message); + for (auto f : log_files) { + fputs(str.c_str(), f); + } - return 0; + for (auto f : log_streams) + *f << str; + + RTLIL::Design *design = yosys_get_design(); + if (design != nullptr) + for (auto &scratchpad : log_scratchpads) + design->scratchpad[scratchpad].append(str); } -#endif -static void logv_string(std::string_view format, std::string str, LogSeverity severity = LogSeverity::LOG_INFO) { +static void logv_string(std::string_view prefix, std::string_view format, std::string str_in, LogSeverity severity) { size_t remove_leading = 0; while (format.size() > 1 && format[0] == '\n') { - logv_string("\n", "\n"); + logv_string(prefix, "\n", "\n", severity); format = format.substr(1); ++remove_leading; } if (remove_leading > 0) { - str = str.substr(remove_leading); + str_in = str_in.substr(remove_leading); } + std::string str = stringf("%s%s",prefix,str_in); + if (str.empty()) return; @@ -124,55 +143,7 @@ static void logv_string(std::string_view format, std::string str, LogSeverity se if (log_hasher) log_hasher->update(str); - if (log_time) - { - std::string time_str; - - if (next_print_log || initial_tv.tv_sec == 0) { - next_print_log = false; - struct timeval tv; - gettimeofday(&tv, NULL); - if (initial_tv.tv_sec == 0) - initial_tv = tv; - if (tv.tv_usec < initial_tv.tv_usec) { - tv.tv_sec--; - tv.tv_usec += 1'000'000; - } - tv.tv_sec -= initial_tv.tv_sec; - tv.tv_usec -= initial_tv.tv_usec; - time_str += stringf("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec)); - } - - if (!format.empty() && format[format.size() - 1] == '\n') - next_print_log = true; - - // Special case to detect newlines in Python log output, since - // the binding always calls `log("%s", payload)` and the newline - // is then in the first formatted argument - if (format == "%s" && str.back() == '\n') - next_print_log = true; - - for (auto f : log_files) - fputs(time_str.c_str(), f); - - for (auto f : log_streams) - *f << time_str; - } - - for (auto f : log_files) - fputs(str.c_str(), f); - - for (auto f : log_streams) - *f << str; - - LogMessage log_msg(severity, str); - for (LogSink* sink : log_sinks) - sink->log(log_msg); - - RTLIL::Design *design = yosys_get_design(); - if (design != nullptr) - for (auto &scratchpad : log_scratchpads) - design->scratchpad[scratchpad].append(str); + log_default_callback(LogMessage(severity, prefix, format, str_in)); static std::string linebuffer; static bool log_warn_regex_recusion_guard = false; @@ -206,13 +177,13 @@ static void logv_string(std::string_view format, std::string str, LogSeverity se } } -void log_formatted_string(std::string_view format, std::string str, LogSeverity severity) +void log_formatted_string(std::string_view prefix, std::string_view format, std::string str, LogSeverity severity) { log_assert(!Multithreading::active()); if (log_make_debug && !ys_debug(1)) return; - logv_string(format, std::move(str), severity); + logv_string(prefix, format, std::move(str), severity); } void log_formatted_header(RTLIL::Design *design, std::string_view format, std::string str) @@ -235,8 +206,8 @@ void log_formatted_header(RTLIL::Design *design, std::string_view format, std::s for (int c : header_count) header_id += stringf("%s%d", header_id.empty() ? "" : ".", c); - log("%s. ", header_id); - log_formatted_string(format, std::move(str)); + log_formatted_string(stringf("%s. ", header_id), {}, {}, LogSeverity::LOG_HEADER); + log_formatted_string({}, format, std::move(str), LogSeverity::LOG_HEADER); log_flush(); if (log_hdump_all) @@ -277,7 +248,7 @@ void log_formatted_warning(std::string_view prefix, std::string message) for (auto &re : log_werror_regexes) if (std::regex_search(message, re)) - log_error("%s", message); + log_formatted_error(message); bool warning_match = false; for (auto &[_, item] : log_expect_warning) @@ -294,7 +265,7 @@ void log_formatted_warning(std::string_view prefix, std::string message) if (log_warnings.count(message)) { - log("%s%s", prefix, message); + log_formatted_string(prefix, "%s", message, LogSeverity::LOG_WARNING); log_flush(); } else @@ -302,7 +273,7 @@ void log_formatted_warning(std::string_view prefix, std::string message) if (log_errfile != NULL && !log_quiet_warnings) log_files.push_back(log_errfile); - log_formatted_string("%s", stringf("%s%s", prefix, message), LogSeverity::LOG_WARNING); + log_formatted_string(prefix, "%s", message, LogSeverity::LOG_WARNING); log_flush(); if (log_errfile != NULL && !log_quiet_warnings) @@ -332,7 +303,7 @@ void log_formatted_file_info(std::string_view filename, int lineno, std::string void log_suppressed() { if (log_debug_suppressed && !log_make_debug) { constexpr const char* format = "\n"; - logv_string(format, stringf(format, log_debug_suppressed)); + logv_string({}, format, stringf(format, log_debug_suppressed),LogSeverity::LOG_INFO); log_debug_suppressed = 0; } } @@ -357,7 +328,7 @@ static void log_error_with_prefix(std::string_view prefix, std::string str) log_last_error = std::move(str); std::string message(prefix); message += log_last_error; - log_formatted_string("%s", message, LogSeverity::LOG_ERROR); + log_formatted_string(prefix, "%s", log_last_error, LogSeverity::LOG_ERROR); log_flush(); log_make_debug = bak_log_make_debug; @@ -434,7 +405,7 @@ void log_formatted_cmd_error(std::string str) pop_errfile = true; } - log_formatted_string("%s", stringf("ERROR: %s", log_last_error), LogSeverity::LOG_ERROR); + log_formatted_string("ERROR: ", "%s", log_last_error, LogSeverity::LOG_ERROR); log_flush(); if (pop_errfile) diff --git a/kernel/log.h b/kernel/log.h index fe62e1c81..1e5719de1 100644 --- a/kernel/log.h +++ b/kernel/log.h @@ -22,6 +22,7 @@ #include "kernel/yosys_common.h" +#include #include #include @@ -86,27 +87,30 @@ YOSYS_NAMESPACE_BEGIN struct log_cmd_error_exception { }; enum LogSeverity { + LOG_DEBUG, + LOG_COMMENT, LOG_INFO, + LOG_HEADER, LOG_WARNING, LOG_ERROR }; struct LogMessage { - LogMessage(LogSeverity severity, std::string_view message) : - severity(severity), timestamp(std::time(nullptr)), message(message) {} + LogMessage(LogSeverity severity, std::string_view prefix, std::string_view format, std::string_view message) : + severity(severity), + prefix(prefix), + format(format), + message(message), + timestamp(std::chrono::steady_clock::now()) {} LogSeverity severity; - std::time_t timestamp; + std::string prefix; + std::string format; std::string message; -}; - -class LogSink { - public: - virtual void log(const LogMessage& message) = 0; + std::chrono::steady_clock::time_point timestamp; }; extern std::vector log_files; extern std::vector log_streams; -extern std::vector log_sinks; extern std::vector log_scratchpads; extern std::map> log_hdump; extern std::vector log_warn_regexes, log_nowarn_regexes, log_werror_regexes; @@ -138,13 +142,26 @@ static inline bool ys_debug(int n = 0) { if (log_force_debug) return true; log_d #else static inline bool ys_debug(int = 0) { return false; } #endif -# define log_debug(...) do { if (ys_debug(1)) log(__VA_ARGS__); } while (0) -void log_formatted_string(std::string_view format, std::string str, LogSeverity severity = LogSeverity::LOG_INFO); +void log_formatted_string(std::string_view prefix, std::string_view format, std::string str, LogSeverity severity); template inline void log(FmtString...> fmt, const Args &... args) { - log_formatted_string(fmt.format_string(), fmt.format(args...)); + log_formatted_string({}, fmt.format_string(), fmt.format(args...), LogSeverity::LOG_INFO); +} + +template +inline void log_comment(FmtString...> fmt, const Args &... args) +{ + log_formatted_string({}, fmt.format_string(), fmt.format(args...), LogSeverity::LOG_COMMENT); +} + +template +inline void log_debug(FmtString...> fmt, const Args &... args) +{ + if (!ys_debug(1)) + return; + log_formatted_string({}, fmt.format_string(), fmt.format(args...), LogSeverity::LOG_DEBUG); } void log_formatted_header(RTLIL::Design *design, std::string_view format, std::string str); @@ -163,12 +180,12 @@ inline void log_warning(FmtString...> fmt, const Args &... ar inline void log_formatted_warning_noprefix(std::string str) { - log_formatted_warning("", str); + log_formatted_warning({}, str); } template inline void log_warning_noprefix(FmtString...> fmt, const Args &... args) { - log_formatted_warning("", fmt.format(args...)); + log_formatted_warning({}, fmt.format(args...)); } void log_experimental(const std::string &str); @@ -185,8 +202,6 @@ void log_formatted_file_info(std::string_view filename, int lineno, std::string template void log_file_info(std::string_view filename, int lineno, FmtString...> fmt, const Args &... args) { - if (log_make_debug && !ys_debug(1)) - return; log_formatted_file_info(filename, lineno, fmt.format(args...)); } diff --git a/pyosys/wrappers_tpl.cc b/pyosys/wrappers_tpl.cc index 3fb5263f1..5e35282c0 100644 --- a/pyosys/wrappers_tpl.cc +++ b/pyosys/wrappers_tpl.cc @@ -180,7 +180,7 @@ namespace pyosys { // Logging Methods m.def("log_header", [](Design *d, std::string s) { log_formatted_header(d, "%s", s); }); - m.def("log", [](std::string s) { log_formatted_string("%s", s); }); + m.def("log", [](std::string s) { log_formatted_string({}, "%s", s, LogSeverity::LOG_INFO); }); m.def("log_file_info", [](std::string_view file, int line, std::string s) { log_formatted_file_info(file, line, s); }); m.def("log_warning", [](std::string s) { log_formatted_warning("Warning: ", s); }); m.def("log_warning_noprefix", [](std::string s) { log_formatted_warning("", s); }); diff --git a/tests/unit/kernel/logTest.cc b/tests/unit/kernel/logTest.cc index c24389e94..62b4f3b98 100644 --- a/tests/unit/kernel/logTest.cc +++ b/tests/unit/kernel/logTest.cc @@ -1,4 +1,3 @@ -#include #include #include "kernel/yosys.h" @@ -12,38 +11,4 @@ TEST(KernelLogTest, logvValidValues) EXPECT_EQ(7, 7); } -class TestSink : public LogSink { - public: - void log(const LogMessage& message) override { - messages_.push_back(message); - } - std::vector messages_; -}; - -TEST(KernelLogTest, logToSink) -{ - TestSink sink; - log_sinks.push_back(&sink); - log("test info log"); - log_warning("test warning log"); - - std::vector expected{ - LogMessage(LogSeverity::LOG_INFO, "test info log"), - LogMessage(LogSeverity::LOG_WARNING, "test warning log"), - }; - // Certain calls to the log.h interface may prepend a string to - // the provided string. We should ensure that the expected string - // is a subset of the actual string. Additionally, we don't want to - // compare timestamps. So, we use a custom comparator. - for (const LogMessage& expected_msg : expected) { - EXPECT_THAT(sink.messages_, ::testing::Contains(::testing::Truly( - [&](const LogMessage& actual) { - return actual.severity == expected_msg.severity && - actual.message.find(expected_msg.message) != std::string::npos; - } - ))); - } - EXPECT_NE(sink.messages_[0].timestamp, 0); -} - YOSYS_NAMESPACE_END