Rails incredibly slow (update)

When in the Rails ruby folder, we run
ruby runner.rb ruby
Chet's machine takes about 6 seconds, and mine takes 93 seconds.

This may be like 'slaking a thirst with a firehose', but...

Maybe instrumenting runner.rb with a trace function:

def __trace_on__
  trace_proc = proc do |event, file, line, id, binding, classname|
    return if file =~ %r{lib/ruby/}
    trace_str = sprintf( "%14.3f %8s %s:%-2d %10s %8s <%d>",
                         Time.now.to_f, event, file, line, id,
                         classname, Thread.current.object_id )
    $stderr.puts trace_str
  end
  set_trace_func trace_proc
end

def __trace_off__
  set_trace_func nil
end

__trace_on__

... This will output a LOT of information, tracing each line
of code executed and printing a timestamp. But maybe it might
reveal something about where the slowdown is occurring. (If
the tracing itself doesn't add so much overhead as to mask
the problem <grin>.)

Note that by default, to cut down on the spam, I have the trace
func ignore files having lib/ruby/ in their path. You may need
to modify that if you aren't seeing the output you're interested
in.

Hope this helps,

Bill

···

From: "Ron Jeffries" <ronjeffries@acm.org>

This is making me think that your DNS is confused. I don't know if rails tries to do a name lookup, but it is probable. I'm sure that ruby's tests do socket lookups.

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

···

On Nov 14, 2007, at 09:25 , Ron Jeffries wrote:

When in the Rails ruby folder, we run
  ruby runner.rb ruby
Chet's machine takes about 6 seconds, and mine takes 93 seconds.

This is ruby tests, not rails. Other comparison tests our machines are
about the same, including a big loop in C#, starting visual studio,
starting eclipse, or starting Word. By and large, the machines run the
same speed. For Ruby, I'm 15x slower or worse.

--
Poor workers blame their tools. Good workers build better tools. The
best workers get their tools to do the work for them. -- Syndicate Wars

I'd suggest finding an analog to strace for windows. I'm pretty sure
such a beast exists.

···

On Nov 16, 2007 10:13 AM, M. Edward (Ed) Borasky <znmeb@cesmail.net> wrote:

Hmmm ... maybe we should get an IRC channel up for hunting this down.
I've got some friends who can usually nail something like this in less
than an hour if it's a general Windows/laptop issue and not something in
Ruby or Rails. I'm still clinging to the hope that it *is* a general
Windows/laptop issue.

One thing you might try is CodeAnalyst from AMD. I think it works even
on Intel processors, at least at the basic level. It will tell you if
something is using a lot of *processor* time. If it's I/O, swapping, or
some timeout, you won't see anything.

--
Rick DeNatale

My blog on Ruby
http://talklikeaduck.denhaven2.com/

I changed RUBYOPT to be empty, as someone suggested, with no change in
performance.

As a reminder, a plain numeric test runs about the same as Chet's
laptop. running the ruby tests as shown below is taking 15x longer on
my machine.

To find out what's happening, I've been trying to figure out how to
make the test command

  ruby runner.rb ruby

trace which tests are running, thinking that since some of the dots
take forever to come out and some come out quickly, that might be
interesting information, and lead to some understanding of what is
going on.

sorry to be so ignorant, but what reformulation of that command would
run the tests named "ruby" and display some test names instead of just
dots?

Thanks,

Ron Jeffries
www.XProgramming.com

It's a solid 8 seconds on my machine. But ordinary web page access is
nothing like that. What is this telling us?

Thanks,

Ron Jeffries
www.XProgramming.com

···

On Wed, 14 Nov 2007 14:03:36 -0500, Eric Hodel <drbrain@segment7.net> wrote:

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

If all else fails, I'll dig into this one. Thanks,

Ron Jeffries
www.XProgramming.com

···

On Wed, 14 Nov 2007 13:32:11 -0500, Bill Kelly <billk@cts.com> wrote:

This may be like 'slaking a thirst with a firehose', but...

you can start with either:

- PerfMon - will show you bytes/s read/written from/to memory, the
same for disk io
- ProcExp - will show you open files, handles, threads, current call
stack of the threads
- WinDbg - shows call stack, memory, you can set breakpoints in system calls,...
- kdb - for kernel debugging

