Merge branch 'profiling' -- add a '--profile' option to print per-lin…

…e duration.

lib/babushka/base.rb

@@ -20,6 +20,13 @@ def ruby
   class Base
   class << self
 
+    # The time at which babushka was loaded. This is used in LogHelpers to
+    # print profiling information via the '--profile' commandline option.
+    @@start_time = Time.now
+    def start_time
+      @@start_time
+    end
+
     # +task+ represents the overall job that is being run, and the parts that
     # are external to running the corresponding dep tree itself - logging, and
     # var loading and saving in particular.

lib/babushka/cmdline.rb

@@ -49,6 +49,7 @@ class Cmdline
       opt '-u', '--update',       "Update referenced sources before loading deps from them"
       opt       '--show-args',    "Show the arguments being passed between deps as they're run"
       opt       '--track-blocks', "Track deps' blocks in TextMate as they're run"
+      opt       '--profile',      "Print a per-line timestamp to the debug log."
     }.run {|cmd|
       dep_names, vars = cmd.argv.partition {|arg| arg['='].nil? }
       if !(bad_var = vars.detect {|var| var[/^\w+=/].nil? }).nil?

lib/babushka/helpers/log_helpers.rb

@@ -103,9 +103,11 @@ def removed! opts = {}
     # runs - so please consider other logging styles before using this one, so as
     # not to visually confuse dep runs with other operations.)
     def log message, opts = {}, &block
-      # now = Time.now
-      # print "#{now.to_i}.#{now.usec}: ".ljust(20) unless opts[:debug]
       printable = !opts[:debug] || Base.task.opt(:debug)
+      if Base.task.opt(:profile)
+        delta = Time.now - Base.start_time
+        Logging.print_log("%.4f ".colorize('grey') % delta, printable, opts[:as])
+      end
       Logging.print_log(Logging.indentation, printable, opts[:as]) unless opts[:indentation] == false
       if block_given?
         Logging.print_log("#{message} {".colorize('grey') + "\n", printable, opts[:as])

spec/babushka/cmdline/help_spec.rb

@@ -52,6 +52,7 @@
     -u, --update                     Update referenced sources before loading deps from them
         --show-args                  Show the arguments being passed between deps as they're run
         --track-blocks               Track deps' blocks in TextMate as they're run
+        --profile                    Print a per-line timestamp to the debug log.
 ")
 
       Cmdline.should_receive(:log).with("\n")