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

Fix slow load time of metanorma command without use of bundler #81

Open
ronaldtse opened this issue May 23, 2019 · 21 comments
Open

Fix slow load time of metanorma command without use of bundler #81

ronaldtse opened this issue May 23, 2019 · 21 comments
Assignees
Labels
bug Something isn't working

Comments

@ronaldtse
Copy link
Contributor

After installing metanorma (without using bundle), running the metanorma command is super slow. Notice that the slow code is at bin/metanorma:23.

This urgently needs fixing.

$ metanorma
^CTraceback (most recent call last):
	32: from /Users/me/.rbenv/versions/2.5.1/bin/metanorma:23:in `<main>'
	31: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems.rb:309:in `activate_bin_path'
	30: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems.rb:309:in `synchronize'
	29: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems.rb:311:in `block in activate_bin_path'
	28: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems.rb:239:in `finish_resolve'
	27: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:122:in `require'
	26: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:122:in `require'
	25: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/request_set.rb:440:in `<top (required)>'
	24: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:122:in `require'
	23: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:122:in `require'
	22: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/request_set/lockfile.rb:238:in `<top (required)>'
	21: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:88:in `require'
	20: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1107:in `find_in_unresolved_tree'
	19: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1107:in `each'
	18: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1108:in `block in find_in_unresolved_tree'
	17: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2651:in `traverse'
	16: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2651:in `each'
	15: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2653:in `block in traverse'
	14: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2653:in `each'
	13: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2658:in `block (2 levels) in traverse'
	12: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1109:in `block (2 levels) in find_in_unresolved_tree'
	11: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1726:in `conficts_when_loaded_with?'
	10: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1726:in `any?'
	 9: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1727:in `block in conficts_when_loaded_with?'
	 8: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1727:in `any?'
	 7: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:1727:in `block (2 levels) in conficts_when_loaded_with?'
	 6: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/specification.rb:2419:in `satisfies_requirement?'
	 5: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/requirement.rb:247:in `satisfied_by?'
	 4: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/requirement.rb:247:in `all?'
	 3: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/requirement.rb:247:in `each'
	 2: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/requirement.rb:247:in `block in satisfied_by?'
	 1: from /Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/requirement.rb:24:in `block in <class:Requirement>'