Jano

···

On Nov 16, 2007 5:45 PM, Rick DeNatale <rick.denatale@gmail.com> wrote:

On Nov 16, 2007 10:13 AM, M. Edward (Ed) Borasky <znmeb@cesmail.net> wrote:
> Hmmm ... maybe we should get an IRC channel up for hunting this down.
> I've got some friends who can usually nail something like this in less
> than an hour if it's a general Windows/laptop issue and not something in
> Ruby or Rails. I'm still clinging to the hope that it *is* a general
> Windows/laptop issue.
>
> One thing you might try is CodeAnalyst from AMD. I think it works even
> on Intel processors, at least at the basic level. It will tell you if
> something is using a lot of *processor* time. If it's I/O, swapping, or
> some timeout, you won't see anything.

I'd suggest finding an analog to strace for windows. I'm pretty sure
such a beast exists.

To find out what's happening, I've been trying to figure out how to
make the test command

ruby runner.rb ruby

trace which tests are running, thinking that since some of the dots
take forever to come out and some come out quickly, that might be
interesting information, and lead to some understanding of what is
going on.

sorry to be so ignorant, but what reformulation of that command would
run the tests named "ruby" and display some test names instead of just
dots?

As a side note perhaps of interest, this command

  >ruby runner.rb --verbose=v --name=ruby

which I typed in hoping that would run the ruby tests with more
information coming out, takes almost //four minutes// to run and then
reports

Loaded suite .
Started

Finished in 0.0 seconds.

0 tests, 0 assertions, 0 failures, 0 errors

This must be some new kind of 0.0 seconds that I wasn't previously
familiar with. Is this telling us that the /compile/ is taking all the
time?

Advice welcome ... thanks,

Ron Jeffries
www.XProgramming.com

···

On Sun, 18 Nov 2007 11:07:54 -0500, Ron Jeffries <ronjeffries@acm.org> wrote:

Easier than that (though not as Ruby-like). Go get:

http://download.sysinternals.com/Files/Filemon.zip

Press CTRL-L, make sure all three checkboxes are checked, and Include:
ruby.exe.

Assuming it's a disk I/O thing, you'll find it!

···

On Sun, 18 Nov 2007 11:07:54 -0500, Ron Jeffries wrote:

To find out what's happening, I've been trying to figure out how to
make the test command

  ruby runner.rb ruby

trace which tests are running, thinking that since some of the dots
take forever to come out and some come out quickly, that might be
interesting information, and lead to some understanding of what is
going on.

--
Jay Levitt |
Boston, MA | My character doesn't like it when they
Faster: jay at jay dot fm | cry or shout or hit.
http://www.jay.fm | - Kristoffer

Hi Ron,

To find out what's happening, I've been trying to figure out how to
make the test command

ruby runner.rb ruby

trace which tests are running, thinking that since some of the dots
take forever to come out and some come out quickly, that might be
interesting information, and lead to some understanding of what is
going on.

I'm not sure if you might have missed some of my posts, or if
I missed some of your replies somehow.

In any case, I'm still wondering if you've tried the following?

Just hack this stuff temporarily into the top of runner.rb:

1. If you haven't already, I'd suggest trying what Caleb suggested:
putting: BasicSocket.do_not_reverse_lookup = true
at the top of that file. (Preceded only by a require 'socket')

2. If that doesn't help, I'd suggest trying: require "resolv-replace"
at the top of that .rb file.

3. If that doesn't help, I'd suggest adding the trace code I
posted the other day (Nov 14th) to the top of that .rb file.

With the lengthy delays you've been experiencing, I'd imagine
the trace code may provide some confirmation as to exactly what
code is being executed at the time of the pause.

Here is the trace code again:

def __trace_on__
  trace_proc = proc do |event, file, line, id, binding, classname|
    # return if file =~ %r{lib/ruby/}
    trace_str = sprintf( "%14.3f %8s %s:%-2d %10s %8s <%d>",
                         Time.now.to_f, event, file, line, id,
                         classname, Thread.current.object_id )
    $stderr.puts trace_str
  end
  set_trace_func trace_proc
end

def __trace_off__
  set_trace_func nil
