From 3c07e3725d6a4f002cb3e246cf707ffda73f9a96 Mon Sep 17 00:00:00 2001
From: Mikko Rasa <tdb@tdb.fi>
Date: Mon, 9 Jan 2023 11:17:17 +0200
Subject: [PATCH] Report timings of the build

---
 source/lib/builder.cpp      | 12 ++++++++++++
 source/lib/externaltask.cpp |  2 +-
 source/lib/internaltask.cpp |  2 +-
 source/lib/task.cpp         | 10 ++++++++++
 source/lib/task.h           | 12 ++++++++++++
 5 files changed, 36 insertions(+), 2 deletions(-)

diff --git a/source/lib/builder.cpp b/source/lib/builder.cpp
index 08e9cd7..3379f2d 100644
--- a/source/lib/builder.cpp
+++ b/source/lib/builder.cpp
@@ -282,6 +282,7 @@ void Builder::save_caches()
 int Builder::build(unsigned jobs, bool dry_run, bool show_progress)
 {
 	unsigned total = build_graph.count_rebuild_targets();
+	Time::TimeStamp start_time = Time::now();
 
 	if(!total)
 	{
@@ -293,6 +294,7 @@ int Builder::build(unsigned jobs, bool dry_run, bool show_progress)
 	vector<Task *> tasks;
 
 	unsigned count = 0;
+	Time::TimeDelta sum_time;
 
 	bool fail = false;
 	bool finish = false;
@@ -350,6 +352,13 @@ int Builder::build(unsigned jobs, bool dry_run, bool show_progress)
 			{
 				++count;
 
+				const vector<const FileTarget *> &targets = tasks[i]->get_targets();
+				if(!targets.empty())
+				{
+					sum_time += tasks[i]->get_duration();
+					get_logger().log("timings", "%s built in %s", targets.front()->get_name(), tasks[i]->get_duration());
+				}
+
 				delete tasks[i];
 				tasks.erase(tasks.begin()+i);
 				if(status==Task::ERROR)
@@ -370,6 +379,9 @@ int Builder::build(unsigned jobs, bool dry_run, bool show_progress)
 	else if(show_progress)
 		get_logger().log("summary", "Build complete");
 
+	Time::TimeStamp end_time = Time::now();
+	get_logger().log("timings", "Build took %s, with a total %s spent on tasks", end_time-start_time, sum_time);
+
 	return fail;
 }
 
diff --git a/source/lib/externaltask.cpp b/source/lib/externaltask.cpp
index 37a36d3..ce81ac1 100644
--- a/source/lib/externaltask.cpp
+++ b/source/lib/externaltask.cpp
@@ -150,7 +150,7 @@ Task::Status ExternalTask::do_wait(bool block)
 				return RUNNING;
 		}
 		else
-			signal_finished.emit(!exit_code);
+			finished(!exit_code);
 	}
 
 	return exit_code ? ERROR : SUCCESS;
diff --git a/source/lib/internaltask.cpp b/source/lib/internaltask.cpp
index fc929ce..fe3ae9d 100644
--- a/source/lib/internaltask.cpp
+++ b/source/lib/internaltask.cpp
@@ -15,7 +15,7 @@ Task::Status InternalTask::check()
 {
 	Status result = worker.get_status();
 	if(result!=RUNNING)
-		signal_finished.emit(result==SUCCESS);
+		finished(result==SUCCESS);
 	return result;
 }
 
diff --git a/source/lib/task.cpp b/source/lib/task.cpp
index 870e068..ed79e56 100644
--- a/source/lib/task.cpp
+++ b/source/lib/task.cpp
@@ -1,6 +1,7 @@
 #include <msp/fs/dir.h>
 #include <msp/fs/stat.h>
 #include <msp/fs/utils.h>
+#include <msp/time/utils.h>
 #include "filetarget.h"
 #include "task.h"
 
@@ -19,6 +20,8 @@ void Task::set_unlink(bool u)
 
 void Task::prepare()
 {
+	start_time = Time::now();
+
 	for(const FileTarget *t: targets)
 	{
 		const FS::Path &f = t->get_path();
@@ -35,3 +38,10 @@ void Task::prepare()
 		}
 	}
 }
+
+void Task::finished(bool success)
+{
+	if(!duration && start_time)
+		duration = Time::now()-start_time;
+	signal_finished.emit(success);
+}
diff --git a/source/lib/task.h b/source/lib/task.h
index 3520a91..e493e3b 100644
--- a/source/lib/task.h
+++ b/source/lib/task.h
@@ -4,6 +4,8 @@
 #include <string>
 #include <vector>
 #include <sigc++/signal.h>
+#include <msp/time/timedelta.h>
+#include <msp/time/timestamp.h>
 #include "libbuilder_api.h"
 
 class FileTarget;
@@ -28,6 +30,8 @@ public:
 protected:
 	std::vector<const FileTarget *> targets;
 	bool unlink = false;
+	Msp::Time::TimeStamp start_time;
+	Msp::Time::TimeDelta duration;
 
 	Task() = default;
 public:
@@ -40,6 +44,8 @@ public:
 	started. */
 	void set_unlink(bool = true);
 
+	const std::vector<const FileTarget *> &get_targets() const { return targets; }
+
 	/** Returns the command being executed for this task.  Only makes sense if
 	an external command is involved. */
 	virtual std::string get_command() const = 0;
@@ -51,12 +57,18 @@ protected:
 	/// Ensures that the output directory exists and removes files if necessary.
 	void prepare();
 
+	void finished(bool);
+
 public:
 	/// Checks the status of the task and immediately returns.
 	virtual Status check() = 0;
 
 	/// Waits for the task to finish and returns its final status.
 	virtual Status wait() = 0;
+
+	/** Returns the amount of time completing the task took.  Only available
+	after the task has finished. */
+	const Msp::Time::TimeDelta &get_duration() const { return duration; }
 };
 
 #endif
-- 
2.43.0