From 20b168df068285558512101084af773db83ff0e0 Mon Sep 17 00:00:00 2001
From: Chris Griego <cgriego@gmail.com>
Date: Mon, 11 Jan 2010 11:58:39 -0600
Subject: [PATCH] Added elapsed time to remote and local command finished log
 messages

---
 lib/capistrano/command.rb                      |  9 ++++++---
 lib/capistrano/recipes/deploy.rb               |  6 +++++-
 lib/capistrano/recipes/deploy/strategy/base.rb | 13 +++++++++++--
 3 files changed, 22 insertions(+), 6 deletions(-)

diff --git a/lib/capistrano/command.rb b/lib/capistrano/command.rb
index 033b097b..958cf464 100644
--- a/lib/capistrano/command.rb
+++ b/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
-        break unless process_iteration { @channels.any? { |ch| !ch[:closed] } }
+      elapsed = Benchmark.realtime do
+        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 }
diff --git a/lib/capistrano/recipes/deploy.rb b/lib/capistrano/recipes/deploy.rb
index 972364fa..67d9d0de 100644
--- a/lib/capistrano/recipes/deploy.rb
+++ b/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
 
diff --git a/lib/capistrano/recipes/deploy/strategy/base.rb b/lib/capistrano/recipes/deploy/strategy/base.rb
index 86c17850..c20da87b 100644
--- a/lib/capistrano/recipes/deploy/strategy/base.rb
+++ b/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