end

__trace_on__

Yes... the trace code will spew out reams of info -- but with
delays as long as you are experiencing, I think it will be
interesting to see what ruby is doing when the delay occurs.
(Even if it's not helpful, it should only take a minute or two
to try.)

Regards,

Bill

···

From: "Ron Jeffries" <ronjeffries@acm.org>

I flushed dns cache (windows xp), same result. changed from system
default DNS to some specific known DNS servers. Same result.

?

Ron Jeffries
www.XProgramming.com

···

On Wed, 14 Nov 2007 22:27:46 -0500, Ron Jeffries <ronjeffries@acm.org> wrote:

On Wed, 14 Nov 2007 14:03:36 -0500, Eric Hodel <drbrain@segment7.net> >wrote:

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

It's a solid 8 seconds on my machine. But ordinary web page access is
nothing like that. What is this telling us?

Do you get the same result for the IP address (last field)?

I have seen problems where DNS is confused only for 127.0.0.1 or localhost which leads to this terrible delay. Adding an entry to the hosts file sometimes fixes this, but I'm not sure where it lives on windows systems.

···

On Nov 14, 2007, at 19:30 , Ron Jeffries wrote:

On Wed, 14 Nov 2007 14:03:36 -0500, Eric Hodel <drbrain@segment7.net> > wrote:

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

It's a solid 8 seconds on my machine. But ordinary web page access is
nothing like that. What is this telling us?

--
Poor workers blame their tools. Good workers build better tools. The
best workers get their tools to do the work for them. -- Syndicate Wars

Also Filemon (or its someday replacement, Process Monitor) from
SysInternals. I've tracked down more Windows mysteries with Filemon and
Regmon than I can count.

···

On Fri, 16 Nov 2007 13:35:38 -0500, Jano Svitok wrote:

you can start with either:

- PerfMon - will show you bytes/s read/written from/to memory, the
same for disk io
- ProcExp - will show you open files, handles, threads, current call
stack of the threads
- WinDbg - shows call stack, memory, you can set breakpoints in system calls,...
- kdb - for kernel debugging

--
Jay Levitt |
Boston, MA | My character doesn't like it when they
Faster: jay at jay dot fm | cry or shout or hit.
http://www.jay.fm | - Kristoffer

Like all the xUnits, the times are misleading because they don't include overhead. It's the time spent actually running the tests: since it ran zero tests, it took zero seconds.

I missed the beginning of the thread, but have you put some judicious puts statements in the test/unit code? It's not hard to figure out where things happen inside it, especially since it's a pretty standard xUnit implementation. Something's almost gotta be reaching out and getting a network timeout, and this should help you divide-and-conquer your way to what.

···

On Nov 18, 2007, at 10:15 AM, Ron Jeffries wrote:

Finished in 0.0 seconds.

0 tests, 0 assertions, 0 failures, 0 errors

This must be some new kind of 0.0 seconds that I wasn't previously
familiar with. Is this telling us that the /compile/ is taking all the
time?

Advice welcome ... thanks,

-----
Brian Marick, independent consultant
Mostly on agile methods with a testing slant
www.exampler.com, Exploration Through Example, twitter.com/marick

It may come to that but not clear it is file I/O. Yet. Would love to
just get ruby runner to print out the test names as they go by ...

Ron Jeffries
www.XProgramming.com

···

On Sun, 18 Nov 2007 11:58:32 -0500, Jay Levitt <jay+news@jay.fm> wrote:

Easier than that (though not as Ruby-like). Go get:

http://download.sysinternals.com/Files/Filemon.zip

Press CTRL-L, make sure all three checkboxes are checked, and Include:
ruby.exe.

Assuming it's a disk I/O thing, you'll find it!

Well, yes and no ... this chunk of code takes some 15 seconds, which I
sort of zeroed in on by successive refinement. I have no idea what it
even means. If someone would care to translate it, I'd be interested
and grateful.

    `#{ruby} -i.bak -pe 'sub(/^[0-9]+$/){$&.to_i * 5}' script_tmp`

I'm seeing lots of I/O as I trace all the tests. I'm not seeing
anything that looks notably slower than anything else. Of course there
are 65000 lines created in filemon during the ruby test file ruby.rb,
so I might have missed something.

