Rails incredibly slow (update)

On Fri, 16 Nov 2007 13:35:38 -0500, Jano S. 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

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.

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 J.
www.XProgramming.com

On Nov 18, 2007, at 10:15 AM, Ron J. 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,

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 Sun, 18 Nov 2007 11:07:54 -0500, Ron J. [email protected]
wrote:

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 J.
www.XProgramming.com

This is probably unhelpful, but since you seem stuck…

uninstall your ruby and rails installation.

download this .exe install (ruby only, no instant rails)

http://rubyforge.org/frs/?group_id=167

(you may need to reboot here or logoff/logon to make sure PATH is
updated)

then manually install rails

gem install rails --include-dependencies

now see how long rails -v takes.

darius wrote:

Actually, I wonder if Portable Rails would help:
http://ruby.about.com/od/resources/qt/portable_rails.htm

I think there was another Portable version of Rails but I can’t remember
what it was…

Cheers,
Mohit.
11/19/2007 | 12:59 AM.

On Sun, 18 Nov 2007 11:07:54 -0500, Ron J. 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.

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:58:32 -0500, Jay L. [email protected]
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!

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 J.
www.XProgramming.com

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 J.
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

On Nov 18, 2007, at 11:10 AM, Ron J. 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 …

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 Sun, 18 Nov 2007 12:06:19 -0500, Ron J. wrote:

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!

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 …

Yep. RSpec has a --format progress (and a per-spec timeout as well
which
would be useful here), but I don’t think Test::Unit has that.

FWIW, in my experience, Ruby speed issues on Windows are pretty much
always
file I/O problems. Even when it’s working, and anti-virus is disabled,
it’s much slower than Mac or Linux, but when it’s not working, hoo boy.

You could probably rig up something with set_trace_func, but (a) that
requires some more coding and (b) set_trace_func itself is pretty slow.

Hi Ron,

From: “Ron J.” [email protected]

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

On Sun, 18 Nov 2007 11:58:32 -0500, Jay L. [email protected]
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 J.
www.XProgramming.com

On Mon, 19 Nov 2007, Ron J. wrote:

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

Back tick ` means run the following command and return whatever goes to
stdout as a string.

#{ruby} means interpolate into the command string the content of the
local variable ruby. My guess is the path to the ruby interpreter.

-i.bak is a perlism to operator on the argument “script_tmp” backing
it up to “script_tmp.bak” prior to feeding it into stdin and stdout
to “script_tmp”

-p is a perlism to iterate through every line of stdin placing each
line in default variable $, execute the chunk of script specified by
-e and
then printing the variable $
to stdout.

-e ‘’ a perlism to execute the enclosed chunk of ruby.

sub(//){} Operating on the default variable $_
find the first occurrence of the regexp // and replace it
with the result of the block {}

/^[0-9]+$/ Match an integer filling the whole line.

{$&.to_i * 5} Convert it to and integer and multiply by 5

This would only be slow is script_tmp is massive. The backtick would
cause lots of swapping if the size of script_tmp was larger than
available free ram.

John C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
New Zealand

From: “Ron J.” [email protected]

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

Appears to be shelling out to another ruby process which will take
all the lines in a script_tmp file beginning with a number, and
multiply those numbers * 5. The original file will be renamed
script_tmp.bak and the modifiled file will be saved as script_tmp.

(Unless script_tmp is a directory? I’ve only ever done -i with
files.)

Normally a command like that wouldn’t take long, unless there’s
an awful lot of data to process.

Regards,

Bill

On Sun, 18 Nov 2007 18:17:41 -0500, John C.
[email protected] wrote:

#{ruby} means interpolate into the command string the content of the
-e ‘’ a perlism to execute the enclosed chunk of ruby.

sub(//){} Operating on the default variable $_
find the first occurrence of the regexp // and replace it with the result of the block {}

/^[0-9]+$/ Match an integer filling the whole line.

{$&.to_i * 5} Convert it to and integer and multiply by 5

Way more cryptic than I needed. Thanks.

This would only be slow is script_tmp is massive. The backtick would
cause lots of swapping if the size of script_tmp was larger than
available free ram.

Interesting. It surely isn’t massive, these lines are preceded by
these:

tmp = open("script_tmp", "w")
for i in 1..5
  tmp.print i, "\n"
end
tmp.close

Which make me think 5 lines. Wonder what’s up with that. Might be
interesting to zero in on …

Ron J.
www.XProgramming.com

On Sun, 18 Nov 2007 15:15:02 -0500, Jay L. [email protected]
wrote:

FWIW, in my experience, Ruby speed issues on Windows are pretty much always
file I/O problems. Even when it’s working, and anti-virus is disabled,
it’s much slower than Mac or Linux, but when it’s not working, hoo boy.

Well, this is in the range of hoo boy, 15x slower than Chet’s laptop,
which is otherwise comparable or possibly slower.
Very confusing …

Ron J.
www.XProgramming.com

On Sun, 18 Nov 2007 17:43:46 -0500, Bill K. [email protected] wrote:

Normally a command like that wouldn’t take long, unless there’s
an awful lot of data to process.

Yes, thanks. I think it’s 5 lines and that it is taking 15 seconds to
run. Weird …

If it’s not the I/O I suppose it could be something about Ruby trying
to compile things.

That brings a thought to mind. Chet and I wrote a trivial benchmark
that just did a long loop. Seemed to run one second slower on my
machine than his, no matter how long the loop.

Which would mean that compiling a trivial program takes one second
longer on his machine … ?

Hmm …

Ron J.
www.XProgramming.com

On Sun, 18 Nov 2007 23:56:57 -0500, Ron J. wrote:

Well, this is in the range of hoo boy, 15x slower than Chet’s laptop,
which is otherwise comparable or possibly slower.

Yeah, you’ve definitely got a degenerate-case condition (or maybe a few)
going on there. That reverse-lookup thing is interesting as well, but I
know less about TCP performance on Windows than file I/O performance, so
this is the streetlight I’m looking under - hopefully Bill can keep
troubleshooting with you on the TCP/DNS thing.

I was trying to repro your problem so I could compare how long that one
line takes on my system - and what calls it makes - but there are a
bunch
of runner.rb scripts, none in the normal path, and they don’t seem to
run
via the command you described.

You’re running Instant Rails 1.7, right? Launching the Ruby (not Rails)
console from the menu option? If so, what directory are you changing to
before the “ruby runner.rb ruby” command?

On Sun, 18 Nov 2007 12:27:52 -0500, Brian M.
[email protected] wrote:

test_should_remember_me_for_one_week(UserTest): EE
Hmm. I read the help, which says

 -v, --verbose=[LEVEL]  Set the output level (default is verbose).
                       (s[ilent], p[rogress], n[ormal], v[erbose])

as saying I had to say --verbose=s or p or n or v, none of which
seemed to work.

So I patched stuff into the ::Unit stuff, which at least gave me info.

Will try other things tomorrow. Dead now. Thanks,

Ron J.
www.XProgramming.com