luke
/
yosys
mirror of https://github.com/YosysHQ/yosys.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

log: Refactor code a bit more

This commit is contained in:
Miodrag Milanovic 2026-08-13 09:22:01 +02:00
parent 8d6be2467b
commit 14afc00862
4 changed files with 80 additions and 129 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

125
kernel/log.cc
View File

@ -40,7 +40,6 @@ YOSYS_NAMESPACE_BEGIN
std::vector<FILE*> log_files;
std::vector<std::ostream*> log_streams;
std::vector<LogSink*> log_sinks;
std::vector<std::string> log_scratchpads;
std::map<std::string, std::set<std::string>> log_hdump;
std::vector<std::regex> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
@ -70,7 +69,7 @@ int log_debug_suppressed = 0;
vector<int> header_count;
vector<char*> log_id_cache;
static struct timeval initial_tv = { 0, 0 };
static std::optional<std::chrono::steady_clock::time_point> 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<std::chrono::microseconds>(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 = "<suppressed ~%d debug messages>\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)

47
kernel/log.h
View File

@ -22,6 +22,7 @@
#include "kernel/yosys_common.h"
#include <chrono>
#include <time.h>
#include <regex>
@ -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<FILE*> log_files;
extern std::vector<std::ostream*> log_streams;
extern std::vector<LogSink*> log_sinks;
extern std::vector<std::string> log_scratchpads;
extern std::map<std::string, std::set<std::string>> log_hdump;
extern std::vector<std::regex> 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 <typename... Args>
inline void log(FmtString<TypeIdentity<Args>...> 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 <typename... Args>
inline void log_comment(FmtString<TypeIdentity<Args>...> fmt, const Args &... args)
{
log_formatted_string({}, fmt.format_string(), fmt.format(args...), LogSeverity::LOG_COMMENT);
}
template <typename... Args>
inline void log_debug(FmtString<TypeIdentity<Args>...> 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<TypeIdentity<Args>...> fmt, const Args &... ar
inline void log_formatted_warning_noprefix(std::string str)
{
log_formatted_warning("", str);
log_formatted_warning({}, str);
}
template <typename... Args>
inline void log_warning_noprefix(FmtString<TypeIdentity<Args>...> 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 <typename... Args>
void log_file_info(std::string_view filename, int lineno, FmtString<TypeIdentity<Args>...> fmt, const Args &... args)
{
if (log_make_debug && !ys_debug(1))
return;
log_formatted_file_info(filename, lineno, fmt.format(args...));
}

2
pyosys/wrappers_tpl.cc
View File

@ -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); });

35
tests/unit/kernel/logTest.cc
View File

@ -1,4 +1,3 @@
#include <gmock/gmock.h>
#include <gtest/gtest.h>
#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<LogMessage> messages_;
};
TEST(KernelLogTest, logToSink)
{
TestSink sink;
log_sinks.push_back(&sink);
log("test info log");
log_warning("test warning log");
std::vector<LogMessage> 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