Very confused ...

Ron Jeffries
www.XProgramming.com

···

On Sun, 18 Nov 2007 11:58:32 -0500, Jay Levitt <jay+news@jay.fm> wrote:

Easier than that (though not as Ruby-like). Go get:

http://download.sysinternals.com/Files/Filemon.zip

Press CTRL-L, make sure all three checkboxes are checked, and Include:
ruby.exe.

Assuming it's a disk I/O thing, you'll find it!

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

It's a solid 8 seconds on my machine. But ordinary web page access is
nothing like that. What is this telling us?

I flushed dns cache (windows xp), same result. changed from system
default DNS to some specific known DNS servers. Same result.

Weird. Not sure this would make any difference, but, might
try adding this at the beginning of your program:

require 'resolv-replace'

It patches a pure-ruby DNS resolver implementation in place of
IPSocket#getaddress, etc., instead of using the blocking system
call.

Also, is `nslookup.exe` fast when invoked from a command prompt?

Regards,

Bill

···

From: "Ron Jeffries" <ronjeffries@acm.org>

On Wed, 14 Nov 2007 22:27:46 -0500, Ron Jeffries <ronjeffries@acm.org> > wrote:

On Wed, 14 Nov 2007 14:03:36 -0500, Eric Hodel <drbrain@segment7.net> >>wrote:

$ time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'
["localhost", ["test"], 2, "\177\000\000\001"]

real 0m0.042s
user 0m0.010s
sys 0m0.009s

It's a solid 8 seconds on my machine. But ordinary web page access is
nothing like that. What is this telling us?

Do you get the same result for the IP address (last field)?

I don't understand the question.

I have seen problems where DNS is confused only for 127.0.0.1 or
localhost which leads to this terrible delay. Adding an entry to the
hosts file sometimes fixes this, but I'm not sure where it lives on
windows systems.

I know where the hosts file is ... it looks like this:

127.0.0.1 localhost
127.0.0.1 www.mycookbook.com
127.0.0.1 typo

But I don't understand what you might be getting at with respect to
changing it. I believe that hosts just contains some locally-specific
redirects, does it not?

Thanks,

Ron Jeffries
www.XProgramming.com

···

On Thu, 15 Nov 2007 05:43:05 -0500, Eric Hodel <drbrain@segment7.net> wrote:

On Nov 14, 2007, at 19:30 , Ron Jeffries wrote:

On Wed, 14 Nov 2007 14:03:36 -0500, Eric Hodel <drbrain@segment7.net> >> wrote:

Again, perhaps I'm missing context, but something like this doesn't work for you?

$ ~/src/publish/wevouchfor/test/unit 518 $ ruby user_test.rb --verbose
Loaded suite user_test
Started
test_should_authenticate_user(UserTest): EE
test_should_create_user(UserTest): EE
test_should_not_rehash_password(UserTest): EE
test_should_remember_me_default_two_weeks(UserTest): EE
test_should_remember_me_for_one_week(UserTest): EE

These are Rails unit tests. (They don't pass, because I just installed Leopard and haven't installed MySQL yet.)

···

On Nov 18, 2007, at 11:10 AM, Ron Jeffries wrote:

It may come to that but not clear it is file I/O. Yet. Would love to
just get ruby runner to print out the test names as they go by ...

-----
Brian Marick, independent consultant
Mostly on agile methods with a testing slant
www.exampler.com, Exploration Through Example, twitter.com/marick

It may come to that but not clear it is file I/O. Yet. Would love to
just get ruby runner to print out the test names as they go by ...

Ron Jeffries
www.XProgramming.com

We use something like the following. All of our tests require the following file:

test/test_helper.rb:

ENV["RAILS_ENV"] = "test"
require File.expand_path(File.dirname(__FILE__) + "/../config/environment")
require 'test_help'

# Show progress by test case
class Test::Unit::TestSuite

  # Runs the tests and/or suites contained in this
  # TestSuite.
  def run(result, &progress_block)
    s = sprintf( "%42s",name)
    print "\n#{s}: "
    yield(STARTED, name)
    @tests.each do |test|
      test.run(result, &progress_block)
    end
    yield(FINISHED, name)
  end

end