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

**URL:** <https://www.ruby-forum.com/t/adventures-in-optimization-optimizing-the-stuff-you-didnt-write/154595>\
**Category:** Ruby\
**Created:** [December 2, 2008, 2:09am UTC](https://www.ruby-forum.com/t/adventures-in-optimization-optimizing-the-stuff-you-didnt-write/154595 "2008-12-02T02:09:17Z")\
**Posts on this page:** 1\
**Page:** 1

<div class="post-metadata">

**Author:** ![amin1426](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/a/4da419/32.png) [@amin1426](https://www.ruby-forum.com/u/amin1426)\
**Post date:** [December 2, 2008, 2:09am UTC](https://www.ruby-forum.com/t/adventures-in-optimization-optimizing-the-stuff-you-didnt-write/154595/1 "2008-12-02T02:09:17Z")

</div>

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 C. Phone : (64)(3) 358 6639  
Tait Electronics Fax : (64)(3) 359 4632  
PO Box 1645 Christchurch Email : removed\_email\_address@domain.invalid  
New Zealand