Ruby IO Performance - What, Where, and When

33 views
Skip to first unread message

Jason Frey

unread,
Jan 27, 2011, 12:14:56 PM1/27/11
to RubyInstaller
Just yesterday I read Luis' article on engineyard:
http://www.engineyard.com/blog/2011/ruby-io-performance-what-where-and-when/
, and would love to help out. I noticed the discussion he linked to
was about a month old, and mainly involved just getting Ruby built, so
I'm starting this thread as a new direct offshoot from the article.

In the article tenderlove mentions trying strace side by side with
Linux, and the best system call viewer I could find (that actually
even worked) was API Monitor v2. I have not built Ruby with any debug
info, nor have I tried any side by side strace run with Linux, but I
figured I'd give you guys my first pass anyway. This may or may not
be a red herring :)

On that, I've been playing with the simple-bench-ruby-io, and the
results are interesting. Initially all I could see was a ton of calls
to EnterCriticalSection/LeaveCriticalSection. Removing that I noticed
an interesting pattern on what seems like a require.

It seems that rb_require eventually calls rb_find_file_ext, to
determine the file extension of the file to require. It does this by
trying every expected extension in every directory in the $LOAD_PATH,
using the API call FindFirstFileA (which is technically used for Dir
globbing), and then if that fails it tries GetFileAttributesA, until
it finds the file. These two calls seem to be made in winnt_stat
which is called by rb_w32_stat.

After finding the extension, it then makes its way to rb_find_file,
which searches the whole $LOAD_PATH AGAIN, even though we technically
already found the file in the _ext method prior. Below is the API
calls to load thread.rb (which in turn requires thread.so).

I think it would be good to see this side by side with what Linux
does.

Jason


FindFirstFileA ( ".\thread.rb", 0x0241ed10 )
GetFileAttributesA ( ".\thread.rb" )
FindFirstFileA ( ".\thread.so", 0x0241ed10 )
GetFileAttributesA ( ".\thread.so" )
FindFirstFileA ( ".\thread.dll", 0x0241ed10 )
GetFileAttributesA ( ".\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.dll", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.rb", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.dll", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.rb",
0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.so",
0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.dll",
0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.dll", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.rb", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.so", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.dll", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.dll", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.rb",
0x0241ecf0 )
FindClose ( 0x001bea10 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
FindFirstFileA ( ".\thread.rb", 0x0241ed10 )
GetFileAttributesA ( ".\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.rb", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.rb",
0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.rb", 0x0241ecd0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.rb", 0x0241ece0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.rb" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.rb",
0x0241ecf0 )
FindClose ( 0x001bea10 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
FindFirstFileA ( ".\thread.so", 0x0241e800 )
GetFileAttributesA ( ".\thread.so" )
FindFirstFileA ( ".\thread.dll", 0x0241e800 )
GetFileAttributesA ( ".\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.dll", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.dll", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.so",
0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.dll",
0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.dll", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.so", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.dll", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.dll", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.so",
0x0241e7e0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.dll",
0x0241e7e0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.dll" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\i386-
mingw32\thread.so", 0x0241e7d0 )
FindClose ( 0x001c0a30 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
FindFirstFileA ( ".\thread.so", 0x0241e800 )
GetFileAttributesA ( ".\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\1.8\i386-
msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby\thread.so",
0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\site_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby\1.8\i386-
msvcrt\thread.so", 0x0241e7c0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\1.8\i386-msvcrt\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so", 0x0241e7d0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\vendor_ruby
\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.so",
0x0241e7e0 )
GetFileAttributesA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\thread.so" )
FindFirstFileA ( "C:\pik\Ruby-187-p330\lib\ruby\1.8\i386-
mingw32\thread.so", 0x0241e7d0 )
FindClose ( 0x001c0a30 )
UnlockFile ( 0x000000a4, 0, 0, 4294967295, 4294967295 )
LoadLibraryA ( "C:/pik/Ruby-187-p330/lib/ruby/1.8/i386-mingw32/
thread.so" )

Chuck Remes

unread,
Jan 27, 2011, 12:21:29 PM1/27/11
to rubyin...@googlegroups.com
On Jan 27, 2011, at 11:14 AM, Jason Frey wrote:

> Just yesterday I read Luis' article on engineyard:
> http://www.engineyard.com/blog/2011/ruby-io-performance-what-where-and-when/
> , and would love to help out. I noticed the discussion he linked to
> was about a month old, and mainly involved just getting Ruby built, so
> I'm starting this thread as a new direct offshoot from the article.

I think that's a great idea!

>
> In the article tenderlove mentions trying strace side by side with
> Linux, and the best system call viewer I could find (that actually
> even worked) was API Monitor v2. I have not built Ruby with any debug
> info, nor have I tried any side by side strace run with Linux, but I
> figured I'd give you guys my first pass anyway. This may or may not
> be a red herring :)

Interesting stuff that you found. However, I do recommend that you repost that data as a pastie or gist so that it is more readable. You may have noticed that it was line-wrapped at around 78 characters, so it's really hard to decipher. Putting it into a pastie will preserve the line length and make it easier to read.

Also, please post a link to that API monitor that you found.

cr

Jason Frey

unread,
Jan 27, 2011, 12:28:42 PM1/27/11
to RubyInstaller
Oops...didn't realize there was a wrapping when I wrote it.

API Monitor v2: http://www.rohitab.com/apimonitor
Pastie of the API trace: http://pastie.org/1503094

Jason

On Jan 27, 12:21 pm, Chuck Remes <cremes.devl...@mac.com> wrote:
> On Jan 27, 2011, at 11:14 AM, Jason Frey wrote:
>
> > Just yesterday I read Luis' article on engineyard:
> >http://www.engineyard.com/blog/2011/ruby-io-performance-what-where-an...

Nikolai Weibull

unread,
Jan 27, 2011, 3:19:40 PM1/27/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 21:13, Nikolai Weibull <n...@bitwi.se> wrote:

> On Thu, Jan 27, 2011 at 18:14, Jason Frey <fry...@gmail.com> wrote:
>
>> It seems that rb_require eventually calls rb_find_file_ext, to
>> determine the file extension of the file to require.  It does this by
>> trying every expected extension in every directory in the $LOAD_PATH,
>> using the API call FindFirstFileA (which is technically used for Dir
>> globbing), and then if that fails it tries GetFileAttributesA, until
>> it finds the file.  These two calls seem to be made in winnt_stat
>> which is called by rb_w32_stat.

> This is part of the problem, but the biggest culprit (in 1.9.2) is
> that it calls expand_path on things it tries to require.  It does this
> a lot.  Expand_path stats every single part of the path leading up to
> the actual file, which is excruciatingly slow on Windows.

This becomes clear when you run Process Monitor, by the way. I
provided an example of this on both this list and on ruby-core, where
there was something close to but got no responses. Here’s my summary:

For some reason require does an insane amount of I/O. I’ve attached
logs that I generated from Process Monitor. (dtruss/strace will
generate similar, less verbose, results.) Not only does require stat
every directory component leading to the found file, once found, it,
if I understand things correctly, makes sure that specification.rb
actually exists 148 times!

It seems, from some slight debugging, that something funky is going on
in rb_get_expanded_load_path/rb_file_expand_path. These results have
to be cached to minimize I/O.

Luis Lavena

unread,
Jan 27, 2011, 3:21:25 PM1/27/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 5:13 PM, Nikolai Weibull <n...@bitwi.se> wrote:
> On Thu, Jan 27, 2011 at 18:14, Jason Frey <fry...@gmail.com> wrote:
>
>> It seems that rb_require eventually calls rb_find_file_ext, to
>> determine the file extension of the file to require.  It does this by
>> trying every expected extension in every directory in the $LOAD_PATH,
>> using the API call FindFirstFileA (which is technically used for Dir
>> globbing), and then if that fails it tries GetFileAttributesA, until
>> it finds the file.  These two calls seem to be made in winnt_stat
>> which is called by rb_w32_stat.
>
> This is part of the problem, but the biggest culprit (in 1.9.2) is
> that it calls expand_path on things it tries to require.  It does this
> a lot.  Expand_path stats every single part of the path leading up to
> the actual file, which is excruciatingly slow on Windows.
>

Hello Nikolai,

The awesome part is that 1.9.3 (trunk) already solved this issue, as I
indicated in the article:

"Something to note is that Ruby 1.9.2 really dropped loading
performance, which seems got fixed in 1.9.3 (trunk, not released
yet)."

--
Luis Lavena
AREA 17
-
Perfection in design is achieved not when there is nothing more to add,
but rather when there is nothing more to take away.
Antoine de Saint-Exupéry

Vít Ondruch

unread,
Jan 27, 2011, 1:42:37 PM1/27/11
to rubyin...@googlegroups.com
Hm, there is another issue which strikes me ... Why there are used ANSI
methods? ... This is not right :(

Vit

Dne 27.1.2011 18:14, Jason Frey napsal(a):

Luis Lavena

unread,
Jan 27, 2011, 3:32:15 PM1/27/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 3:42 PM, Vít Ondruch <v.on...@gmail.com> wrote:
> Hm, there is another issue which strikes me ... Why there are used ANSI
> methods? ... This is not right :(
>

That is 1.8.7 :-P

Breathe... we need to look at 1.9.3, all the methods should be W ;-)

Nikolai Weibull

unread,
Jan 27, 2011, 3:37:33 PM1/27/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 21:21, Luis Lavena <luisl...@gmail.com> wrote:
> On Thu, Jan 27, 2011 at 5:13 PM, Nikolai Weibull <n...@bitwi.se> wrote:
>> On Thu, Jan 27, 2011 at 18:14, Jason Frey <fry...@gmail.com> wrote:
>>
>>> It seems that rb_require eventually calls rb_find_file_ext, to
>>> determine the file extension of the file to require.  It does this by
>>> trying every expected extension in every directory in the $LOAD_PATH,
>>> using the API call FindFirstFileA (which is technically used for Dir
>>> globbing), and then if that fails it tries GetFileAttributesA, until
>>> it finds the file.  These two calls seem to be made in winnt_stat
>>> which is called by rb_w32_stat.
>>
>> This is part of the problem, but the biggest culprit (in 1.9.2) is
>> that it calls expand_path on things it tries to require.  It does this
>> a lot.  Expand_path stats every single part of the path leading up to
>> the actual file, which is excruciatingly slow on Windows.

> The awesome part is that 1.9.3 (trunk) already solved this issue, as I


> indicated in the article:
>
> "Something to note is that Ruby 1.9.2 really dropped loading
> performance, which seems got fixed in 1.9.3 (trunk, not released
> yet)."

Sorry, I must have missed that paragraph (in my rather quick
read-through). That’s excellent news. Perhaps now I can finally move
on to 1.9.2.

Jon

unread,
Jan 27, 2011, 4:02:19 PM1/27/11
to rubyin...@googlegroups.com
> > This is part of the problem, but the biggest culprit (in 1.9.2) is
> > that it calls expand_path on things it tries to require.  It does this
> > a lot.  Expand_path stats every single part of the path leading up to
> > the actual file, which is excruciatingly slow on Windows.
>
> This becomes clear when you run Process Monitor, by the way. I
> provided an example of this on both this list and on ruby-core, where
> there was something close to but got no responses. Here’s my summary:

Amazing isn't it when you do something very simple like filter by "Process Name is ruby.exe" in Process Monitor and do:

ruby --disable-gems -ve ""

...hey, what are you doing traversing my "C:\ruby19trunk\lib\ruby\gems\1.9.1\gems" dir with CreateFile, SetBasicInformationFile, etc??


> It seems, from some slight debugging, that something funky is going on
> in rb_get_expanded_load_path/rb_file_expand_path. These results have
> to be cached to minimize I/O.

Ah, here comes the clone the GitHub Ruby repo, patch-o-rama, and "rake ruby19 local=c:\ruby-trunk-git" dance ;)


Jon

---
blog: http://jonforums.github.com/
twitter: @jonforums

Jason Frey

unread,
Jan 27, 2011, 4:24:00 PM1/27/11
to RubyInstaller
Yes, on 1.9.3 trunk the code is using FindFirstFileW.

On Jan 27, 3:32 pm, Luis Lavena <luislav...@gmail.com> wrote:

Luis Lavena

unread,
Jan 27, 2011, 3:52:47 PM1/27/11
to rubyin...@googlegroups.com

Hello Jason,

Awesome findings, and I appreciate your interest in help us!

I've started to look into this but using ruby-trunk as base.

I would suggest we build ruby from source and clone Ruby repository,
so we have a working environment to look at.

1) Have Ruby 1.8.7 installed (ehem, you can download RubyInstaller)

CHECK, you already have that ;-)

2) Clone RubyInstaller repository:

git clone git://github.com/oneclick/rubyinstaller.git rubyinstaller

3) Clone Ruby repository:

git clone git://github.com/ruby/ruby.git ruby

4) Build Ruby using RubyInstaller:

