From: John Carter <john.carter@...>
Date: 2008-12-02T10:03:12+09:00
Subject: Adventures in Optimization...Optimizing the stuff you didn't write!

The heart of Optimization is Benchmarking.

Measure, measure, measure!

So I found couple of really promising optimizations....
.... but they made hardly any difference.

End to end, the process took just as many hours to within a few
seconds.

WHY!?

The real elapsed time is not being chewed by my Ruby. It's been eaten
by the things I'm using Ruby as a "Glue Language" to bind together.

Measure, measure, measure...

I love Ruby. It's so open. There is the profiler module. The Source
code my disk, there to be tweaked.

Pull in /usr/lib/ruby/1.8/profiler.rb

Search and replace all occurrences of Process.times[0] with Time.now

======================================================================
diff -u /usr/lib/ruby/1.8/profiler.rb ProfileRealTime.rb
--- /usr/lib/ruby/1.8/profiler.rb	2007-02-13 12:01:19.000000000 +1300
+++ ProfileRealTime.rb	2008-11-28 11:51:28.000000000 +1300
@@ -1,13 +1,13 @@
-module Profiler__
+module ProfileRealTime
    # internal values
    @@start = @@stack = @@map = nil
    PROFILE_PROC = proc{|event, file, line, id, binding, klass|
      case event
      when "call", "c-call"
-      now = Process.times[0]
+      now = Time.now
        @@stack.push [now, 0.0]
      when "return", "c-return"
-      now = Process.times[0]
+      now = Time.now
        key = [klass, id]
        if tick = @@stack.pop
          data = (@@map[key] ||= [0, 0.0, 0.0, key])
@@ -21,7 +21,7 @@
    }
  module_function
    def start_profile
-    @@start = Process.times[0]
+    @@start = Time.now
      @@stack = []
      @@map = {}
      set_trace_func PROFILE_PROC
@@ -31,7 +31,7 @@
    end
    def print_profile(f)
      stop_profile
-    total = Process.times[0] - @@start
+    total = Time.now - @@start
      if total == 0 then total = 0.01 end
      data = @@map.values
      data.sort!{|a,b| b[2] <=> a[2]}
@@ -57,3 +57,8 @@
    end
    private :get_name
  end
+
+END {
+  ProfileRealTime::print_profile(STDERR)
+}
+ProfileRealTime::start_profile
======================================================================

Add a
   require 'ProfileRealTime'
and run.

That was so easy! Oooh! Looky, I'm `backticking` that program way more
than I need to! I bet if consolidate all the invocations into one Big
One..

Hmm. IO.read is taken rather long... Which invocation is it? Use my
cunning trick from my previous most to find the call graph that's
chewing all the time.


John Carter                             Phone : (64)(3) 358 6639
Tait Electronics                        Fax   : (64)(3) 359 4632
PO Box 1645 Christchurch                Email : john.carter@tait.co.nz
New Zealand