Added per-pass cpu usage statistics

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();
 

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() { }

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);

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);