cd rubyinstaller
rake ruby19 LOCAL=C:\Path\To\Where\I\Cloned\ruby

5) Get some tea, this is going to take some time ;-)

6) Profile against sandbox\ruby19_mingw\bin\ruby.exe directory

If you used the simple-bench-ruby-io, then you will need to install
isolate into that sandboxed ruby.

Open a new console and add sandbox\ruby19_mingw\bin to the PATH, and
then "gem install isolate --pre"

From there, you can run the profiling and let's see what is the result ;-)

Another trick is that you can:

rake ruby19:dependencies devkit:sh

And inside bash, go into sandbox/ruby19_build

And do: make

If you updated files in Ruby source code, these changes will trigger
new file compilation, then you can "make install" which will target
the sandbox directory we had...

Oh la la.. hope I'm not causing you dizziness!

Nikolai Weibull

unread,
Jan 27, 2011, 3:13:38 PM1/27/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 18:14, Jason Frey <fry...@gmail.com> wrote:

> It seems that rb_require eventually calls rb_find_file_ext, to
> determine the file extension of the file to require.  It does this by
> trying every expected extension in every directory in the $LOAD_PATH,
> using the API call FindFirstFileA (which is technically used for Dir
> globbing), and then if that fails it tries GetFileAttributesA, until
> it finds the file.  These two calls seem to be made in winnt_stat
> which is called by rb_w32_stat.

