From b550791d9279416525d0de48d22989bcf5397535 Mon Sep 17 00:00:00 2001 From: David Shah Date: Wed, 21 Nov 2018 17:08:45 +0000 Subject: Refactor log code and add log file support Signed-off-by: David Shah --- common/command.cc | 26 +++++++++---- common/command.h | 1 + common/log.cc | 113 +++++++++++------------------------------------------- common/log.h | 17 ++++---- gui/basewindow.cc | 1 - 5 files changed, 52 insertions(+), 106 deletions(-) diff --git a/common/command.cc b/common/command.cc index 5070bf9c..fd634df4 100644 --- a/common/command.cc +++ b/common/command.cc @@ -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() { @@ -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; } @@ -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(), + "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 @@ -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(); + 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")) { @@ -144,7 +156,7 @@ void CommandHandler::setupContext(Context *ctx) int r; do { r = rand(); - } while(r == 0); + } while (r == 0); ctx->rngseed(r); } diff --git a/common/command.h b/common/command.h index 12f710f6..30e0e58b 100644 --- a/common/command.h +++ b/common/command.h @@ -66,6 +66,7 @@ class CommandHandler int argc; char **argv; ProjectHandler project; + std::ofstream logfile; }; NEXTPNR_NAMESPACE_END diff --git a/common/log.cc b/common/log.cc index 6b2d6065..19873148 100644 --- a/common/log.cc +++ b/common/log.cc @@ -32,18 +32,12 @@ NEXTPNR_NAMESPACE_BEGIN NPNR_NORETURN void logv_error(const char *format, va_list ap) NPNR_ATTRIBUTE(noreturn); -std::vector log_files; -std::vector log_streams; -FILE *log_errfile = NULL; +std::vector> 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; std::string stringf(const char *fmt, ...) @@ -88,7 +82,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 @@ -108,90 +102,50 @@ 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); } @@ -199,15 +153,7 @@ 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); } @@ -215,41 +161,26 @@ void log_error(const char *format, ...) { va_list ap; va_start(ap, format); - logv_error(format, ap); -} + logv_prefixed("ERROR: ", format, ap, LogLevel::ERROR); -void log_cmd_error(const char *format, ...) -{ - va_list ap; - va_start(ap, format); - - 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() { - for (auto f : log_files) - fflush(f); - for (auto f : log_streams) - f->flush(); + f.first->flush(); } NEXTPNR_NAMESPACE_END diff --git a/common/log.h b/common/log.h index b5fddf53..de5aa85c 100644 --- a/common/log.h +++ b/common/log.h @@ -42,12 +42,18 @@ struct log_execution_error_exception { }; -extern std::vector log_files; -extern std::vector log_streams; -extern FILE *log_errfile; +enum class LogLevel +{ + LOG, + INFO, + WARNING, + ERROR, + ALWAYS +}; + +extern std::vector> 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)(); @@ -59,9 +65,7 @@ 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_break(); void log_flush(); @@ -75,7 +79,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 diff --git a/gui/basewindow.cc b/gui/basewindow.cc index 92812285..49c2d8d5 100644 --- a/gui/basewindow.cc +++ b/gui/basewindow.cc @@ -44,7 +44,6 @@ BaseMainWindow::BaseMainWindow(std::unique_ptr context, ArchArgs args, initBasenameResource(); qRegisterMetaType(); - log_files.clear(); log_streams.clear(); setObjectName("BaseMainWindow"); -- cgit v1.2.3 From 51d1363dfeb7005ec35a2acd10fe9ae2cd8631d5 Mon Sep 17 00:00:00 2001 From: David Shah Date: Wed, 21 Nov 2018 17:13:53 +0000 Subject: Change the log level of some timing-related messages Signed-off-by: David Shah --- common/router1.cc | 3 ++- common/timing.cc | 30 ++++++++++++++++-------------- common/timing.h | 3 ++- 3 files changed, 20 insertions(+), 16 deletions(-) diff --git a/common/router1.cc b/common/router1.cc index a3388fa8..8d19797b 100644 --- a/common/router1.cc +++ b/common/router1.cc @@ -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; diff --git a/common/timing.cc b/common/timing.cc index 80be554c..afe14e21 100644 --- a/common/timing.cc +++ b/common/timing.cc @@ -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), @@ -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; @@ -689,15 +689,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_warning("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$")) diff --git a/common/timing.h b/common/timing.h index 1fd76310..42f928dc 100644 --- a/common/timing.h +++ b/common/timing.h @@ -29,7 +29,8 @@ void assign_budget(Context *ctx, bool quiet = false); // Perform timing analysis and print out the fmax, and optionally the // critical path -void timing_analysis(Context *ctx, bool slack_histogram = true, bool print_fmax = true, bool print_path = false); +void timing_analysis(Context *ctx, bool slack_histogram = true, bool print_fmax = true, bool print_path = false, + bool warn_on_failure = false); NEXTPNR_NAMESPACE_END -- cgit v1.2.3 From b035cb9fcf3502c74c769560f02e29adcafe6fd8 Mon Sep 17 00:00:00 2001 From: David Shah Date: Mon, 26 Nov 2018 09:22:42 +0000 Subject: Add nonfatal error support and use for timing failures Signed-off-by: David Shah --- common/command.cc | 2 +- common/log.cc | 10 ++++++++++ common/log.h | 3 ++- common/timing.cc | 2 +- 4 files changed, 14 insertions(+), 3 deletions(-) diff --git a/common/command.cc b/common/command.cc index fd634df4..6cc9fbe7 100644 --- a/common/command.cc +++ b/common/command.cc @@ -270,7 +270,7 @@ int CommandHandler::executeMain(std::unique_ptr 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, diff --git a/common/log.cc b/common/log.cc index 19873148..82e09fec 100644 --- a/common/log.cc +++ b/common/log.cc @@ -39,6 +39,7 @@ std::string log_last_error; void (*log_error_atexit)() = NULL; static int log_newline_count = 0; +bool had_nonfatal_error = false; std::string stringf(const char *fmt, ...) { @@ -177,6 +178,15 @@ void log_break() log("\n"); } +void log_nonfatal_error(const char *format, ...) +{ + 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) diff --git a/common/log.h b/common/log.h index de5aa85c..f1727ac6 100644 --- a/common/log.h +++ b/common/log.h @@ -56,6 +56,7 @@ extern log_write_type log_write_function; 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); @@ -66,7 +67,7 @@ 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)); NPNR_NORETURN void log_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(); diff --git a/common/timing.cc b/common/timing.cc index afe14e21..8bbf2bca 100644 --- a/common/timing.cc +++ b/common/timing.cc @@ -698,7 +698,7 @@ void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool p log_info("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); else - log_warning("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "", + 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) { -- cgit v1.2.3