From: Brian Candler Date: 2008-12-10T18:04:33+09:00 Subject: 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/.