Re: Way to many calls to Dir#[]

Tj Holowaychuk wrote:
> Im not using windows either haha. just took a look at the highline 
> source looks like it conditionally supports termios so your right there. 

And win32 too:

$ pwd
/usr/lib/ruby/gems/1.8/gems/highline-1.5.0
$ find . -type f | xargs grep -i win32
./lib/highline/system_extensions.rb:      require "Win32API" 
# See if we're on Windows.
./lib/highline/system_extensions.rb:      CHARACTER_MODE = "Win32API" 
# For Debugging purposes only.
./lib/highline/system_extensions.rb:        Win32API.new("crtdll", 
"_getch", [ ], "L").Call
./lib/highline/system_extensions.rb:        m_GetStdHandle 
= Win32API.new( 'kernel32',
./lib/highline/system_extensions.rb:        m_GetConsoleScreenBufferInfo 
= Win32API.new(
./test/tc_highline.rb:if HighLine::CHARACTER_MODE == "Win32API"
./test/tc_highline.rb:    assert(%w[Win32API termios 
stty].include?(HighLine::CHARACTER_MODE))

However there is only a single require of Win32API, and if it fails a 
LoadError is rescued which should cause it to install termios methods 
instead. It shouldn't attempt to load Win32API again after that.

> I see your point though, if its a long running process I guess 0.35 of a 
> second is not much, just seemed really sketchy to me being new to Ruby

Now I know you're not on Windows, let me look a bit more. Here's what I 
get (P4 2.8GHz, 1.8.6p111, rubygems 1.2.0), giving the second run times 
for each test:

$ time for i in $(seq 1 10); do ruby -rubygems -e0; done

real  0m0.646s
user  0m0.568s
sys  0m0.060s

$ time for i in $(seq 1 10); do ruby -rubygems -e'require "termios"'; 
done

real  0m0.707s
user  0m0.612s
sys  0m0.072s

$ time for i in $(seq 1 10); do ruby -rubygems -e'require "highline"'; 
done

real  0m2.680s
user  0m2.380s
sys  0m0.244s

So there is a substantial startup overhead in including highline, which 
for me is about 0.2s more than just loading ruby + rubygems + termios.

But when I profile this, I find that Dir[] is a very long way down the 
list.

$ ruby -rubygems -rprofile -e'require "highline"'
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 23.23     1.05      1.05      248     4.23    23.79  Array#each
  7.08     1.37      0.32     5522     0.06     0.09  Kernel.===
  6.86     1.68      0.31      502     0.62     0.62  Regexp#===
  4.20     1.87      0.19     6987     0.03     0.03  Module#===
  3.32     2.02      0.15     5501     0.03     0.03  Kernel.==
  2.88     2.15      0.13     1664     0.08     0.10  Kernel.dup
  2.88     2.28      0.13      104     1.25    31.73 
Gem::Specification#initialize
  2.43     2.39      0.11      303     0.36     0.83 
Gem::Version#normalize
  2.43     2.50      0.11       25     4.40    47.60 
Kernel.gem_original_require
  2.21     2.60      0.10        1   100.00   140.00  Array#sort
  1.99     2.69      0.09      104     0.87     0.87  IO#read
  1.99     2.78      0.09      209     0.43     0.53 
Gem::Specification#full_name
... skip lots ...
  0.44     4.25      0.02      144     0.14     0.14  Dir#[]
...

(Whilst it's possible that Dir#[] is using a lot more *real* time than 
*CPU* time - and there was a post about fixing profile for this a week 
or two back - you can see from above that the total real time is very 
close to user+sys time in this case. That's what I'd expect when the 
directories are in the VFS cache, that is, no actual disk I/O is done 
when searching through directories)

Sorting by total ms/call, I get:

$ env LC_ALL=C sort -rn -k6 ert | head -20
  0.00     4.52      0.00        1     0.00  4520.00  #toplevel
  0.00     4.52      0.00        1     0.00  4090.00 
Gem::GemPathSearcher#initialize
  0.00     4.52      0.00        1     0.00  3880.00 
Gem::GemPathSearcher#init_gemspecs
  0.00     4.52      0.00        1     0.00  3740.00 
Gem::SourceIndex#from_installed_gems
  0.00     4.52      0.00        1     0.00  3620.00 
Gem::SourceIndex#refresh!
  0.00     4.52      0.00        1     0.00  3620.00 
Gem::SourceIndex#load_gems_in
  0.00     4.52      0.00        1     0.00  3620.00 
Gem::SourceIndex#from_gems_in
  0.00     4.52      0.00        1     0.00  3620.00  Array#reverse_each
  0.00     4.52      0.00        2     0.00  2045.00  Mutex#synchronize
  0.00     4.52      0.00        2     0.00  2045.00  Gem.searcher
  0.00     4.52      0.00        2     0.00  1870.00  Gem.source_index
  0.22     4.33      0.01       24     0.42   225.42  Kernel.require
  2.21     2.60      0.10        1   100.00   140.00  Array#sort
  0.00     4.52      0.00        1     0.00   120.00 
Gem::SourceIndex#installed_spec_directories
  0.00     4.52      0.00        1     0.00   120.00  Gem.set_paths
  0.00     4.52      0.00        1     0.00   120.00  Gem.path
  0.00     4.52      0.00        1     0.00   110.00  Gem.set_home
  0.00     4.52      0.00        1     0.00   110.00  Gem.dir
  0.00     4.52      0.00        2     0.00    60.00 
Gem.ensure_gem_subdirectories
  0.00     4.52      0.00        2     0.00    50.00 
Gem::GemPathSearcher#find
...

So there's a lot of rubygems chomping going on. Optimising that may be 
difficult, I'm afraid. I tried reading the rubygems source once, and 
gave up :-)

Notice that whilst there are 24 calls to Kernel.require, there is only 1 
call to Gem::GemPathSearcher#initialize accounting for most of the work. 
Perhaps highline forces rubygems to do some dependency calculations, 
whereas an itsy-bitsy standalone gem like termios doesn't.

Indeed, when loading only termios, this doesn't seem to be done:

$ ruby -rubygems -rprofile -e'require "termios"' 2>&1 | env LC_ALL=C 
sort -rn -k6 | head
  0.00     0.09      0.00        1     0.00    90.00  #toplevel
 55.56     0.05      0.05        1    50.00    80.00  Array#each
  0.00     0.09      0.00        1     0.00    80.00 
Enumerable.each_with_index
 11.11     0.09      0.01        2     5.00    50.00 
Kernel.gem_original_require
  0.00     0.09      0.00        2     0.00    50.00  Kernel.require
 33.33     0.08      0.03      514     0.06     0.06  Hash#[]=
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.09      0.00      257     0.00     0.00  Integer#to_int
  0.00     0.09      0.00      257     0.00     0.00  Array#pack
  0.00     0.09      0.00       64     0.00     0.00  String#eql?

Regards,

Brian.
-- 
Posted via http://www.ruby-forum.com/.