Added elapsed time to remote and local command finished log messages

lib/capistrano/command.rb

@@ -1,3 +1,4 @@
+require 'benchmark'
 require 'capistrano/errors'
 require 'capistrano/processable'
 
@@ -159,11 +160,13 @@ module Capistrano
     # fails (non-zero return code) on any of the hosts, this will raise a
     # Capistrano::CommandError.
     def process!
-      loop do
+      elapsed = Benchmark.realtime do
-        break unless process_iteration { @channels.any? { |ch| !ch[:closed] } }
+        loop do
+          break unless process_iteration { @channels.any? { |ch| !ch[:closed] } }
+        end
       end
 
-      logger.trace "command finished" if logger
+      logger.trace "command finished in #{(elapsed * 1000).round}ms" if logger
 
       if (failed = @channels.select { |ch| ch[:status] != 0 }).any?
         commands = failed.inject({}) { |map, ch| (map[ch[:command]] ||= []) << ch[:server]; map }

lib/capistrano/recipes/deploy.rb

@@ -1,3 +1,4 @@
+require 'benchmark'
 require 'yaml'
 require 'capistrano/recipes/deploy/scm'
 require 'capistrano/recipes/deploy/strategy'
@@ -95,10 +96,13 @@ end
 # returns the command output as a string
 def run_locally(cmd)
   logger.trace "executing locally: #{cmd.inspect}" if logger
-  output_on_stdout = `#{cmd}`
+  elapsed = Benchmark.realtime do
+    output_on_stdout = `#{cmd}`
+  end
   if $?.to_i > 0 # $? is command exit code (posix style)
     raise Capistrano::LocalArgumentError, "Command #{cmd} returned status code #{$?}"
   end
+  logger.trace "command finished in #{(elapsed * 1000).round}ms" if logger
   output_on_stdout
 end
 

lib/capistrano/recipes/deploy/strategy/base.rb

@@ -1,3 +1,4 @@
+require 'benchmark'
 require 'capistrano/recipes/deploy/dependencies'
 
 module Capistrano
@@ -49,16 +50,24 @@ module Capistrano
           # A wrapper for Kernel#system that logs the command being executed.
           def system(*args)
             cmd = args.join(' ')
+            result = nil
             if RUBY_PLATFORM =~ /win32/
 							cmd = cmd.split(/\s+/).collect {|w| w.match(/^[\w+]+:\/\//) ? w : w.gsub('/', '\\') }.join(' ') # Split command by spaces, change / by \\ unless element is a some+thing:// 
               cmd.gsub!(/^cd /,'cd /D ') # Replace cd with cd /D
               cmd.gsub!(/&& cd /,'&& cd /D ') # Replace cd with cd /D
               logger.trace "executing locally: #{cmd}"
-              super(cmd)
+              elapsed = Benchmark.realtime do
+                result = super(cmd)
+              end
             else
               logger.trace "executing locally: #{cmd}"
-              super
+              elapsed = Benchmark.realtime do
+                result = super
+              end
             end
+            
+            logger.trace "command finished in #{(elapsed * 1000).round}ms"
+            result
           end
 
         private