This is part of the problem, but the biggest culprit (in 1.9.2) is

Jason Frey

unread,
Jan 28, 2011, 2:10:27 AM1/28/11
to RubyInstaller
Ok, got through all the steps, and am able to run the simple-bench-
ruby-io against 1.9.3 trunk build.

Incidentally, there were a couple issues that I made it through.
- I kept getting connection timeouts when downloading things, but just
rerunning the rake worked perfect.
- openssl.org is down...had to manually download from a mirror
- After the build, running the simple-bench-ruby-io I'm getting an
error in lib\ruby\1.9.1\rubygems\format.rb: Uninitialized constant
Gem::UserInteraction. I just commented out the line and was able to
proceed

Ready for the next steps!

Jason

On Jan 27, 3:52 pm, Luis Lavena <luislav...@gmail.com> wrote:
> On Thu, Jan 27, 2011 at 2:14 PM, Jason Frey <fryg...@gmail.com> wrote:
> > Just yesterday I read Luis' article on engineyard:
> >http://www.engineyard.com/blog/2011/ruby-io-performance-what-where-an...

Luis Lavena

unread,
Jan 28, 2011, 10:03:36 AM1/28/11
to rubyin...@googlegroups.com
On Fri, Jan 28, 2011 at 4:10 AM, Jason Frey <fry...@gmail.com> wrote:
> Ok, got through all the steps, and am able to run the simple-bench-
> ruby-io against 1.9.3 trunk build.
>

