Skip to content

Commit

Permalink
Merge pull request YosysHQ#138 from YosysHQ/refactor_log
Browse files Browse the repository at this point in the history 
Tidy up logging code, add log file support, make timing failures non-fatal errors
  • Loading branch information
@gatecat
gatecat authored Nov 26, 2018
2 parents 98858fe + b035cb9 commit 22ac41d
Show file tree
Hide file tree
Showing 8 changed files with 84 additions and 123 deletions.
26 changes: 19 additions & 7 deletions common/command.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,7 @@

NEXTPNR_NAMESPACE_BEGIN

CommandHandler::CommandHandler(int argc, char **argv) : argc(argc), argv(argv) { log_files.push_back(stdout); }
CommandHandler::CommandHandler(int argc, char **argv) : argc(argc), argv(argv) { log_streams.clear(); }

bool CommandHandler::parseOptions()
{
Expand All @@ -64,14 +64,14 @@ bool CommandHandler::parseOptions()
bool CommandHandler::executeBeforeContext()
{
if (vm.count("help") || argc == 1) {
std::cout << boost::filesystem::basename(argv[0])
std::cerr << boost::filesystem::basename(argv[0])
<< " -- Next Generation Place and Route (git sha1 " GIT_COMMIT_HASH_STR ")\n";
std::cout << options << "\n";
std::cerr << options << "\n";
return argc != 1;
}

if (vm.count("version")) {
std::cout << boost::filesystem::basename(argv[0])
std::cerr << boost::filesystem::basename(argv[0])
<< " -- Next Generation Place and Route (git sha1 " GIT_COMMIT_HASH_STR ")\n";
return true;
}
Expand All @@ -84,7 +84,9 @@ po::options_description CommandHandler::getGeneralOptions()
po::options_description general("General options");
general.add_options()("help,h", "show help");
general.add_options()("verbose,v", "verbose output");
general.add_options()("quiet,q", "quiet mode, only errors displayed");
general.add_options()("quiet,q", "quiet mode, only errors and warnings displayed");
general.add_options()("log,l", po::value<std::string>(),
"log file, all log messages are written to this file regardless of -q");
general.add_options()("debug", "debug output");
general.add_options()("force,f", "keep running after errors");
#ifndef NO_GUI
Expand Down Expand Up @@ -128,7 +130,17 @@ void CommandHandler::setupContext(Context *ctx)
}

if (vm.count("quiet")) {
log_quiet_warnings = true;
log_streams.push_back(std::make_pair(&std::cerr, LogLevel::WARNING));
} else {
log_streams.push_back(std::make_pair(&std::cerr, LogLevel::LOG));
}

if (vm.count("log")) {
std::string logfilename = vm["log"].as<std::string>();
logfile = std::ofstream(logfilename);
if (!logfile)
log_error("Failed to open log file '%s' for writing.\n", logfilename.c_str());
log_streams.push_back(std::make_pair(&logfile, LogLevel::LOG));
}

if (vm.count("force")) {
Expand Down Expand Up @@ -258,7 +270,7 @@ int CommandHandler::executeMain(std::unique_ptr<Context> ctx)
deinit_python();
#endif

return 0;
return had_nonfatal_error ? 1 : 0;
}

void CommandHandler::conflicting_options(const boost::program_options::variables_map &vm, const char *opt1,
Expand Down
1 change: 1 addition & 0 deletions common/command.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,7 @@ class CommandHandler
int argc;
char **argv;
ProjectHandler project;
std::ofstream logfile;
};

NEXTPNR_NAMESPACE_END
Expand Down
123 changes: 32 additions & 91 deletions common/log.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,19 +32,14 @@ NEXTPNR_NAMESPACE_BEGIN

NPNR_NORETURN void logv_error(const char *format, va_list ap) NPNR_ATTRIBUTE(noreturn);

std::vector<FILE *> log_files;
std::vector<std::ostream *> log_streams;
FILE *log_errfile = NULL;
std::vector<std::pair<std::ostream *, LogLevel>> log_streams;
log_write_type log_write_function = nullptr;

bool log_error_stderr = false;
bool log_cmd_error_throw = false;
bool log_quiet_warnings = false;
std::string log_last_error;
void (*log_error_atexit)() = NULL;

// static bool next_print_log = false;
static int log_newline_count = 0;
bool had_nonfatal_error = false;

std::string stringf(const char *fmt, ...)
{
Expand Down Expand Up @@ -88,7 +83,7 @@ std::string vstringf(const char *fmt, va_list ap)
return string;
}

void logv(const char *format, va_list ap)
void logv(const char *format, va_list ap, LogLevel level = LogLevel::LOG)
{
//
// Trim newlines from the beginning
Expand All @@ -108,148 +103,94 @@ void logv(const char *format, va_list ap)
else
log_newline_count = str.size() - nnl_pos - 1;

for (auto f : log_files)
fputs(str.c_str(), f);

for (auto f : log_streams)
*f << str;
if (f.second <= level)
*f.first << str;
if (log_write_function)
log_write_function(str);
}

void logv_info(const char *format, va_list ap)
void log_with_level(LogLevel level, const char *format, ...)
{
std::string message = vstringf(format, ap);

log_always("Info: %s", message.c_str());
log_flush();
va_list ap;
va_start(ap, format);
logv(format, ap, level);
va_end(ap);
}

void logv_warning(const char *format, va_list ap)
void logv_prefixed(const char *prefix, const char *format, va_list ap, LogLevel level)
{
std::string message = vstringf(format, ap);

log_always("Warning: %s", message.c_str());
log_with_level(level, "%s%s", prefix, message.c_str());
log_flush();
}

void logv_warning_noprefix(const char *format, va_list ap)
{
std::string message = vstringf(format, ap);

log_always("%s", message.c_str());
}

void logv_error(const char *format, va_list ap)
{
#ifdef EMSCRIPTEN
auto backup_log_files = log_files;
#endif

if (log_errfile != NULL)
log_files.push_back(log_errfile);

if (log_error_stderr)
for (auto &f : log_files)
if (f == stdout)
f = stderr;

log_last_error = vstringf(format, ap);
log_always("ERROR: %s", log_last_error.c_str());
log_flush();

if (log_error_atexit)
log_error_atexit();

#ifdef EMSCRIPTEN
log_files = backup_log_files;
#endif
throw log_execution_error_exception();
}

void log_always(const char *format, ...)
{
va_list ap;
va_start(ap, format);
logv(format, ap);
logv(format, ap, LogLevel::ALWAYS);
va_end(ap);
}

void log(const char *format, ...)
{
if (log_quiet_warnings)
return;
va_list ap;
va_start(ap, format);
logv(format, ap);
logv(format, ap, LogLevel::LOG);
va_end(ap);
}

void log_info(const char *format, ...)
{
if (log_quiet_warnings)
return;
va_list ap;
va_start(ap, format);
logv_info(format, ap);
logv_prefixed("Info: ", format, ap, LogLevel::INFO);
va_end(ap);
}

void log_warning(const char *format, ...)
{
va_list ap;
va_start(ap, format);
logv_warning(format, ap);
va_end(ap);
}

void log_warning_noprefix(const char *format, ...)
{
va_list ap;
va_start(ap, format);
logv_warning_noprefix(format, ap);
logv_prefixed("Warning: ", format, ap, LogLevel::WARNING);
va_end(ap);
}

void log_error(const char *format, ...)
{
va_list ap;
va_start(ap, format);
logv_error(format, ap);
}

void log_cmd_error(const char *format, ...)
{
va_list ap;
va_start(ap, format);
logv_prefixed("ERROR: ", format, ap, LogLevel::ERROR);

if (log_cmd_error_throw) {
log_last_error = vstringf(format, ap);
log_always("ERROR: %s", log_last_error.c_str());
log_flush();
throw log_cmd_error_exception();
}
if (log_error_atexit)
log_error_atexit();

logv_error(format, ap);
throw log_execution_error_exception();
}

void log_break()
{
if (log_quiet_warnings)
return;
if (log_newline_count < 2)
log_always("\n");
log("\n");
if (log_newline_count < 2)
log_always("\n");
log("\n");
}

void log_flush()
void log_nonfatal_error(const char *format, ...)
{
for (auto f : log_files)
fflush(f);
va_list ap;
va_start(ap, format);
logv_prefixed("ERROR: ", format, ap, LogLevel::ERROR);
va_end(ap);
had_nonfatal_error = true;
}

void log_flush()
{
for (auto f : log_streams)
f->flush();
f.first->flush();
}

NEXTPNR_NAMESPACE_END
20 changes: 12 additions & 8 deletions common/log.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,14 +42,21 @@ struct log_execution_error_exception
{
};

extern std::vector<FILE *> log_files;
extern std::vector<std::ostream *> log_streams;
extern FILE *log_errfile;
enum class LogLevel
{
LOG,
INFO,
WARNING,
ERROR,
ALWAYS
};

extern std::vector<std::pair<std::ostream *, LogLevel>> log_streams;
extern log_write_type log_write_function;

extern bool log_quiet_warnings;
extern std::string log_last_error;
extern void (*log_error_atexit)();
extern bool had_nonfatal_error;

std::string stringf(const char *fmt, ...);
std::string vstringf(const char *fmt, va_list ap);
Expand All @@ -59,10 +66,8 @@ void log(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
void log_always(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
void log_info(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
void log_warning(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
void log_warning_noprefix(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
NPNR_NORETURN void log_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2), noreturn);
NPNR_NORETURN void log_cmd_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2), noreturn);

void log_nonfatal_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
void log_break();
void log_flush();

Expand All @@ -75,7 +80,6 @@ static inline void log_assert_worker(bool cond, const char *expr, const char *fi
NEXTPNR_NAMESPACE_PREFIX log_assert_worker(_assert_expr_, #_assert_expr_, __FILE__, __LINE__)

#define log_abort() log_error("Abort in %s:%d.\n", __FILE__, __LINE__)
#define log_ping() log("-- %s:%d %s --\n", __FILE__, __LINE__, __PRETTY_FUNCTION__)

NEXTPNR_NAMESPACE_END

Expand Down
3 changes: 2 additions & 1 deletion common/router1.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -812,7 +812,8 @@ bool router1(Context *ctx, const Router1Cfg &cfg)
#endif

log_info("Checksum: 0x%08x\n", ctx->checksum());
timing_analysis(ctx, true /* slack_histogram */, true /* print_fmax */, true /* print_path */);
timing_analysis(ctx, true /* slack_histogram */, true /* print_fmax */, true /* print_path */,
true /* warn_on_failure */);

ctx->unlock();
return true;
Expand Down
30 changes: 16 additions & 14 deletions common/timing.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -485,11 +485,11 @@ void assign_budget(Context *ctx, bool quiet)
for (auto &user : net.second->users) {
// Post-update check
if (!ctx->auto_freq && user.budget < 0)
log_warning("port %s.%s, connected to net '%s', has negative "
"timing budget of %fns\n",
user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
ctx->getDelayNS(user.budget));
else if (ctx->verbose)
log_info("port %s.%s, connected to net '%s', has negative "
"timing budget of %fns\n",
user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
ctx->getDelayNS(user.budget));
else if (ctx->debug)
log_info("port %s.%s, connected to net '%s', has "
"timing budget of %fns\n",
user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
Expand All @@ -513,7 +513,7 @@ void assign_budget(Context *ctx, bool quiet)
log_info("Checksum: 0x%08x\n", ctx->checksum());
}

void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool print_path)
void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool print_path, bool warn_on_failure)
{
auto format_event = [ctx](const ClockEvent &e, int field_width = 0) {
std::string value;
Expand Down Expand Up @@ -705,15 +705,17 @@ void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool p
for (auto &clock : clock_reports) {
const auto &clock_name = clock.first.str(ctx);
const int width = max_width - clock_name.size();
if (ctx->nets.at(clock.first)->clkconstr) {
float target = 1000 / ctx->getDelayNS(ctx->nets.at(clock.first)->clkconstr->period.minDelay());
float target = ctx->target_freq / 1e6;
if (ctx->nets.at(clock.first)->clkconstr)
target = 1000 / ctx->getDelayNS(ctx->nets.at(clock.first)->clkconstr->period.minDelay());

bool passed = target < clock_fmax[clock.first];
if (!warn_on_failure || passed)
log_info("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "",
clock_name.c_str(), clock_fmax[clock.first],
(target < clock_fmax[clock.first]) ? "PASS" : "FAIL", target);
} else {
log_info("Max frequency for clock %*s'%s': %.02f MHz\n", width, "", clock_name.c_str(),
clock_fmax[clock.first]);
}
clock_name.c_str(), clock_fmax[clock.first], passed ? "PASS" : "FAIL", target);
else
log_nonfatal_error("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "",
clock_name.c_str(), clock_fmax[clock.first], passed ? "PASS" : "FAIL", target);
}
for (auto &eclock : empty_clocks) {
if (eclock != ctx->id("$async$"))
Expand Down
Loading

0 comments on commit 22ac41d

Please sign in to comment.