From 59a3cb4e10bb81c4c33e642e2be06f4a9dbc0bff Mon Sep 17 00:00:00 2001
From: Josh Holtrop <jholtrop@gmail.com>
Date: Sat, 27 Apr 2019 22:29:18 -0400
Subject: [PATCH] verbose mode should list operations and their execution times
 - close #103

---
 lib/rscons/application.rb | 68 +++++++++++++++++++++++----------------
 lib/rscons/util.rb        | 21 ++++++++++++
 spec/build_tests_spec.rb  | 10 ++++++
 spec/rscons/util_spec.rb  | 14 ++++++++
 4 files changed, 86 insertions(+), 27 deletions(-)

diff --git a/lib/rscons/application.rb b/lib/rscons/application.rb
index a563b94..e816117 100644
--- a/lib/rscons/application.rb
+++ b/lib/rscons/application.rb
@@ -47,40 +47,54 @@ module Rscons
     #   The script.
     # @param operation_options [Hash]
     #   Option values from the CLI for the operation.
+    # @param options [Hash]
+    #   Optional parameters.
+    # @option sub_op [Boolean]
+    #   Whether this operation is not the top-level operation.
     #
     # @return [Integer]
     #   Process exit code (0 on success).
-    def run(operation, script, operation_options)
-      @operations << operation
+    def run(operation, script, operation_options, options = {})
+      @start_time = Time.new
       @script = script
-      case operation
-      when "build"
-        unless Cache.instance["configuration_data"]["configured"]
-          if @script.autoconf
-            rv = run("configure", script, operation_options)
-            if rv != 0
-              return rv
-            end
-          else
-            $stderr.puts "Project must be configured first, and autoconf is disabled"
-            return 1
+      @operations << operation
+      puts "Starting '#{operation}' at #{Time.new}" if verbose
+      rv =
+        case operation
+        when "build"
+          rv = 0
+          unless Cache.instance["configuration_data"]["configured"]
+            rv =
+              if @script.autoconf
+                run("configure", script, operation_options, sub_op: false)
+              else
+                $stderr.puts "Project must be configured first, and autoconf is disabled"
+                1
+              end
           end
+          if rv == 0
+            build(operation_options)
+          end
+        when "clean"
+          clean
+        when "configure"
+          configure(operation_options)
+        when "distclean"
+          distclean
+        when "install"
+          run("build", script, operation_options, sub_op: false)
+        when "uninstall"
+          uninstall
+        else
+          $stderr.puts "Unknown operation: #{operation}"
+          1
         end
-        build(operation_options)
-      when "clean"
-        clean
-      when "configure"
-        configure(operation_options)
-      when "distclean"
-        distclean
-      when "install"
-        run("build", script, operation_options)
-      when "uninstall"
-        uninstall
-      else
-        $stderr.puts "Unknown operation: #{operation}"
-        1
+      if verbose and options[:sub_op].nil?
+        time = Time.new
+        elapsed = time - @start_time
+        puts "'#{operation}' complete at #{time} (#{Util.format_elapsed_time(elapsed)})"
       end
+      rv
     end
 
     private
diff --git a/lib/rscons/util.rb b/lib/rscons/util.rb
index 0c6ba25..85a2968 100644
--- a/lib/rscons/util.rb
+++ b/lib/rscons/util.rb
@@ -95,6 +95,27 @@ module Rscons
         end
       end
 
+      # Format an elapsed time in human-readable format.
+      #
+      # @return [String]
+      #   Elapsed time in human-readable format.
+      def format_elapsed_time(elapsed)
+        hours = (elapsed / (60 * 60)).to_i
+        elapsed -= hours * 60 * 60
+        minutes = (elapsed / 60).to_i
+        elapsed -= minutes * 60
+        seconds = elapsed.ceil
+        result = ""
+        if hours > 0
+          result += "#{hours}h "
+        end
+        if hours > 0 || minutes > 0
+          result += "#{minutes}m "
+        end
+        result += "#{seconds}s"
+        result
+      end
+
       # Make a relative path corresponding to a possibly absolute one.
       #
       # @param path [String]
diff --git a/spec/build_tests_spec.rb b/spec/build_tests_spec.rb
index 0821545..bf3b9de 100644
--- a/spec/build_tests_spec.rb
+++ b/spec/build_tests_spec.rb
@@ -2089,6 +2089,16 @@ EOF
       expect(result.stderr).to eq ""
       expect(result.stdout).to match /gcc.*-o.*simple/
     end
+
+    it "prints operation start time" do
+      test_dir("simple")
+      result = run_rscons(rscons_args: %w[-v])
+      expect(result.stderr).to eq ""
+      expect(result.stdout).to match /Starting 'configure' at/
+      expect(result.stdout).to match /Starting 'build' at/
+      expect(result.stdout).to match /'build' complete at/
+      expect(result.stdout).to_not match /'configure' complete at/
+    end
   end
 
   context "direct mode" do
diff --git a/spec/rscons/util_spec.rb b/spec/rscons/util_spec.rb
index 4c39c5e..6ce114f 100644
--- a/spec/rscons/util_spec.rb
+++ b/spec/rscons/util_spec.rb
@@ -151,6 +151,20 @@ EOF
       end
     end
 
+    describe ".format_elapsed_time" do
+      it "includes minutes when hours is nonzero and minutes is zero" do
+        expect(Util.format_elapsed_time(60 * 60 + 4)).to eq "1h 0m 4s"
+      end
+
+      it "only includes minutes and seconds when hours is zero and minutes is nonzero" do
+        expect(Util.format_elapsed_time(3 * 60 + 33)).to eq "3m 33s"
+      end
+
+      it "only includes seconds when hours and minutes are zero" do
+        expect(Util.format_elapsed_time(7.84)).to eq "8s"
+      end
+    end
+
     describe ".make_relative_path" do
       context "when passed a relative path" do
         it "returns the path itself" do