/Users/me/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/version.rb:304:in `release': Interrupt
@ronaldtse ronaldtse added the bug Something isn't working label May 23, 2019
@ronaldtse
Copy link
Contributor Author

This file is generated by RubyGems:

bin/metanorma:

#!/Users/me/.rbenv/versions/2.5.1/bin/ruby
#
# This file was generated by RubyGems.
#
# The application 'metanorma-cli' is installed as part of a gem, and
# this file is here to facilitate running it.
#

require 'rubygems'

version = ">= 0.a"

str = ARGV.first
if str
  str = str.b[/\A_(.*)_\z/, 1]
  if str and Gem::Version.correct?(str)
    version = str
    ARGV.shift
  end
end

if Gem.respond_to?(:activate_bin_path)
load Gem.activate_bin_path('metanorma-cli', 'metanorma', version)   # <=== This is the line that loads for a long time
else
gem "metanorma-cli", version
load Gem.bin_path("metanorma-cli", "metanorma", version)
end

@ronaldtse
Copy link
Contributor Author

This apparently only appears in 2.5.x, not 2.6 (works fine in 2.6, with a short lag).

@CAMOBAP
Copy link
Contributor

CAMOBAP commented Jun 9, 2019

According to my research, we fall into a problem which described here https://www.sitepoint.com/rubygems-slow/

I did rbenv exec rbtrace --slow 2000 --exec metanorma and found many calls to Gem::Specification.find_in_unresolved_tree each of this call took 2-3 second

As far as I understood the only solution for this is 'cleanup' installed gems and remove unused versions of gem

@ronaldtse @abunashir let me know wht do you think about this?

@ronaldtse
Copy link
Contributor Author

@CAMOBAP795 I believe this is also due to our laxness in gemspec version specification. We need to ensure each metanorma gem has a tight version dependency. This is related to https://github.com/metanorma/metanorma-release.

@abunashir
Copy link
Member

@ronaldtse: by any chance do you have METANORMA_DEV_MODE environment variable set to true?

@ronaldtse
Copy link
Contributor Author

Of course not 😉

@abunashir
Copy link
Member

I tried a clean installation in ruby 2.5.1, it seems to be okay in my machine, but it does install around 50 gems 😨

Trying to reproduce the issue, could you please sent me your gem list | grep metanorma-cli?

@ronaldtse
Copy link
Contributor Author

metanorma-cli (1.2.0, 1.1.8, 1.1.7, 1.1.6, 1.1.5, 1.1.4, 1.1.3, 1.1.2, 1.1.0, 1.0.10, 1.0.0)

@ronaldtse
Copy link
Contributor Author

I believe the problem is more pronounced due to this issue (posted by sorah , a Ruby committer):

aws/aws-sdk-ruby#1811

And there is a problem where the gemspecs aren't limiting the gems (too many gems match the criteria).

@abunashir
Copy link
Member

@ronaldtse: Yap, what's your suggestion to resolve this issue?

@ronaldtse
Copy link
Contributor Author

ronaldtse commented Jul 1, 2019

The suggested fix is: "Resolve gem versions early on":

From aws/aws-sdk-ruby#1811 (comment)

But as you're saying, causing slow load pain with require "aws-sdk" is not intentional behavior (I understand you're agreeing with this).

That method does allow you to load a specific gem version, but it needs to be specified in code.

No. Kernel#gem is to activate gems, and optionally takes requirements. https://docs.ruby-lang.org/en/2.5.0/Kernel.html#method-i-gem
Version constraints are not required.

The problem I've explained earlier is: Activating aws-sdk gem causes unresolved dependencies (unresolved_deps) to the service gems . But they remains unresolved because aws-sdk-resources.rb just registers service gems for autoloading.

Rubygems may try to find a file from unresolved_deps (with trying all possible gem version combinations) when requiring new files. require "aws-sdk" with this situation triggers that code path. (Actually, it happens when requiring standard libraries such as cgi, in inside of aws-sdk-core.rb)

The code path becomes slow when an environment has many aws-* gem versions.

The solution is to resolve gems in unresolved_deps. One is to require them (which activates a gem inside require method), and alternate one is to just activate them using Kernel#gem method.

@abunashir
Copy link
Member

@ronaldtse: I don't have an exact idea to fix this one yet, is it something major and worth spending the time now or should we postponed this until it become a big problem?

@ronaldtse
Copy link
Contributor Author

@abunashir this is actually quite a significant problem for people who have upgraded the metanorma gem several times without using bundler. Can you help us resolve this? Thanks!

@ronaldtse
Copy link
Contributor Author

Ping @abunashir.

@ronaldtse
Copy link
Contributor Author

As mentioned in aws/aws-sdk-ruby#1811 (comment):

The solution is to resolve gems in unresolved_deps. One is to require them (which activates a gem inside require method), and alternate one is to just activate them using Kernel#gem method.

One more thing: As I explained require "aws-sdk" leds many unresolved_deps unresolved, any requiring standard libraries after require "aws-sdk" could be also slow.

$ irb -raws-sdk
(slow)
>> require 'cgi'
(slow!)
=> false
>> Gem::Specification.unresolved_deps
=> [... so many  aws-* gems ...]

I think we should:

  1. Verify that our issue is caused by Gem::Specification.unresolved_deps
  2. Fix this issue using the recommendation above.

@ronaldtse
Copy link
Contributor Author

Here what happens when I require metanorma-cli. It took over a minute to start.

$ irb -rmetanorma-cli
/Users/me/.rbenv/versions/2.6.6/lib/ruby/2.6.0/irb/init.rb:280: warning: Gem::ConflictError: Unable to activate asciimath2unitsml-0.1.3, because nokogiri-1.11.1-x86_64-darwin conflicts with nokogiri (~> 1.10.4)
irb(main):001:0> Gem::Specification.unresolved_deps
=> 
{"thor"=>
  Gem::Dependency.new("thor", Gem::Requirement.new(["~> 1.0"]), :runtime),
 "metanorma-iso"=>
  Gem::Dependency.new("metanorma-iso",
   Gem::Requirement.new(["~> 1.7.0"]),
   :runtime),
 "metanorma-ietf"=>
  Gem::Dependency.new("metanorma-ietf",
   Gem::Requirement.new(["~> 2.2.0"]),
   :runtime),
 "metanorma-iec"=>
  Gem::Dependency.new("metanorma-iec",
   Gem::Requirement.new(["~> 1.2.0"]),
   :runtime),
 "metanorma-cc"=>
  Gem::Dependency.new("metanorma-cc",
   Gem::Requirement.new(["~> 1.6.0"]),
   :runtime),
 "metanorma-csa"=>
  Gem::Dependency.new("metanorma-csa",
   Gem::Requirement.new(["~> 1.7.0"]),
   :runtime),
 "metanorma-m3aawg"=>
  Gem::Dependency.new("metanorma-m3aawg",
   Gem::Requirement.new(["~> 1.6.0"]),
   :runtime),
 "metanorma-bipm"=>
  Gem::Dependency.new("metanorma-bipm",
   Gem::Requirement.new(["~> 1.0.0"]),
   :runtime),
 "metanorma-standoc"=>
  Gem::Dependency.new("metanorma-standoc",
   Gem::Requirement.new(["~> 1.8.0"]),
   :runtime),
 "isodoc"=>
  Gem::Dependency.new("isodoc",
   Gem::Requirement.new([">= 1.5.0", "~> 1.5.0"]),
   :runtime),
 "metanorma-un"=>
  Gem::Dependency.new("metanorma-un",
   Gem::Requirement.new(["~> 0.5.0"]),
   :runtime),
 "metanorma-ogc"=>
  Gem::Dependency.new("metanorma-ogc",
   Gem::Requirement.new(["~> 1.2.0"]),
   :runtime),
 "metanorma-nist"=>
  Gem::Dependency.new("metanorma-nist",
   Gem::Requirement.new(["~> 1.2.0"]),
   :runtime),
 "metanorma-itu"=>
  Gem::Dependency.new("metanorma-itu",
   Gem::Requirement.new(["~> 1.2.0"]),
   :runtime),
 "metanorma-iho"=>
  Gem::Dependency.new("metanorma-iho",
   Gem::Requirement.new(["~> 0.2.0"]),
   :runtime),
 "git"=>Gem::Dependency.new("git", Gem::Requirement.new(["~> 1.5"]), :runtime),
 "metanorma-utils"=>
  Gem::Dependency.new("metanorma-utils",
   Gem::Requirement.new(["~> 1.0.2", "~> 1.0.3"]),
   :runtime),
 "pry"=>Gem::Dependency.new("pry", Gem::Requirement.new([">= 0"]), :runtime),
 "fontist"=>
  Gem::Dependency.new("fontist", Gem::Requirement.new(["~> 1.8"]), :runtime),
 "liquid"=>
  Gem::Dependency.new("liquid", Gem::Requirement.new([">= 0"]), :runtime),
 "metanorma-plugin-lutaml"=>
  Gem::Dependency.new("metanorma-plugin-lutaml",
   Gem::Requirement.new(["~> 0.2.1"]),
   :runtime),
 "relaton"=>
  Gem::Dependency.new("relaton",
   Gem::Requirement.new([">= 1.6", "~> 1.7.0"]),
   :runtime),
 "concurrent-ruby"=>
  Gem::Dependency.new("concurrent-ruby",
   Gem::Requirement.new([">= 0"]),
   :runtime),
 "unicode2latex"=>
  Gem::Dependency.new("unicode2latex",
   Gem::Requirement.new(["~> 0.0.1"]),
   :runtime),
 "ox"=>Gem::Dependency.new("ox", Gem::Requirement.new(["~> 2.13"]), :runtime)}

@ronaldtse
Copy link
Contributor Author

The 'unresolved_deps' occur when a gemspec contains this dependency, but has not been "require"d in Ruby (e.g. require 'ox' will resolve the "ox" entry here).

@abunashir
Copy link
Member

From @ronaldtse:

metanorma (1.2.7, 1.2.6, 1.2.5, 1.2.4, 1.2.3, 1.2.2, 1.2.1, 1.0.5)
metanorma-bipm (1.0.6, 1.0.5, 1.0.4, 1.0.3, 1.0.2, 1.0.1, 1.0.0)
metanorma-cc (1.6.8, 1.6.7, 1.6.6, 1.6.5, 1.6.4, 1.6.3, 1.6.2, 1.6.1, 1.6.0)
metanorma-cli (1.4.6, 1.4.5, 1.4.4, 1.4.3, 1.4.2, 1.4.1, 1.4.0, 1.3.9, 1.3.8.1, 1.2.13.1)
metanorma-csa (1.7.6, 1.7.5, 1.7.4, 1.7.3, 1.7.2, 1.7.1, 1.7.0, 1.6.8, 1.6.7, 1.4.12)
metanorma-csd (1.3.23)
metanorma-gb (1.5.8, 1.3.26)
metanorma-generic (1.9.0, 1.8.2, 1.8.1, 1.8.0, 1.7.3, 1.4.10)
metanorma-iec (1.2.16, 1.2.15, 1.2.14, 1.2.13, 1.2.12, 1.2.11, 1.2.10, 1.2.9, 1.0.8)
metanorma-ietf (2.2.9, 2.2.8, 2.2.7, 2.2.6, 2.2.5, 2.2.4, 2.0.12)
metanorma-iho (0.2.15, 0.2.14, 0.2.13, 0.2.12, 0.2.11, 0.2.10, 0.2.9, 0.2.8, 0.2.7, 0.0.3)
metanorma-iso (1.7.3, 1.7.2, 1.7.1, 1.7.0, 1.6.1, 1.6.0, 1.5.14, 1.5.13, 1.5.12, 1.3.26)
metanorma-itu (1.2.15, 1.2.14, 1.2.13, 1.2.12, 1.2.11, 1.2.10, 1.2.9, 1.2.8, 1.2.7, 1.0.17)
metanorma-m3aawg (1.6.8, 1.6.7, 1.6.6, 1.6.5, 1.6.4, 1.6.3, 1.6.2, 1.6.1, 1.6.0)
metanorma-m3d (1.3.21)
metanorma-nist (1.2.14, 1.2.13, 1.2.12, 1.2.11, 1.2.10, 1.2.9, 1.2.8, 1.2.7, 1.0.9)
metanorma-ogc (1.2.16, 1.2.15, 1.2.14, 1.2.12, 1.2.11, 1.2.10, 1.2.9, 1.2.8, 1.2.7, 1.0.8)
metanorma-plugin-datastruct (0.1.1)
metanorma-plugin-lutaml (0.3.0, 0.2.5, 0.2.4, 0.2.4.pre.alpha.4, 0.2.4.pre.alpha.3, 0.2.4.pre.alpha.2, 0.2.3)
metanorma-standoc (1.8.6, 1.8.4, 1.8.3, 1.8.2, 1.7.3, 1.7.2, 1.7.1, 1.6.5, 1.6.4, 1.6.3, 1.4.0)
metanorma-un (0.5.15, 0.5.14, 0.5.13, 0.5.12, 0.5.11, 0.5.10, 0.5.9, 0.5.8, 0.5.7, 0.3.10)
metanorma-utils (1.0.9, 1.0.7, 1.0.6, 1.0.5, 1.0.3, 1.0.1)

@CAMOBAP
Copy link
Contributor

CAMOBAP commented May 5, 2021

@ronaldtse @abunashir should gem cleanup help in this case? BTW what is gem cleanup --dryrun reports?

@abunashir
Copy link
Member

That would definitely help, and I would personally prefer that but @ronaldtse had some valid point about the user, trying to see if we can somehow fix this without a user having to cleanup their system.

@abunashir
Copy link
Member

@ronaldtse: I've created a PR that explicitly activates the flavours on load, I'm not super confident that it would fix the issue but that's the best I can think at the moment. On a positive site - it would fix the issue we've seen earlier related to private gem loading issue. Let me know if that helps :)

@CAMOBAP CAMOBAP removed their assignment Jul 24, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants