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

Lazy classloading of invokers caused increased allocation for compiled defs #1404

Closed
headius opened this issue Jan 14, 2014 · 1 comment
Closed

Comments

@headius
Copy link
Member

headius commented Jan 14, 2014

In e50a20f, we made changes to our invoker loading to not eagerly try to lookup the class, instead waiting for it to fail to link. This helps boot time of AOT or eagerly-jitted systems by avoiding the expense of class lookups that will raise exceptions almost every time. However, the cost is substantially increased for repeated method definitions, since they now pay the cost of generating the stub and raising an exception when that stub fails to link.

The latter case is far less common, but could be impacting heavily meta-programmed environments. We should try to find a happy medium between these solutions.

system ~/projects/jruby-1.7 $ jruby -rbenchmark -e "def foo; def bar; end; end; 10.times { puts Benchmark.measure { 10_000.times { foo } } }"
  4.300000   0.120000   4.420000 (  2.572000)
  2.910000   0.070000   2.980000 (  1.493000)
  1.550000   0.020000   1.570000 (  1.313000)
  1.390000   0.010000   1.400000 (  1.303000)
  1.340000   0.000000   1.340000 (  1.259000)
  1.470000   0.010000   1.480000 (  1.293000)
  1.360000   0.000000   1.360000 (  1.275000)
  2.490000   0.020000   2.510000 (  1.478000)
  1.340000   0.000000   1.340000 (  1.266000)
  1.480000   0.010000   1.490000 (  1.298000)

system ~/projects/jruby-1.7 $ rvm jruby-1.7.8 do ruby -rbenchmark -e "def foo; def bar; end; end; 10.times { puts Benchmark.measure { 10_000.times { foo } } }"
  2.210000   0.050000   2.260000 (  1.276000)
  1.210000   0.020000   1.230000 (  0.607000)
  0.610000   0.030000   0.640000 (  0.578000)
  0.580000   0.010000   0.590000 (  0.531000)
  0.590000   0.020000   0.610000 (  0.540000)
  0.530000   0.000000   0.530000 (  0.530000)
  0.520000   0.000000   0.520000 (  0.521000)
  0.510000   0.000000   0.510000 (  0.508000)
  0.520000   0.000000   0.520000 (  0.528000)
  0.500000   0.000000   0.500000 (  0.510000)

system ~/projects/jruby-1.7 $ jruby -J-XX:+PrintGCDetails -rbenchmark -e "def foo; def bar; end; end; 10.times { puts Benchmark.measure { 10_000.times { foo } } }"
[GC [PSYoungGen: 66048K->7723K(76800K)] 66048K->7825K(251392K), 0.0134310 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 73771K->7685K(76800K)] 73873K->7794K(251392K), 0.0120080 secs] [Times: user=0.07 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 73733K->7813K(76800K)] 73842K->7930K(251392K), 0.0110030 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 73861K->7893K(142848K)] 73978K->8018K(317440K), 0.0129710 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 139989K->8165K(142848K)] 140114K->8298K(317440K), 0.0142330 secs] [Times: user=0.09 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 140261K->8165K(157184K)] 140394K->8482K(331776K), 0.0155590 secs] [Times: user=0.10 sys=0.01, real=0.02 secs] 
  4.290000   0.140000   4.430000 (  2.526000)
[GC [PSYoungGen: 157157K->1120K(157696K)] 157474K->8963K(332288K), 0.0168300 secs] [Times: user=0.11 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 150112K->1184K(159744K)] 157955K->9315K(334336K), 0.0072140 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 150688K->1120K(151040K)] 158819K->9659K(325632K), 0.0070640 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
  2.270000   0.040000   2.310000 (  1.420000)
