ruby-concurrency / concurrent-ruby

Modern concurrency tools including agents, futures, promises, thread pools, supervisors, and more. Inspired by Erlang, Clojure, Scala, Go, Java, JavaScript, and classic concurrency patterns.
https://ruby-concurrency.github.io/concurrent-ruby/
Other
5.68k stars 418 forks source link

Slow require 'concurrent' on windows #971

Closed Largo closed 1 year ago

Largo commented 1 year ago

Hi! So I'm on the hunt for the reason why my app needs seconds to start instead of miliseconds. I'm using TZInfo in my app which depends on concurrent-ruby. I'm not sure if anything can be done about it, as the issue might lie with ruby on windows but maybe it can be improved? I assume this also affects rails on windows startup.

require 'benchmark'
 puts Benchmark.measure {
     require   'concurrent'
}

Windows benchmark on an intel core i9 laptop: 0.047000 0.734000 0.781000 ( 2.150554)

Linux benchmark on a simple cloud VPS: 0.043045 0.003789 0.046834 ( 0.050957)

2.10 seconds vs 0.05 seconds

Thanks for your hard work!

* Operating system:                 win
* Ruby implementation:             Ruby 3.1.2
* `concurrent-ruby` version:       1.1.10
* `concurrent-ruby-ext` installed: no
* `concurrent-ruby-edge` used:      no
chrisseaton commented 1 year ago

Can you profile it for me?

I'm sorry I'm not going to be able to help with anything Windows-specific - I just don't know anything about it.

Largo commented 1 year ago

It is faster today, probably because of a cache, I've also checked the code and could only find one windows specific part, which doesn't seem to be an issue. It might just be "require" itself , which is known to be slower on windows.

require 'ruby-prof'

result = RubyProf.profile do
 require 'concurrent'
end

printer = RubyProf::FlatPrinter.new(result)
printer.print(File.open("ruby_prof_example_api1_profile.txt", "w+"))
Measure Mode: wall_time
Thread ID: 80
Fiber ID: 60
Total: 0.581108
Sort by: self_time

 %self      total      self      wait     child     calls  name                           location
 68.93      0.567     0.401     0.000     0.167      295  *Kernel#gem_original_require    
 17.81      0.104     0.104     0.000     0.000     3629   <Class::File>#file?            
  2.66      0.016     0.015     0.000     0.000        6  *Kernel#require_relative        
  2.15      0.013     0.013     0.000     0.000      105   <Class::File>#exist?           
  1.38      0.121     0.008     0.000     0.113     2281  *Array#any?                     
  0.68      0.004     0.004     0.000     0.000     1323   <Class::File>#join             
  0.50      0.003     0.003     0.000     0.000     3626   String#+                       
  0.44      0.003     0.003     0.000     0.000       75   Module#class_eval              
  0.36      0.147     0.002     0.000     0.145     1060   Gem::BasicSpecification#contains_requirable_file? C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/basic_specification.rb:72
  0.35      0.128     0.002     0.000     0.126     1060   Gem::BasicSpecification#have_file? C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/basic_specification.rb:332
  0.35      0.581     0.002     0.000     0.579      294  *Kernel#require                 <internal:C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:36
  0.35      0.002     0.002     0.000     0.000     4119   Gem::StubSpecification#data    C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:108
  0.29      0.003     0.002     0.000     0.002     1975   Gem::StubSpecification#extensions C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:168
  0.25      0.016     0.001     0.000     0.015     1060   Gem::StubSpecification#missing_extensions? C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:143
  0.24      0.153     0.001     0.000     0.152       63  *Array#each                     
  0.24      0.001     0.001     0.000     0.000     2151   Kernel#tap                     <internal:kernel>:89
  0.23      0.004     0.001     0.000     0.002     1062   Gem::BasicSpecification#have_extensions? C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/basic_specification.rb:330
  0.21      0.001     0.001     0.000     0.000        3   File#flock                     
  0.13      0.002     0.001     0.000     0.001     1060   Gem::StubSpecification#raw_require_paths C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:139
  0.13      0.002     0.001     0.000     0.001     1068   Gem::StubSpecification#full_name C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:179
  0.10      0.001     0.001     0.000     0.000     1975   Gem::StubSpecification::StubLine#extensions 
  0.10      0.002     0.001     0.000     0.001        3   Kernel#eval                    
  0.10      0.001     0.001     0.000     0.000     1065   <Module::Gem>#suffixes         C:/Ruby31-x64/lib/ruby/3.1.0/rubygems.rb:944
  0.10      0.001     0.001     0.000     0.000      238   IO#set_encoding                
  0.08      0.000     0.000     0.000     0.000     2011   Array#empty?                   
  0.07      0.000     0.000     0.000     0.000     1060   Gem::StubSpecification#default_gem? C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/stub_specification.rb:93
  0.07      0.000     0.000     0.000     0.000      942   Kernel#respond_to?             
  0.06      0.001     0.000     0.000     0.000      294   <Module::Gem>#find_unresolved_default_spec C:/Ruby31-x64/lib/ruby/3.1.0/rubygems.rb:1219
  0.06      0.000     0.000     0.000     0.000        3   IO#read                        
  0.05      0.000     0.000     0.000     0.000     1088   BasicObject#!                  
  0.05      0.000     0.000     0.000     0.000     1068   Gem::StubSpecification#gems_dir 
  0.05      0.000     0.000     0.000     0.000      411   Hash#[]                        
  0.05      0.000     0.000     0.000     0.000     1384   Module#method_added            
  0.05      0.000     0.000     0.000     0.000     1060   Gem::StubSpecification::StubLine#require_paths 
  0.04      0.000     0.000     0.000     0.000     1068   Gem::StubSpecification::StubLine#full_name 
  0.04      0.000     0.000     0.000     0.000       22   Module#attr_reader             
  0.03      0.000     0.000     0.000     0.000       20   Gem::Version#<=>               C:/Ruby31-x64/lib/ruby/3.1.0/rubygems/version.rb:347
chrisseaton commented 1 year ago

The top two make it seem like an IO issue? Are you one some kind of strange machine, or a virtualised machine?

This isn't likely to be a Concurrent Ruby issue, so I'm closing unless there is evidence otherwise. I'm happy to keep engaging with you here to try to help as best I can though.