9.0.5.0 numerical computation regression

[jzakiya]

9.0.5.0 has seriously regressed from 9.0.4.0 on this numerical computation extensive rubygem
rubygem : primes-utils (2.7.0)

def tm; t = Time.now; yield; Time.now - t end
require 'primes/utils'

9.0.4.0
n = 40_10_*9; GC.start; tm{n.primescnt}
7.692

9.0.5.0
n = 40_10_*9; GC.start; tm{n.primescnt}
38.456

This behavior is consistent across different 32/64-bit OSs, as Host and VB guests.

[jzakiya]

Huh, the markup messed up the number.

n = 40 x 10^9

[jzakiya]

Another example.

Base System:
Lenovo laptop, 2.3GHz I5 cpu, 6GB ram
Versions installed via RVM

def tm; t=Time.now; yield; Time.now-t end

class Integer      # To test primality of an integer
  def primep5?     # Uses P5 Strictly Prime Generator
    n = self.abs
    return true if [2,3,5].include? n
    return false unless n > 1 and [1,7,11,13,17,19,23,29].include?(n%30)
    (7..Math.sqrt(n).to_i).step(30) do |p|
      return false if 
      n%(p)    == 0 or n%(p+4)  == 0 or n%(p+6)  == 0 or n%(p+10) == 0 or
      n%(p+12) == 0 or n%(p+16) == 0 or n%(p+22) == 0 or n%(p+24) == 0
    end
    true
  end
end

All times in seconds
On 32-bit Linux distro as Host OS.

jruby-9.0.4.0 :027 > n=20000000000000003; GC.start; tm{n.primep5?}
=> 2.47
jruby-9.0.4.0 :028 > n=200000000000000003; GC.start; tm{n.primep5?}
=> 7.803
jruby-9.0.4.0 :029 > n=1000000000000000003; GC.start; tm{n.primep5?}
=> 18.454
jruby-9.0.4.0 :030 > n=5000000000000000003; GC.start; tm{n.primep5?}
=> 45.479

jruby-9.0.5.0 :037 > n=20000000000000003; GC.start; tm{n.primep5?}
=> 9.539
jruby-9.0.5.0 :038 > n=200000000000000003; GC.start; tm{n.primep5?}
=> 29.504
jruby-9.0.5.0 :039 > n=1000000000000000003; GC.start; tm{n.primep5?}
=> 67.408
jruby-9.0.5.0 :040 > n=5000000000000000003; GC.start; tm{n.primep5?}
=> 158.045

On 64-bit Linux distro as VB Guest OS.

jruby-9.0.4.0 :036 > n=20000000000000003; GC.start; tm{n.primep5?}
=> 2.969
jruby-9.0.4.0 :037 > n=200000000000000003; GC.start; tm{n.primep5?}
=> 7.157
jruby-9.0.4.0 :038 > n=1000000000000000003; GC.start; tm{n.primep5?}
=> 15.325
jruby-9.0.4.0 :039 > n=5000000000000000003; GC.start; tm{n.primep5?}
=> 34.465

jruby-9.0.5.0 :040 > n=20000000000000003; GC.start; tm{n.primep5?}
=> 12.915
jruby-9.0.5.0 :041 > n=200000000000000003; GC.start; tm{n.primep5?}
=> 41.961
jruby-9.0.5.0 :042 > n=1000000000000000003; GC.start; tm{n.primep5?}
=> 89.645
jruby-9.0.5.0 :043 > n=5000000000000000003; GC.start; tm{n.primep5?}
=> 200.452

[headius]

Interesting. May still be JIT taking too long to kick in but I'll play with it.

[headius]

I think this is mostly a side effect of the new interpreter being slower and the JIT being no faster to kick in.

Here's my numbers with CRuby and then JRuby with different flags.

CRuby:

$ ruby23 blah.rb 
Using pure ruby versions for all methods
Available methods are: prime? primemr? primes primesmr primescnt primescntmr primenth|nthprime factors|prime_division primes_utils
8.940085
8.963216
8.977946

JRuby with no flags

$ jruby blah.rb 
Using pure ruby versions for all methods
Available methods are: prime? primemr? primes primesmr primescnt primescntmr primenth|nthprime factors|prime_division primes_utils
56.575
42.663
41.55

JRuby with more memory:

$ jruby -J-Xmx1G blah.rb 
Using pure ruby versions for all methods
Available methods are: prime? primemr? primes primesmr primescnt primescntmr primenth|nthprime factors|prime_division primes_utils
39.585
39.594

JRuby with more memory and immediate JIT:

$ jruby -Xjit.threshold=0 -J-Xmx2G blah.rb 
Using pure ruby versions for all methods
Available methods are: prime? primemr? primes primesmr primescnt primescntmr primenth|nthprime factors|prime_division primes_utils
7.727
6.679
6.711

So when the JIT gets going, we look fine. That's one issue.

This also uses a lot of memory. I went digging into primes-utils and gathered very quickly that this isn't unexpected; primes/utils.rb has logic to catch memory errors and report a range error. CRuby used about 1GB to run the benchmark, so JRuby was really struggling with our default cap of 500MB. I don't think the memory use looks comparatively bad once I bump the JVM heap size up, so no real issue here.

Largely this comes down to getting JIT to trigger sooner.

[jzakiya]

Why is so much memory used for this? Only 8 numbers are created each loop, so are old values being kept around until the routine ends? But even still, 9.0.4.0 performed so much better what else had to change to cause such a big difference? Are the architectures between the versions that much different? I'm just grasping at straws here.

[headius]

I believe I've found a regression. cc @enebo @subbuss

When I run this with JIT logging under 9.0.4.0, I can see some block bodies from the primes-util library getting jitted:

...
Using pure ruby versions for all methods
2016-03-07T17:36:17.329-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/rubies/jruby-9.0.4.0/lib/ruby/stdlib/rubygems.rb:1130
2016-03-07T17:36:17.336-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/rubies/jruby-9.0.4.0/lib/ruby/stdlib/rubygems/dependency.rb:272
2016-03-07T17:36:18.143-06:00: JITCompiler: done jitting:<anon class>.Module.suffixes at /Users/headius/.rvm/rubies/jruby-9.0.4.0/lib/ruby/stdlib/rubygems.rb:888
2016-03-07T17:36:18.150-06:00: JITCompiler: done jitting:<block> at uri:classloader:/jruby/java/core_ext/object.rb:39
Available methods are: prime? primemr? primes primesmr primescnt primescntmr primenth|nthprime factors|prime_division primes_utils
2016-03-07T17:36:18.153-06:00: JITCompiler: done jitting:<anon class>.Java::JavaLang::Character.java_identifier_part? at uri:classloader:/jruby/java/java_ext/java.lang.rb:217
2016-03-07T17:36:18.165-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/gems/jruby-9.0.4.0/gems/primes-utils-2.7.0/lib/primes/utils.rb:264
2016-03-07T17:36:20.768-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/gems/jruby-9.0.4.0/gems/primes-utils-2.7.0/lib/primes/utils.rb:347
2016-03-07T17:36:23.655-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/gems/jruby-9.0.4.0/gems/primes-utils-2.7.0/lib/primes/utils.rb:340
9.815
2016-03-07T17:36:28.054-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/gems/jruby-9.0.4.0/gems/primes-utils-2.7.0/lib/primes/utils.rb:378
2016-03-07T17:36:28.181-06:00: JITCompiler: done jitting:<block> at /Users/headius/.rvm/gems/jruby-9.0.4.0/gems/primes-utils-2.7.0/lib/primes/utils.rb:336
^C

Under 9.1 I do not see any blocks jitting. Something seems to have broken how we decide to JIT blocks.

[headius]

Success!

It appears that changes I made to ensure we only build blocks that were ready to be built actually caused NONE of them to build. I was checking to see if they had full call protocol before they had completed a full/JIT set of compiler passes...including the pass that sets up call protocol.

I have a fix coming. @enebo this is a good reason we need to start monitoring a set of CI benchmarks.

[enebo]

@headius yowch :)