[GC [PSYoungGen: 150624K->736K(158720K)] 159163K->9947K(333312K), 0.0072570 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 148192K->480K(159232K)] 157403K->10347K(333824K), 0.0056830 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 118535K->416K(159232K)] 128402K->10603K(333824K), 0.0046830 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC [PSYoungGen: 416K->0K(159232K)] [ParOldGen: 10187K->7665K(92160K)] 10603K->7665K(251392K) [PSPermGen: 83967K->23316K(83968K)], 0.0387140 secs] [Times: user=0.15 sys=0.01, real=0.04 secs] 
[GC [PSYoungGen: 147456K->384K(159232K)] 155121K->8049K(251392K), 0.0035320 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  1.560000   0.030000   1.590000 (  1.357000)
[GC [PSYoungGen: 147840K->416K(159232K)] 155505K->8417K(251392K), 0.0051090 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 147872K->448K(147968K)] 155873K->8793K(240128K), 0.0051110 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 147904K->448K(158720K)] 156249K->9129K(250880K), 0.0046570 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 147904K->480K(158720K)] 156585K->9497K(250880K), 0.0046630 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  1.390000   0.000000   1.390000 (  1.292000)
[GC [PSYoungGen: 147936K->480K(159232K)] 156953K->9841K(251392K), 0.0052390 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 149472K->384K(159232K)] 158833K->10073K(251392K), 0.0046000 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 149376K->480K(160256K)] 159065K->10497K(252416K), 0.0047470 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
  1.340000   0.010000   1.350000 (  1.271000)
[GC [PSYoungGen: 151008K->448K(160256K)] 161025K->10801K(252416K), 0.0054790 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 15507K->256K(160768K)] 25861K->10961K(252928K), 0.0030840 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 256K->0K(160768K)] [ParOldGen: 10705K->7695K(109056K)] 10961K->7695K(269824K) [PSPermGen: 83967K->23315K(83968K)], 0.0376700 secs] [Times: user=0.14 sys=0.00, real=0.04 secs] 
[GC [PSYoungGen: 152064K->384K(160768K)] 159759K->8079K(269824K), 0.0042100 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 152448K->480K(161792K)] 160143K->8511K(270848K), 0.0052860 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 154592K->512K(161792K)] 162623K->8879K(270848K), 0.0046920 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] 
  1.530000   0.010000   1.540000 (  1.331000)
[GC [PSYoungGen: 154624K->480K(162816K)] 162991K->9191K(271872K), 0.0047520 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 156128K->448K(162816K)] 164839K->9511K(271872K), 0.0050670 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 156096K->448K(163328K)] 165159K->9855K(272384K), 0.0054880 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  1.350000   0.000000   1.350000 (  1.277000)
[GC [PSYoungGen: 157632K->512K(163328K)] 167039K->10263K(272384K), 0.0050760 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 157696K->480K(164352K)] 167447K->10583K(273408K), 0.0053790 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 111639K->352K(164352K)] 121743K->10815K(273408K), 0.0041860 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 352K->0K(164352K)] [ParOldGen: 10463K->7397K(145408K)] 10815K->7397K(309760K) [PSPermGen: 83967K->23181K(83968K)], 0.1995050 secs] [Times: user=1.12 sys=0.00, real=0.20 secs] 
[GC [PSYoungGen: 158720K->480K(164864K)] 166117K->7877K(310272K), 0.0044320 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  2.540000   0.010000   2.550000 (  1.497000)
[GC [PSYoungGen: 160224K->800K(164864K)] 167621K->8197K(310272K), 0.0056610 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 160544K->1120K(165376K)] 167941K->8517K(310784K), 0.0065490 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 162400K->1504K(165376K)] 169797K->8901K(310784K), 0.0080850 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
  1.370000   0.010000   1.380000 (  1.275000)
[GC [PSYoungGen: 162784K->1824K(166912K)] 170181K->9221K(312320K), 0.0084150 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 164640K->2208K(166912K)] 172037K->9605K(312320K), 0.0095160 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 165024K->2496K(165888K)] 172421K->9893K(311296K), 0.0111410 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 
  1.440000   0.010000   1.450000 (  1.265000)
Heap
 PSYoungGen      total 165888K, used 146567K [0x00000007f5900000, 0x0000000800000000, 0x0000000800000000)
  eden space 161792K, 89% used [0x00000007f5900000,0x00000007fe5b1c78,0x00000007ff700000)
  from space 4096K, 60% used [0x00000007ffc00000,0x00000007ffe70000,0x0000000800000000)
  to   space 4608K, 0% used [0x00000007ff700000,0x00000007ff700000,0x00000007ffb80000)
 ParOldGen       total 145408K, used 7397K [0x00000007e0c00000, 0x00000007e9a00000, 0x00000007f5900000)
  object space 145408K, 5% used [0x00000007e0c00000,0x00000007e13394b8,0x00000007e9a00000)
 PSPermGen       total 83968K, used 80193K [0x00000007dba00000, 0x00000007e0c00000, 0x00000007e0c00000)
  object space 83968K, 95% used [0x00000007dba00000,0x00000007e08504f0,0x00000007e0c00000)

system ~/projects/jruby-1.7 $ rvm jruby-1.7.8 do ruby -J-XX:+PrintGCDetails -rbenchmark -e "def foo; def bar; end; end; 10.times { puts Benchmark.measure { 10_000.times { foo } } }"
[GC [PSYoungGen: 66048K->7947K(76800K)] 66048K->8048K(251392K), 0.0140300 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 73995K->7717K(76800K)] 74096K->7826K(251392K), 0.0111860 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 73765K->7685K(76800K)] 73874K->7802K(251392K), 0.0089260 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
  2.170000   0.060000   2.230000 (  1.255000)
[GC [PSYoungGen: 73733K->7717K(142848K)] 73850K->7842K(317440K), 0.0113210 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
  1.120000   0.030000   1.150000 (  0.618000)
[GC [PSYoungGen: 139813K->7749K(142848K)] 139938K->7882K(317440K), 0.0106820 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
[GC [PSYoungGen: 139845K->7749K(157696K)] 139978K->7890K(332288K), 0.0104060 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
  0.670000   0.030000   0.700000 (  0.584000)
[GC [PSYoungGen: 157253K->256K(157696K)] 157394K->7990K(332288K), 0.0117070 secs] [Times: user=0.07 sys=0.01, real=0.01 secs] 
  0.590000   0.010000   0.600000 (  0.532000)
[GC [PSYoungGen: 149760K->256K(159232K)] 157494K->8054K(333824K), 0.0018860 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  0.560000   0.000000   0.560000 (  0.555000)
[GC [PSYoungGen: 149760K->224K(150016K)] 157558K->8022K(324608K), 0.0013420 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  0.530000   0.000000   0.530000 (  0.534000)
[GC [PSYoungGen: 149728K->224K(158720K)] 157526K->8030K(333312K), 0.0022020 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
  0.520000   0.000000   0.520000 (  0.510000)
[GC [PSYoungGen: 147680K->224K(159232K)] 155486K->8038K(333824K), 0.0023010 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
  0.540000   0.010000   0.550000 (  0.541000)
[GC [PSYoungGen: 147680K->224K(150016K)] 155494K->8046K(324608K), 0.0019030 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [PSYoungGen: 143072K->224K(138752K)] 150894K->8086K(313344K), 0.0014620 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  0.550000   0.000000   0.550000 (  0.544000)
[GC [PSYoungGen: 138464K->224K(139776K)] 146326K->8086K(314368K), 0.0013710 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  0.510000   0.000000   0.510000 (  0.514000)
Heap
 PSYoungGen      total 139776K, used 57746K [0x00000007f5900000, 0x00000007ff180000, 0x0000000800000000)
  eden space 133632K, 43% used [0x00000007f5900000,0x00000007f912cb18,0x00000007fdb80000)
  from space 6144K, 3% used [0x00000007feb80000,0x00000007febb8000,0x00000007ff180000)
  to   space 11264K, 0% used [0x00000007fdb80000,0x00000007fdb80000,0x00000007fe680000)
 ParOldGen       total 174592K, used 7862K [0x00000007e0c00000, 0x00000007eb680000, 0x00000007f5900000)
  object space 174592K, 4% used [0x00000007e0c00000,0x00000007e13adbf8,0x00000007eb680000)
 PSPermGen       total 23552K, used 23391K [0x00000007dba00000, 0x00000007dd100000, 0x00000007e0c00000)
  object space 23552K, 99% used [0x00000007dba00000,0x00000007dd0d7f10,0x00000007dd100000)
@headius headius modified the milestones: JRuby 9000, JRuby 1.7.11 Feb 21, 2014
@enebo enebo modified the milestone: JRuby 9.0.0.0 Jul 14, 2015
@enebo enebo added this to the Won't Fix milestone Feb 17, 2017
@enebo
Copy link
Member

enebo commented Feb 17, 2017

JRuby 9.x is as fast as your original numbers and 1.7.x is as slow as reported but since we are EOL'ing 1.7.x we will just resolve this.

@enebo enebo closed this as completed Feb 17, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants