Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow require 'concurrent' on windows #971

Closed
Largo opened this issue Nov 22, 2022 · 3 comments
Closed

Slow require 'concurrent' on windows #971

Largo opened this issue Nov 22, 2022 · 3 comments

Comments

@Largo
Copy link

Largo commented Nov 22, 2022

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
Copy link
Member

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
Copy link
Author

Largo commented Nov 23, 2022

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
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants