Adventures in Optimization...Optimizing the stuff you didn't write!

[John Carter]

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:rint_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 : (e-mail address removed)
New Zealand