From 75ffd1643c97321255bc591edf0c1a7097b8dce9 Mon Sep 17 00:00:00 2001 From: Clifford Wolf Date: Fri, 1 Aug 2014 19:43:28 +0200 Subject: [PATCH] Added logfile hash to statistics footer --- kernel/driver.cc | 70 ++++++++++++++++++++++++++---------------------- kernel/log.cc | 36 ++++++++++++++++--------- kernel/log.h | 2 ++ kernel/yosys.cc | 16 +++++++++-- kernel/yosys.h | 2 ++ 5 files changed, 80 insertions(+), 46 deletions(-) diff --git a/kernel/driver.cc b/kernel/driver.cc index 273be7ce1..6f9764238 100644 --- a/kernel/driver.cc +++ b/kernel/driver.cc @@ -18,6 +18,7 @@ */ #include "kernel/yosys.h" +#include "libs/sha1/sha1.h" #include #include @@ -233,6 +234,9 @@ int main(int argc, char **argv) log("\n"); } + if (print_stats) + log_hasher = new SHA1; + yosys_setup(); if (optind == argc && passes_commands.size() == 0 && scriptfile.empty()) { @@ -262,8 +266,40 @@ int main(int argc, char **argv) if (!backend_command.empty()) run_backend(output_filename, backend_command, yosys_design); - delete yosys_design; - yosys_design = NULL; + if (print_stats) + { + std::string hash = log_hasher->final().substr(0, 10); + delete log_hasher; + log_hasher = nullptr; + + struct rusage ru_buffer; + getrusage(RUSAGE_SELF, &ru_buffer); + log("\nEnd of script. Logfile hash: %s, CPU: user %.2fs system %.2fs\n", hash.c_str(), + ru_buffer.ru_utime.tv_sec + 1e-6 * ru_buffer.ru_utime.tv_usec, + ru_buffer.ru_stime.tv_sec + 1e-6 * ru_buffer.ru_stime.tv_usec); + log("%s\n", yosys_version_str); + + int64_t total_ns = 0; + std::set> timedat; + + for (auto &it : pass_register) + if (it.second->call_counter) { + total_ns += it.second->runtime_ns + 1; + timedat.insert(make_tuple(it.second->runtime_ns + 1, it.second->call_counter, it.first)); + } + + int out_count = 0; + log("Time spent:"); + for (auto it = timedat.rbegin(); it != timedat.rend() && out_count < 4; it++, out_count++) { + if (out_count >= 2 && (std::get<0>(*it) < 1000000000 || int(100*std::get<0>(*it) / total_ns) < 20)) { + log(", ..."); + break; + } + log("%s %d%% %dx %s (%d sec)", out_count ? "," : "", int(100*std::get<0>(*it) / total_ns), + std::get<1>(*it), std::get<2>(*it).c_str(), int(std::get<0>(*it) / 1000000000)); + } + log("%s\n", out_count ? "" : " no commands executed"); + } #ifdef COVER_ACTIVE if (getenv("YOSYS_COVER_DIR") || getenv("YOSYS_COVER_FILE")) @@ -291,36 +327,6 @@ int main(int argc, char **argv) } #endif - if (print_stats) - { - struct rusage ru_buffer; - getrusage(RUSAGE_SELF, &ru_buffer); - log("\nEnd of script. Logfile hash: xxxxxxxxxx, CPU: user %.2fs system %.2fs\n", - ru_buffer.ru_utime.tv_sec + 1e-6 * ru_buffer.ru_utime.tv_usec, - ru_buffer.ru_stime.tv_sec + 1e-6 * ru_buffer.ru_stime.tv_usec); - log("%s\nTime spent:", yosys_version_str); - - int64_t total_ns = 0; - std::set> timedat; - - for (auto &it : pass_register) - if (it.second->call_counter) { - total_ns += it.second->runtime_ns + 1; - timedat.insert(make_tuple(it.second->runtime_ns + 1, it.second->call_counter, it.first)); - } - - int out_count = 0; - for (auto it = timedat.rbegin(); it != timedat.rend() && out_count < 4; it++, out_count++) { - if (out_count >= 2 && (std::get<0>(*it) < 1000000000 || int(100*std::get<0>(*it) / total_ns) < 20)) { - log(", ..."); - break; - } - log("%s %d%% %dx %s (%d sec)", out_count ? "," : "", int(100*std::get<0>(*it) / total_ns), - std::get<1>(*it), std::get<2>(*it).c_str(), int(std::get<0>(*it) / 1000000000)); - } - log("%s\n", out_count ? "" : " no commands executed"); - } - if (call_abort) abort(); diff --git a/kernel/log.cc b/kernel/log.cc index 64dd7a92a..10eb2563c 100644 --- a/kernel/log.cc +++ b/kernel/log.cc @@ -18,6 +18,7 @@ */ #include "kernel/yosys.h" +#include "libs/sha1/sha1.h" #include "backends/ilang/ilang_backend.h" #include @@ -32,6 +33,8 @@ YOSYS_NAMESPACE_BEGIN std::vector log_files; FILE *log_errfile = NULL; +SHA1 *log_hasher = NULL; + bool log_time = false; bool log_cmd_error_throw = false; int log_verbose_level; @@ -44,11 +47,20 @@ static bool next_print_log = false; void logv(const char *format, va_list ap) { - if (log_time) { - while (format[0] == '\n' && format[1] != 0) { - format++; - log("\n"); - } + while (format[0] == '\n' && format[1] != 0) { + log("\n"); + format++; + } + + std::string str = vstringf(format, ap); + + 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; @@ -61,18 +73,18 @@ void logv(const char *format, va_list ap) } tv.tv_sec -= initial_tv.tv_sec; tv.tv_usec -= initial_tv.tv_usec; - log("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec)); + time_str += stringf("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec)); } + if (format[0] && format[strlen(format)-1] == '\n') next_print_log = true; + + for (auto f : log_files) + fputs(time_str.c_str(), f); } - for (auto f : log_files) { - va_list aq; - va_copy(aq, ap); - vfprintf(f, format, aq); - va_end(aq); - } + for (auto f : log_files) + fputs(str.c_str(), f); } void logv_header(const char *format, va_list ap) diff --git a/kernel/log.h b/kernel/log.h index 8e46ad493..2e968039f 100644 --- a/kernel/log.h +++ b/kernel/log.h @@ -38,6 +38,8 @@ struct log_cmd_error_expection { }; extern std::vector log_files; extern FILE *log_errfile; +extern class SHA1 *log_hasher; + extern bool log_time; extern bool log_cmd_error_throw; extern int log_verbose_level; diff --git a/kernel/yosys.cc b/kernel/yosys.cc index 671945631..89a9cdf7f 100644 --- a/kernel/yosys.cc +++ b/kernel/yosys.cc @@ -37,13 +37,22 @@ Tcl_Interp *yosys_tcl_interp = NULL; std::string stringf(const char *fmt, ...) { std::string string; - char *str = NULL; va_list ap; va_start(ap, fmt); + string = vstringf(fmt, ap); + va_end(ap); + + return string; +} + +std::string vstringf(const char *fmt, va_list ap) +{ + std::string string; + char *str = NULL; + if (vasprintf(&str, fmt, ap) < 0) str = NULL; - va_end(ap); if (str != NULL) { string = str; @@ -71,6 +80,9 @@ void yosys_shutdown() { log_pop(); + delete yosys_design; + yosys_design = NULL; + for (auto f : log_files) if (f != stderr) fclose(f); diff --git a/kernel/yosys.h b/kernel/yosys.h index d9db57c51..e90dcc46e 100644 --- a/kernel/yosys.h +++ b/kernel/yosys.h @@ -43,6 +43,7 @@ #include #include #include +#include #define PRIVATE_NAMESPACE_BEGIN namespace { #define PRIVATE_NAMESPACE_END } @@ -68,6 +69,7 @@ namespace RTLIL { } std::string stringf(const char *fmt, ...); +std::string vstringf(const char *fmt, va_list ap); template int SIZE(const T &obj) { return obj.size(); } int SIZE(RTLIL::Wire *wire);