Added per-pass cpu usage statistics

diff --git a/kernel/driver.cc b/kernel/driver.cc
index 01ade7d467d66a5f1e6543bfea9506ffd24007bc..273be7ce1c74e266e0b230fd5513b5d2e35912a4 100644 (file)
--- 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 <level>[-t] [-l <logfile>] [-o <outfile>] [-f <frontend>] [-h cmd] \\\n", argv[0]);
+                       fprintf(stderr, "Usage: %s [-V -S -Q -T -q] [-v <level>[-t] [-l <logfile>] [-o <outfile>] [-f <frontend>] [-h cmd] \\\n", argv[0]);
                        fprintf(stderr, "       %*s[{-s|-c} <scriptfile>] [-p <pass> [-p ..]] [-b <backend>] [-m <module_file>] [<infile> [..]]\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<std::tuple<int64_t, int, std::string>> 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 9fc83800c7fb7b8f8247245723882ec245a69da6..8e46ad493acdeecbdb020489f7136886b53db6d8 100644 (file)
--- 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 7469b3e81c8d4e74ef3b0c2bba0f1ead0cf945f4..4d204069c3da768c4220405fe3486137a0290a37 100644 (file)
--- 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<std::string, Frontend*> frontend_register;
 std::map<std::string, Pass*> 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<std::string> 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<std::string> 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, "<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<std::string> 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, "<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 17942ca96afa9bf57e9816087c90feda76683e72..93a3308adb22a856140a2c39bbbd238752b9de17 100644 (file)
--- 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<std::string> 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<std::string> &args);
        void cmd_error(const std::vector<std::string> &args, size_t argidx, std::string msg);
        void extra_args(std::vector<std::string> args, size_t argidx, RTLIL::Design *design, bool select = true);