Awesome!

> Incidentally, there were a couple issues that I made it through.
> - I kept getting connection timeouts when downloading things, but just
> rerunning the rake worked perfect.

co> - openssl.org is down...had to manually download from a mirror

Ouch, OpenSSL is on and off to often. Definitely we need to change to
a better mirror.

Can you provide me a link where you got it?

> - After the build, running the simple-bench-ruby-io I'm getting an
> error in lib\ruby\1.9.1\rubygems\format.rb: Uninitialized constant
> Gem::UserInteraction.  I just commented out the line and was able to
> proceed
>

Yeah, format is not depending anymore on User interaction:

https://github.com/rubygems/rubygems/commit/d95c34d438723bc9b31d01428c0ba36a1a7b818c

> Ready for the next steps!
>

Yay!!!

I would love get your thoughts after running against trunk.

Specially the excessive lookup you mention on your post, if we can
track it down and reduce it, will be the first win.

For the time being, you can add a "gets" to the start of app.rb so you
can hook the running process with API Monitor and only trace loading
after the whole VM is initialized, that will help us find out what to
optimize outside of the VM startup stuff.

Keep the feedback coming, I'm loving it!

Thank you for your time and eagerly looking forward your next steps email!

Jason Frey

unread,
Jan 28, 2011, 10:20:51 AM1/28/11
to RubyInstaller
> co> - openssl.org is down...had to manually download from a mirror
>
> Ouch, OpenSSL is on and off to often. Definitely we need to change to
> a better mirror.
>
> Can you provide me a link where you got it?

I used the one here: http://mirrors.ibiblio.org/pub/mirrors/openssl/source/

Jason

Gordon Thiesfeld

unread,
Jan 28, 2011, 2:18:24 PM1/28/11
to rubyin...@googlegroups.com
On Thu, Jan 27, 2011 at 2:32 PM, Luis Lavena <luisl...@gmail.com> wrote:
> On Thu, Jan 27, 2011 at 3:42 PM, Vít Ondruch <v.on...@gmail.com> wrote:
>> Hm, there is another issue which strikes me ... Why there are used ANSI
>> methods? ... This is not right :(
>>
>
> That is 1.8.7 :-P
>
> Breathe... we need to look at 1.9.3, all the methods should be W ;-)
>

I'm not certain if I'm interpreting this data[1] correctly, but it
looks like FindFirstFileA is getting used in some places. I'm
basically just loading rubygems and exiting, using:

ruby 1.9.3dev (2011-01-28 trunk 30684) [i386-mingw32]

I did find a call to FindFirstFile in: file.c:3148: h = FindFirstFile(b, &wfd);

I believe that's part of File#expand_path.

Also, it seems like when FindFirstFileW is used, it does what looks
like a recursive descent down the path, even though we should know the
exact location of the file from the previous FindFirstFileA

[1] https://gist.github.com/800767

--
Gordon Thiesfeld
http://vert.igino.us

Gordon Thiesfeld

unread,
Jan 28, 2011, 7:55:21 PM1/28/11
to rubyin...@googlegroups.com

Luis and I dug into this a bit this evening. Here is my understanding
of the issue:

When a ruby file is required, first the files is located in the
load_path, (several stats to every dir in the load path until the file
is found). These stats seem necessary, although Dusan Majkic has some
teriffic ideas on how to optimize stat itself.

Once the ruby file is found, it's loaded via a call to
rb_load_internal, which makes a call to rb_realpath_internal.
rb_real_path_internal is used to find the real path of a file. I was
thinking this had to do with relative vs. absolute paths, but Luis
thinks it is more to do with symlinks. rb_real_path_internal makes a
call to rb_real_path_rec, which resolves by doing a stat to every
directory in the path to the file to make sure it's real. If a file
is 10 directories deep, that is 10 stats, and 20 API calls, for a file
whose absolute path we already know.

