Rails incredibly slow (update)

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.

···

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

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

  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

···

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

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

···

On Mon, 19 Nov 2007, Ron Jeffries 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`

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.

"My program" is rails, so I'm not sure I could do that.

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

Instantaneous.

Weird ...

Ron Jeffries
www.XProgramming.com

···

On Wed, 14 Nov 2007 22:59:29 -0500, Bill Kelly <billk@cts.com> wrote:

Ron Jeffries wrote:

···

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:

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

He's asking if the last element of this:
   ["localhost", ["test"], 2, "\177\000\000\001"]
is the same.

This is possibly a long shot, but what's in your RUBYOPT environment variable?

--
Alex

Just a SWAG, but. time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'

is doing a reverse-"DNS" lookup. Might windoze be confused by having
127.0.0.1 map to three different hostnames in the hosts file?

···

On Nov 15, 2007 7:00 AM, Ron Jeffries <ronjeffries@acm.org> wrote:

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:
>>>
>>> $ 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?

--
Rick DeNatale

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

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

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

···

On Sun, 18 Nov 2007 18:17:41 -0500, John Carter <john.carter@tait.co.nz> wrote:

On Mon, 19 Nov 2007, Ron Jeffries wrote:

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

···

On Sun, 18 Nov 2007 17:43:46 -0500, Bill Kelly <billk@cts.com> wrote:

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

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

···

On Sun, 18 Nov 2007 12:27:52 -0500, Brian Marick <marick@visibleworkings.com> 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

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

···

On Sun, 18 Nov 2007 15:15:02 -0500, Jay Levitt <jay+news@jay.fm> 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.

He's asking if the last element of this:
  ["localhost", ["test"], 2, "\177\000\000\001"]
is the same.

Still don't understand. Same as what?

I'm entering this line at the command prompt:

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

(all on one line)

and after 6 seconds at Borders and 8 at home, it echoes:

["localhost", , 2, "\177\000\000\001"]

This is possibly a long shot, but what's in your RUBYOPT environment
variable?

it contains:

  -rubygems

with the dash.

Ron Jeffries
www.XProgramming.com

···

On Thu, 15 Nov 2007 07:24:33 -0500, Alex Young <alex@blackkettle.org> wrote:

Just a SWAG, but. time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'

is doing a reverse-"DNS" lookup. Might windoze be confused by having
127.0.0.1 map to three different hostnames in the hosts file?

At least on Linux, when I've had big slowdowns like this, throwing in

BasicSocket.do_not_reverse_lookup = true

made things run much faster.

I think we've discussed this issue on the list before, too.

Tried it. No effect. This is so confusing ...

Ron Jeffries
www.XProgramming.com

···

On Thu, 15 Nov 2007 11:52:02 -0500, Rick DeNatale <rick.denatale@gmail.com> wrote:

Just a SWAG, but. time ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'

is doing a reverse-"DNS" lookup. Might windoze be confused by having
127.0.0.1 map to three different hostnames in the hosts file?

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 23:56:57 -0500, Ron Jeffries wrote:

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

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

Way more cryptic than I needed. Thanks.

Always a pleasure to render a persons day more surreal. May the force
squeak you!

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

Nah. Googling for that code turns it up in a standard ruby test. I
willing to bet for some reason the mere invocation of ruby is what is slow.

For some reason something somewhere is attempting to do lots when you
fire up ruby. Guesses....

  * That ruby.exe is infected with a virus that is attempting to Take
    Over the World on start up.

  * You have some weird default module special that at start up
    attempts to phone home and perhaps update itself, but hits a
    firewall and timesout. (Weird very unlikely)

  * Some virus scanner is seeing the ruby subprocess start up and is going
    paranoid and scanning it.

Absolutely no blooming way should on a remotely healthy installation
of ruby should those few lines be taking a "human noticable" length of
time.

If you can find a Windows equivalent of that most invaluable of Unix
utilities, "strace" (do tell me where you got it when you do) get it
to strace which files ruby opens on startup and send that to the
group. strace is mankinds best and most loyal friend, never leave home
without it.

My personal guess is you have a virus.

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

···

On Mon, 19 Nov 2007, Ron Jeffries wrote:

Ron Jeffries wrote:

He's asking if the last element of this:
  ["localhost", ["test"], 2, "\177\000\000\001"]
is the same.

Still don't understand. Same as what?

Ah, I see. I believe Eric was originally asking you to enter only this command:
   ruby -rsocket -e 'p Socket.gethostbyname("127.0.0.1")'

which should (and apparently does) print:
   ["localhost", ["test"], 2, "\177\000\000\001"]

to the console. The section "\177\000\000\001" is the binary representation of the IP address that the gethostbyname system call actually used (I think - slightly outside my area), and if it had been different it would have indicated DNS or low-level IP weirdery. I think.

This is possibly a long shot, but what's in your RUBYOPT environment variable?

it contains:

  -rubygems

If you remove it (set RUBYOPT=""), does the time taken to run your counting script improve? I can't think of any reason that it should (barring AV-scanning of opened files), but it might narrow the scope a little.

···

On Thu, 15 Nov 2007 07:24:33 -0500, Alex Young <alex@blackkettle.org> > wrote:

--
Alex

# it contains:

···

From: Ron Jeffries [mailto:ronjeffries@acm.org]
#
# -rubygems
#
# with the dash.

remove it.
then go to the folder where ruby.exe resides.

then try creating and running a simple program like,

# sample.rb
5.times {puts "hello, world"}

.\ruby sample.rb

let us narrow it down to pure ruby first by avoiding gem loading and long path traversals...

kind regards -botp

McAfee doesn't agree. They could be wrong, I suppose. I'm running all
kinds of scanners and optimizers just now, on general principles.
We'll see.

I'll report back on the other stuff as I get time to chase it ...

Thanks,

Ron Jeffries
www.XProgramming.com

···

On Mon, 19 Nov 2007 18:27:24 -0500, John Carter <john.carter@tait.co.nz> wrote:

My personal guess is you have a virus.

Hi,

···

On 16-Nov-07, at 3:48 AM, Peña, Botp wrote:

From: Ron Jeffries [mailto:ronjeffries@acm.org]
# it contains:
#
# -rubygems
#
# with the dash.

remove it.

I second this.

In fact, can you create a brand new user on your machine, log in as that user, and try it from there?

Cheers,
Bob

I think I reported earlier but may not have. Simiple ruby programs
like counting start a bit slower on my machine but then seem to run
just as fast as on Chet's. OTOH the Ruby unit tests go slowly.

I'm thinking I'll try turning off the rubygems thing and if that
doesn't crack it, try a full reinstall of Ruby. Cheaper than a new
computer, which I'm sure would fix it. :slight_smile:

Thanks ... keep those cards and letters coming.

Ron Jeffries
www.XProgramming.com

···

On Fri, 16 Nov 2007 03:48:56 -0500, Peña, Botp <botp@delmonte-phil.com> wrote:

then try creating and running a simple program like,

# sample.rb
5.times {puts "hello, world"}

\ruby sample.rb

let us narrow it down to pure ruby first by avoiding gem loading and long path traversals...