Report timings of the build

diff --git a/source/lib/builder.cpp b/source/lib/builder.cpp
index 08e9cd7ef69f68b8d12d2bb61c081d3145db789e..3379f2dcfebdea1e1f0d4533189d4480f71ba7ed 100644 (file)
--- 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 37a36d39150da641b3a39e91d5c0fb866576af02..ce81ac119fef8bbce93ea096f971deed29342db0 100644 (file)
--- 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 fc929ce02b2f843c2bd6de87331bbe081f11017c..fe3ae9d0666a5458fd9beb925c4491cb0f05bbee 100644 (file)
--- 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 870e068c76a9cab072c98eacfeff1b3450c76c19..ed79e56c68621a31dbefa9638fb64f88efe54cc0 100644 (file)
--- 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 3520a91ae04ab3fe584a873ec6e56123d7f8e8ae..e493e3b188e99efaef18a81db22b266b3820d0f9 100644 (file)
--- 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