Here's a gist to show you what I mean. Basically, I fired up IRB and
attached to it with API Monitor V2. I then did a single method call
to File#realpath.

https://gist.github.com/801331

My hope is that we can short-circuit this (seemingly) unneeded
path-traversal on Windows.

Vít Ondruch

unread,
Jan 29, 2011, 7:28:28 AM1/29/11
to rubyin...@googlegroups.com
Dne 29.1.2011 1:55, Gordon Thiesfeld napsal(a):

> On Fri, Jan 28, 2011 at 1:18 PM, Gordon Thiesfeld<gthie...@gmail.com> wrote:
>> On Thu, Jan 27, 2011 at 2:32 PM, Luis Lavena<luisl...@gmail.com> wrote:

How does it work with hardlinks on Windows? Could it be issue? How often
are hardlinks used on Windows? It seems that they are used more often
than before, eg "Users" and "Documents and Settings" on W7 ...

Vit

Gordon Thiesfeld

unread,
Jan 29, 2011, 9:18:41 AM1/29/11
to rubyin...@googlegroups.com
I need to do a bit more testing of realpath's behavior.  I did figure out that it resolves relative paths to absolute paths, but I haven't tested any symlinks yet.   I'll try to spend some time on it this weekend.

I also found the windows API function GetFinalPathNameByHandle. I'm hoping that will provide the same functionality. 


Gordon

Gordon Thiesfeld

unread,
Jan 29, 2011, 10:23:55 AM1/29/11
to rubyin...@googlegroups.com

Ok, the below gist shows my findings. It doesn't seem to be aware of
links on Windows. On my machine, C:\repo is a soft link to
C:\users\gthiesfeld\Work\repo. And "C:\Documents and Settings" is a
hard link to C:\Users. It seems to have the same behavior as
File#expand_path, but goes about it differently.

I tried to line up the stuff I was doing in IRB with what I was seeing
in API Monitor. The lines from API mon starts with ###.

https://gist.github.com/801907

Luis Lavena

unread,
Jan 29, 2011, 2:55:20 PM1/29/11
to rubyin...@googlegroups.com
On Sat, Jan 29, 2011 at 9:28 AM, Vít Ondruch <v.on...@gmail.com> wrote:
>
> How does it work with hardlinks on Windows? Could it be issue? How often are
> hardlinks used on Windows? It seems that they are used more often than
> before, eg "Users" and "Documents and Settings" on W7 ...
>

I will say no issue.

realpath_rec, which is used by rb_realpath_internal, traverse
directory by directory and build a hash of each of the elements
iterated before.

This is to avoid possible infinite recursion.

Now, realpath_rec traverse each part of the path requested and stat
it. It will only resolve links if readlink() is present (#ifdef
HAVE_READLINK)

That is the only recursive part that resolve symlinks, and only if
readlink() is present, which is not under Windows.

So, no matter if you have a Junction, Hardlink or Symlink, the results
are the same:

>ruby -v
ruby 1.9.3dev (2011-01-30 trunk 30723) [i386-mingw32]

Results:

https://gist.github.com/802121

realpath_rec do not resolve symlinks on Windows, IMO, and it will not
avoid infinite recursion due a bad symlink/hardlink/junction point.

So, to Gordon's point:

realpath_rec needs an optimized version for Windows that do not
require stat every single directory, since stat information is not
cached for already stated directories.

To Dusan's point:

winnt_stat needs to introduce newer Windows API to the cost of Windows
2000 or greater, dropping support for previous versions.

To conclude:

>type gem.bat
@ECHO OFF
IF NOT "%~f0" == "~f0" GOTO :WinNT
ECHO.This version of Ruby has not been built with support for Windows 95/98/Me.
GOTO :EOF

rubyinstaller.org Windows OS drilldown:

7: 51%
XP: 38%
Vista: 9%
Server 2003: 1%
2000: 0.16%
98: 0.02%
ME: 0.01%
NT: 0.01%

Reply all
Reply to author
Forward
0 new messages