[performance] Virtus initialisation takes very long time.

[nglx]

Virtus seems to be pretty lightweight library but its initialisation time is one of the slowest of all the gems I have in my different apps:

Benchmark taken from bundler require: virtus 0.630000 0.220000 0.850000 ( 0.844830)

I suspect that it might be because of it's modular implementation and lots of requires in lib/virtus.rb. Is there any way to improve it?

[mbj]

Does this count virtus itsself or virtus-and-its dependencies?

[nglx]

Virtus itself. It could be calculated using script similar to https://gist.github.com/panthomakos/2588879

[mbj]

Can you try this one, very ad-hoc but effective?

class Kernel
  alias_method :_virtus_debug_original_requre, :require

  def require(name)
    start = Time.now
    _virtus_debug_original_require(name)
    puts "#{name} took #{Time.now - start}"
  end
end

Lets see what file in virtus takes so long!

[nglx]

Got the concept of it, but does it really working with ruby 2.0? Getting 'Kernel is not a class (TypeError)'... changing to module doesn't help much...

[mbj]

@managr Kernel is a module ;) Sorry module Kernel.

[mbj]

@managr mhh, works pretty well for me:

irb(main):001:0> module Kernel
irb(main):002:1>   alias_method :_old_require, :require
irb(main):003:1>   def require(name)
irb(main):004:2>     puts "hello"
irb(main):005:2>     _old_require(name)
irb(main):006:2>   end
irb(main):007:1> end
=> nil
irb(main):008:0> require 'set'
hello
=> true
irb(main):009:0> RUBY_VERSION
=> "2.0.0"
irb(main):010:0> RUBY_ENGINE
=> "ruby"

[mbj]

@managr Just remove all my typos in my first code post. Not ready for copy & paste. I do not run all the stuf I post in comments. Shame on me. Hint: requre vs require, first arg of alias_method.

[nglx]

oh was a typo in the alias name... got it. runnning... and....

[mbj]

Ready for copy and paste, does not modify return value and only prints if file is required the first time. Remember this does count cumulative require time if a file requires others.

module Kernel
  alias_method :_old_virtus_require, :require
  def require(name)
    start = Time.now
   _old_virtus_require(name).tap do |required|
      puts "#{name} took #{Time.now - start }" if required
    end
  end
end

[nglx]

Doesn't look that bad:

virtus               ostruct took 7.0e-06
virtus/support/equalizer took 0.000566
virtus/support/options took 0.000485
virtus/support/type_lookup took 0.000458
virtus/model took 0.000419
virtus/extensions took 0.000559
virtus/const_missing_extensions took 0.000255
virtus/class_inclusions took 0.000328
virtus/module_extensions took 0.000415
virtus/configuration took 0.00041
virtus/builder took 0.000572
virtus/builder/hook_context took 0.000368
virtus/class_methods took 0.000372
virtus/instance_methods took 0.000472
virtus/value_object took 0.000437
virtus/coercer took 0.000276
virtus/attribute_set took 0.000748
virtus/attribute/default_value took 0.000325
virtus/attribute/default_value/from_clonable took 0.000323
virtus/attribute/default_value/from_callable took 0.000289
virtus/attribute/default_value/from_symbol took 0.000294
virtus/attribute took 0.002213
virtus/attribute/builder took 0.000912
virtus/attribute/coercer took 0.000341
virtus/attribute/accessor took 0.000511
virtus/attribute/coercible took 0.000262
virtus/attribute/strict took 0.000264
virtus/attribute/lazy_default took 0.000343
virtus/attribute/boolean took 0.000446
virtus/attribute/collection took 0.000747
virtus/attribute/hash took 0.000726
virtus/attribute/embedded_value took 0.00053

[mbj]

Could also be the bundler overhead try: bundle exec ruby -e 'start = Time.now; require virtus; p Time.now - start' I'm up 18h and cannot come up with better debug vectors (there are better ones!).

[mbj]

• fix syntax pls ;)

[nglx]

Here you are:

bundle exec ruby -e 'start = Time.now; require "virtus"; p Time.now - start'
0.519969

ps. 18h up, it's not an urgent issue... :)

[dkubb]

@managr try factoring out the axiom-types initialization by requiring it before virtus, and see if maybe that is the cause of the slowdown.

[nglx]

@dkubb tried that. doesn't seem to help much:

virtus                 0.640000   0.200000   0.840000 (  0.833434)

but a little bit

bundle exec ruby -e 'require "axiom-types"; start = Time.now; require "virtus"; p Time.now - start'
0.449708

[mbj]

@managr Can you set up a public repo that replicates your problem? I'll happily clone and debug!

[nglx]

I'm just using this benchmark code https://gist.github.com/managr/7875683

and run it right now on the virtus from: https://github.com/managr/virtus

will be glad to help. Still if you find out that 0.6-0.8 sec is the usual initialisation time for virtus I can probably live with that...

[mbj]

@managr So you are using rails? (Your gist shows) Can you just try to load virtus outside of rails infected environment?

[nglx]

Using rails, but it's pretty much the same without it

ruby -e 'start = Time.now; require "virtus"; p Time.now - start'
0.438029

[mbj]

@managr I have 0.22 for virtus. Maybe your machine is just slow? Mutant is 0.5. Unparser 0.28. Adamantium 0.09.

[nglx]

Thanks @mbj. I don't have any decent machine :). That's true, but having almost 100 gems lightweight virtus is the slowest one - that's just odd.

       user     system      total        real
after_commit_queue     0.000000   0.000000   0.000000 (  0.001996)
ancestry               0.000000   0.000000   0.000000 (  0.004733)
axlsx_rails            0.000000   0.000000   0.000000 (  0.006194)
binding_of_caller      0.000000   0.000000   0.000000 (  0.000013)
bootstrap-sass         0.000000   0.000000   0.000000 (  0.004407)
cityhash               0.000000   0.000000   0.000000 (  0.000018)
font-awesome-rails     0.000000   0.000000   0.000000 (  0.003040)

(removing around 80 for convinience)

prawn                  0.240000   0.050000   0.290000 (  0.291219)
sass-rails             0.270000   0.060000   0.330000 (  0.323602)
cancan                 0.310000   0.110000   0.420000 (  0.408611)
axlsx                  0.340000   0.110000   0.450000 (  0.452658)
fog                    0.630000   0.170000   0.800000 (  0.813161)
virtus                 0.610000   0.190000   0.800000 (  0.806407)

[nglx]

But anyway go ahead and close that issue. It's probably the way it should be and it won't prevent me from using virtus :+1: .

[mbj]

@managr How long does rails (and nothing else) take on your machine?

[nglx]

Good question.

ruby -e 'start = Time.now; require "rails"; p Time.now - start'
0.696688

comparing to virtus

ruby -e 'start = Time.now; require "virtus"; p Time.now - start'
0.438029

[mbj]

@managr I suspect only a subset of rails was loaded, because of autoloads? (I'm not a rails person). But compared to this number virtus looks a littlebit slow. I think @solnic can judge best of virtus initialization time can/should be improved.

[solnic]

hey @managr - virtus.rb requires 36 things. not really my fault that it takes almost half a second on your machine, it's not like we do anything weird here, just simple require statements, that's all. I tried some other gems that I know that require a bunch of stuff and it's as slow as with virtus.

I guess I would accept a patch that adds autoload if that could help anyone.

closing for now.

[nglx]

that seems to be reasonable explanations. thanks guys for taking your time.