From 1e224506be6d824ea9ed1855fa46d039e5ffefd5 Mon Sep 17 00:00:00 2001 From: Clifford Wolf Date: Fri, 1 Aug 2014 18:42:10 +0200 Subject: [PATCH] Added per-pass cpu usage statistics --- kernel/driver.cc | 42 +++++++++++++++++++++++++++++++++++++++--- kernel/log.h | 1 + kernel/register.cc | 42 +++++++++++++++++++++++++++++++++++------- kernel/register.h | 13 +++++++++++-- 4 files changed, 86 insertions(+), 12 deletions(-) diff --git a/kernel/driver.cc b/kernel/driver.cc index 01ade7d46..273be7ce1 100644 --- a/kernel/driver.cc +++ b/kernel/driver.cc @@ -43,6 +43,7 @@ int main(int argc, char **argv) bool scriptfile_tcl = false; bool got_output_filename = false; bool print_banner = true; + bool print_stats = true; bool call_abort = false; int history_offset = 0; @@ -54,7 +55,7 @@ int main(int argc, char **argv) } int opt; - while ((opt = getopt(argc, argv, "AQVSm:f:Hh:b:o:p:l:qv:ts:c:")) != -1) + while ((opt = getopt(argc, argv, "AQTVSm:f:Hh:b:o:p:l:qv:ts:c:")) != -1) { switch (opt) { @@ -64,6 +65,9 @@ int main(int argc, char **argv) case 'Q': print_banner = false; break; + case 'T': + print_stats = false; + break; case 'V': printf("%s\n", yosys_version_str); exit(0); @@ -129,12 +133,15 @@ int main(int argc, char **argv) break; default: fprintf(stderr, "\n"); - fprintf(stderr, "Usage: %s [-V -S -Q -q] [-v [-t] [-l ] [-o ] [-f ] [-h cmd] \\\n", argv[0]); + fprintf(stderr, "Usage: %s [-V -S -Q -T -q] [-v [-t] [-l ] [-o ] [-f ] [-h cmd] \\\n", argv[0]); fprintf(stderr, " %*s[{-s|-c} ] [-p [-p ..]] [-b ] [-m ] [ [..]]\n", int(strlen(argv[0])+1), ""); fprintf(stderr, "\n"); fprintf(stderr, " -Q\n"); fprintf(stderr, " suppress printing of banner (copyright, disclaimer, version)\n"); fprintf(stderr, "\n"); + fprintf(stderr, " -T\n"); + fprintf(stderr, " suppress printing of footer (log hash, version, timing statistics)\n"); + fprintf(stderr, "\n"); fprintf(stderr, " -q\n"); fprintf(stderr, " quiet operation. only write error messages to console\n"); fprintf(stderr, "\n"); @@ -284,7 +291,36 @@ int main(int argc, char **argv) } #endif - log("\nEnd of script.\n"); + 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.h b/kernel/log.h index 9fc83800c..8e46ad493 100644 --- a/kernel/log.h +++ b/kernel/log.h @@ -170,6 +170,7 @@ struct PerformanceTimer return total_ns * 1e-9; } #else + static int64_t query() { return 0; } void reset() { } void begin() { } void end() { } diff --git a/kernel/register.cc b/kernel/register.cc index 7469b3e81..4d204069c 100644 --- a/kernel/register.cc +++ b/kernel/register.cc @@ -29,6 +29,7 @@ YOSYS_NAMESPACE_BEGIN bool echo_mode = false; Pass *first_queued_pass; +Pass *current_pass; std::map frontend_register; std::map pass_register; @@ -41,6 +42,7 @@ Pass::Pass(std::string name, std::string short_help) : pass_name(name), short_he next_queued_pass = first_queued_pass; first_queued_pass = this; call_counter = 0; + runtime_ns = 0; } void Pass::run_register() @@ -69,6 +71,25 @@ Pass::~Pass() { } +Pass::pre_post_exec_state_t Pass::pre_execute() +{ + pre_post_exec_state_t state; + call_counter++; + state.begin_ns = PerformanceTimer::query(); + state.parent_pass = current_pass; + current_pass = this; + return state; +} + +void Pass::post_execute(Pass::pre_post_exec_state_t state) +{ + int64_t time_ns = PerformanceTimer::query() - state.begin_ns; + runtime_ns += time_ns; + current_pass = state.parent_pass; + if (current_pass) + current_pass->runtime_ns -= time_ns; +} + void Pass::help() { log("\n"); @@ -183,8 +204,9 @@ void Pass::call(RTLIL::Design *design, std::vector args) log_cmd_error("No such command: %s (type 'help' for a command overview)\n", args[0].c_str()); size_t orig_sel_stack_pos = design->selection_stack.size(); - pass_register[args[0]]->call_counter++; + auto state = pass_register[args[0]]->pre_execute(); pass_register[args[0]]->execute(args, design); + pass_register[args[0]]->post_execute(state); while (design->selection_stack.size() > orig_sel_stack_pos) design->selection_stack.pop_back(); @@ -266,8 +288,9 @@ void Frontend::execute(std::vector args, RTLIL::Design *design) do { FILE *f = NULL; next_args.clear(); - call_counter++; + auto state = pre_execute(); execute(f, std::string(), args, design); + post_execute(state); args = next_args; fclose(f); } while (!args.empty()); @@ -359,12 +382,14 @@ void Frontend::frontend_call(RTLIL::Design *design, FILE *f, std::string filenam log_cmd_error("No such frontend: %s\n", args[0].c_str()); if (f != NULL) { - frontend_register[args[0]]->call_counter++; + auto state = frontend_register[args[0]]->pre_execute(); frontend_register[args[0]]->execute(f, filename, args, design); + frontend_register[args[0]]->post_execute(state); } else if (filename == "-") { FILE *f_stdin = stdin; // workaround for OpenBSD 'stdin' implementation - frontend_register[args[0]]->call_counter++; + auto state = frontend_register[args[0]]->pre_execute(); frontend_register[args[0]]->execute(f_stdin, "", args, design); + frontend_register[args[0]]->post_execute(state); } else { if (!filename.empty()) args.push_back(filename); @@ -396,8 +421,9 @@ Backend::~Backend() void Backend::execute(std::vector args, RTLIL::Design *design) { FILE *f = NULL; - call_counter++; + auto state = pre_execute(); execute(f, std::string(), args, design); + post_execute(state); if (f != stdout) fclose(f); } @@ -458,12 +484,14 @@ void Backend::backend_call(RTLIL::Design *design, FILE *f, std::string filename, size_t orig_sel_stack_pos = design->selection_stack.size(); if (f != NULL) { - backend_register[args[0]]->call_counter++; + auto state = backend_register[args[0]]->pre_execute(); backend_register[args[0]]->execute(f, filename, args, design); + backend_register[args[0]]->post_execute(state); } else if (filename == "-") { FILE *f_stdout = stdout; // workaround for OpenBSD 'stdout' implementation - backend_register[args[0]]->call_counter++; + auto state = backend_register[args[0]]->pre_execute(); backend_register[args[0]]->execute(f_stdout, "", args, design); + backend_register[args[0]]->post_execute(state); } else { if (!filename.empty()) args.push_back(filename); diff --git a/kernel/register.h b/kernel/register.h index 17942ca96..93a3308ad 100644 --- a/kernel/register.h +++ b/kernel/register.h @@ -31,14 +31,23 @@ YOSYS_NAMESPACE_BEGIN struct Pass { std::string pass_name, short_help; - int call_counter; - Pass(std::string name, std::string short_help = "** document me **"); virtual ~Pass(); virtual void help(); virtual void execute(std::vector args, RTLIL::Design *design) = 0; + int call_counter; + int64_t runtime_ns; + + struct pre_post_exec_state_t { + Pass *parent_pass; + int64_t begin_ns; + }; + + pre_post_exec_state_t pre_execute(); + void post_execute(pre_post_exec_state_t state); + void cmd_log_args(const std::vector &args); void cmd_error(const std::vector &args, size_t argidx, std::string msg); void extra_args(std::vector args, size_t argidx, RTLIL::Design *design, bool select = true); -- 2.30.2