jruby-head shoes4 performance regression (on rake spec) #2544

PragTob · 2015-02-01T12:34:17Z

Hello everyone :)

First off, sorry for the relatively coarse grained report. I noticed that with jruby-head/pre1 the performance of shoes4 degraded - at least as mainly shown in running our specs (mainly), so it might as well be related to rspec. Also some very basic benchmarks, see below.

Our rake spec runs 3 different test suites. The first one is the shoes-core specs with our mock backend (does nothing), the second one is running our specs with the SWT backend (+ SWT specific specs) and the third one is specs for our packaging. Noteworthy, we do a lot of Java interoperability calls.

It is mostly our logic/swt specs that got slower. So for swt it is (as in the example below) 48 seconds on 1.7.19 versus 75 seconds on current jruby-head (built ~2 hours ago). Overall run time is 2minutes 23 seconds versus 3 minutes 33 seconds.

Here is a shortened log of our tests running and the associated time:

tobi@airship ~/github/shoes4 $ java -version
java version "1.7.0_75"
OpenJDK Runtime Environment (IcedTea 2.5.4) (7u75-2.5.4-1~trusty1)
OpenJDK 64-Bit Server VM (build 24.75-b04, mixed mode)
tobi@airship ~/github/shoes4 $ ruby -v
jruby 1.7.19 (1.9.3p551) 2015-01-29 20786bd on OpenJDK 64-Bit Server VM 1.7.0_75-b13 +jit [linux-amd64]
tobi@airship ~/github/shoes4 $ uname -a
Linux airship 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:28:38 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
tobi@airship ~/github/shoes4 $ time rake spec
jruby --debug --1.9 -Ispec  -S rspec --tty -rshoes-core/spec/spec_helper  shoes-core/spec/shoes/point_spec.rb shoes-core/spec/shoes/keyrelease_spec.rb shoes-core/spec/shoes/constants_spec.rb 

# shoes-core with the mock backend

Finished in 2.73 seconds (files took 3.58 seconds to load)
1541 examples, 0 failures

jruby --debug --1.9 -Ispec  -S rspec --tty -rshoes-swt/spec/spec_helper --tag ~no_swt  shoes-swt/spec/shoes/cli_spec.rb shoes-swt/spec/shoes/swt/radio_group_spec.rb shoes-swt/spec/shoes

# JRuby SWT specs and stuff

Finished in 47.6 seconds (files took 5.19 seconds to load)
2068 examples, 0 failures

jruby --debug --1.9 -Ispec  -S rspec --tty   shoes-package/spec/swt_jar_spec.rb shoes-package/spec/swt_app_spec.rb shoes-package/spec/configuration_spec.rb

# yadda yadda packaging specs

Finished in 16.74 seconds (files took 0.785 seconds to load)
79 examples, 0 failures

real    1m36.015s
user    2m23.638s
sys 0m2.648s

--------------------------------------------------------------------------------------------------------

tobi@airship ~/github/shoes4 $ rvm use jruby-head@shoes
Using /home/tobi/.rvm/gems/jruby-head with gemset shoes
tobi@airship ~/github/shoes4 $ ruby -v
jruby 9.0.0.0-SNAPSHOT (2.2.0p0) 2015-02-01 1310672 OpenJDK 64-Bit Server VM 24.75-b04 on 1.7.0_75-b13 +jit [linux-amd64]
tobi@airship ~/github/shoes4 $ time rake spec
jruby --debug --1.9 -Ispec  -S rspec --tty -rshoes-core/spec/spec_helper  shoes-core/spec/shoes/point_spec.rb shoes-core/spec/shoes/keyrelease_spec.rb shoes-core/spec/shoes/constants_spec.rb 

# shoes-core specs with the mock abckend

Finished in 3.6 seconds (files took 4.05 seconds to load)
1541 examples, 0 failures

jruby --debug --1.9 -Ispec  -S rspec --tty -rshoes-swt/spec/spec_helper --tag ~no_swt  shoes-swt/spec

# SWT integration specs

Finished in 1 minute 15.56 seconds (files took 5.36 seconds to load)
2068 examples, 0 failures

jruby --debug --1.9 -Ispec  -S rspec --tty   shoes-package/spec/swt_jar_spec.rb shoes-package/spec/swt_app_spec.rb shoes-package/spec/configuration_spec.rb
# packaging tests
Finished in 17.69 seconds (files took 0.953 seconds to load)
79 examples, 0 failures

real    2m15.551s
user    3m33.468s
sys 0m2.902s

full jruby-head test log - warning, lots of gtk warnings in there. Also some jruby deprecation warnings, which I'll work on fixing (already got a shoes ticket)

Also noteworthy, although that travis ci test execution times vary our jruby-head specs are almost reliably 1.5-2.0x slower on travis (as compared to current JRuby) - a travis build

We also have some really basic benchmarks that are a bit slower:

1.7.19:

tobi@airship ~/github/shoes4 $ bin/shoes benchmark/clear.rb 
       user     system      total        real
1. fill app  3.210000   0.070000   3.280000 (  1.455000)
1. clear app  0.120000   0.000000   0.120000 (  0.045000)
2. fill app  1.620000   0.030000   1.650000 (  0.943000)
2. clear app  0.120000   0.000000   0.120000 (  0.039000)
3. fill app  2.310000   0.030000   2.340000 (  0.953000)
3. clear app  0.100000   0.000000   0.100000 (  0.031000)

9k:

tobi@airship ~/github/shoes4 $ bin/shoes benchmark/clear.rb 
warning: --1.9 ignored
       user     system      total        real
1. fill app  3.550000   0.020000   3.570000 (  1.726247)
1. clear app  0.080000   0.000000   0.080000 (  0.046536)
2. fill app  1.850000   0.040000   1.890000 (  1.161765)
2. clear app  0.080000   0.000000   0.080000 (  0.038373)
3. fill app  1.350000   0.000000   1.350000 (  1.054767)
3. clear app  0.110000   0.000000   0.110000 (  0.036593)

As always thank you for all your work! :) I hope to get around to write some more fine grained/not really gui benchmarks that could narrow down and show case the problem better. But no promises, busy times ahead :)

Thanks!
Tobi

The text was updated successfully, but these errors were encountered:

subbuss · 2015-02-22T18:00:36Z

Can you report back with latest master?

PragTob · 2015-03-01T22:01:29Z

Updated to latest master. Unfortunately the problems haven't gotten better, the last benchmark has even gotten notably worse from my last 9k snapshot (3.6 seconds --> 6,3 seconds for fill app among others):

jruby 1.7.19:

# swt specs
Finished in 46.92 seconds (files took 5.08 seconds to load)
2066 examples, 0 failures

Randomized with seed 30479

Coverage report generated for RSpec to /home/tobi/github/shoes4/coverage. 27 / 39 LOC (69.23%) covered.
jruby --debug --1.9 -Ispec  -S rspec --tty   shoes-package/spec/swt_jar_spec.rb shoes-package/spec/swt_app_spec.rb shoes-package/spec/configuration_spec.rb
.rm -f pkg/tmp/sweet-nebulae.jar
Creating pkg/tmp/sweet-nebulae.jar
...................rm -f pkg/sweet-nebulae.jar
Creating pkg/sweet-nebulae.jar
...........................................................

Finished in 17.53 seconds (files took 0.8 seconds to load)
79 examples, 0 failures

Randomized with seed 36977


real    1m35.042s
user    2m20.284s
sys 0m3.147s

tobi@airship ~/github/shoes4 $ bin/shoes benchmark/clear.rb 
       user     system      total        real
1. fill app  3.460000   0.060000   3.520000 (  1.574000)
1. clear app  0.130000   0.000000   0.130000 (  0.048000)
2. fill app  1.730000   0.000000   1.730000 (  0.972000)
2. clear app  0.130000   0.000000   0.130000 (  0.043000)
3. fill app  1.990000   0.010000   2.000000 (  0.957000)
3. clear app  0.100000   0.000000   0.100000 (  0.035000)

jruby-head:

# swt specs
inished in 1 minute 10.29 seconds (files took 5.24 seconds to load)
2066 examples, 0 failures

Randomized with seed 31590

Coverage report generated for RSpec to /home/tobi/github/shoes4/coverage. 27 / 39 LOC (69.23%) covered.
jruby --debug --1.9 -Ispec  -S rspec --tty   shoes-package/spec/swt_jar_spec.rb shoes-package/spec/swt_app_spec.rb shoes-package/spec/configuration_spec.rb
warning: --1.9 ignored
....................................................rm -f pkg/sweet-nebulae.jar
Creating pkg/sweet-nebulae.jar
........rm -f pkg/tmp/sweet-nebulae.jar
Creating pkg/tmp/sweet-nebulae.jar
...................

Finished in 19.04 seconds (files took 0.965 seconds to load)
79 examples, 0 failures

Randomized with seed 46217


real    2m9.108s
user    3m20.009s
sys 0m3.639s

tobi@airship ~/github/shoes4 $ bin/shoes benchmark/clear.rb 
warning: --1.9 ignored
       user     system      total        real
1. fill app  6.210000   0.080000   6.290000 (  2.354991)
1. clear app  0.120000   0.000000   0.120000 (  0.057360)
2. fill app  2.540000   0.030000   2.570000 (  1.318482)
2. clear app  0.090000   0.000000   0.090000 (  0.045943)
3. fill app  1.310000   0.010000   1.320000 (  1.116442)
3. clear app  0.120000   0.000000   0.120000 (  0.038170)

headius · 2015-03-04T18:28:38Z

Does the test run spin up any subprocesses? Startup time has increased a bit from 1.7 (we're working on it) and that could add up.

The normal benchmark numbers are mostly in line with what I'd expect for current performance, but a reproducible benchmark would help us improve.

I'd also be curious about interpreted execution versus JIT versus JIT with invokedynamic on current master. 9k.pre1 is not a good target for benchmarking (at least with JIT enabled), so we'll stick to current master.

PragTob · 2015-03-04T20:28:14Z

The test run does spin up separate processes, one for every "test suite" - 3 in total (those are the processes I'm aware of). However, the swt specs (one process) are up to 1 minute 10 seconds versus 46 seconds in 1.7.

Hm ok, I was a bit alerted as for some cases performance seems to be halved... I could see if I can write a smaller script reproducing the problems but not soon/and no promises (moving this weekend)

Same goes for interpreted vs. JIT vs. JIT with invoke dynamic - have to check out the appropriate switches :)

Thanks for the feedback Charlie!

enebo · 2015-03-04T21:44:24Z

@headius there is some mystery here. His second numbers are with our new faster to get going startup interpreter. So frequent restarts should be much faster than pre1. It sounds like this may not be the case though. This new interpreter is not as fast as old one but it spends a lot less time getting to actual interpretation so I would expect reasonable testing perf.

@PragTob I wonder if we broke something in our recent changes since we did nothing which should have affected JIT performance. Your benchmarks slowing down should not have happened.

headius · 2015-05-09T01:01:34Z

It would be good to hear if 9k.pre2 has helped :-)

PragTob · 2015-05-20T19:01:15Z

Sorry I was sick and just catching up on github notifications :)

Sadly results don't seem to have changed much. Time for rake spec in 1.7.19:

real    2m53.465s
user    3m55.957s
sys 0m7.037s

Time on jruby-head from just know:

real    3m0.269s
user    4m39.884s
sys 0m5.513s

The clear benchmark is also still faster (especially on the first fill):

1.7.19:

       user     system      total        real
1. fill app  6.170000   0.170000   6.340000 (  3.718000)
1. clear app  0.150000   0.010000   0.160000 (  0.102000)
2. fill app  4.680000   0.040000   4.720000 (  2.758000)
2. clear app  0.080000   0.000000   0.080000 (  0.067000)
3. fill app  3.770000   0.040000   3.810000 (  2.523000)
3. clear app  0.100000   0.000000   0.100000 (  0.062000)

head from today:

       user     system      total        real
1. fill app 15.820000   0.200000  16.020000 (  6.566986)
1. clear app  0.170000   0.000000   0.170000 (  0.131994)
2. fill app  5.510000   0.030000   5.540000 (  3.383701)
2. clear app  0.100000   0.000000   0.100000 (  0.079070)
3. fill app  3.580000   0.020000   3.600000 (  2.807078)
3. clear app  0.080000   0.000000   0.080000 (  0.074688)

PragTob · 2017-01-08T21:20:45Z

for reference I checked out this commit as it was around the time I opened the issue, so that shoes still works with 1.7: 7c90d16097b87ae61

This is also running JDK 8 now. The difference seems smaller but 1.7 is still faster for the clear benchmark (I gave up getting the tests running again, pulls in new gems that don't play with 1.7 etc.)

1.7:

tobi@speedy ~/github/shoes4 $ bin/shoes benchmark/clear.rb 
       user     system      total        real
1. fill app  4.810000   0.080000   4.890000 (  1.268000)
1. clear app  0.110000   0.000000   0.110000 (  0.032000)
2. fill app  2.080000   0.010000   2.090000 (  0.708000)
2. clear app  0.100000   0.000000   0.100000 (  0.023000)
3. fill app  2.210000   0.020000   2.230000 (  0.651000)
3. clear app  0.050000   0.000000   0.050000 (  0.013000)

9.1.6.0:

tobi@speedy ~/github/shoes4 $ bundle exec bin/shoes benchmark/clear.rb 
       user     system      total        real
1. fill app  6.390000   0.090000   6.480000 (  1.518366)
1. clear app  0.140000   0.000000   0.140000 (  0.040486)
2. fill app  2.540000   0.010000   2.550000 (  0.844540)
2. clear app  0.080000   0.000000   0.080000 (  0.019868)
3. fill app  2.500000   0.010000   2.510000 (  0.795990)
3. clear app  0.100000   0.010000   0.110000 (  0.022016)

Still closing out, as probably to hard to reproduce/work out.

subbuss added JRuby 9000 performance labels Feb 15, 2015

PragTob mentioned this issue Mar 25, 2015

JRuby 9k: simple script ~80% as fast as jruby 1.7.19 #2761

Closed

PragTob closed this as completed Jan 8, 2017

enebo added this to the Invalid or Duplicate milestone Jan 10, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

jruby-head shoes4 performance regression (on rake spec) #2544

jruby-head shoes4 performance regression (on rake spec) #2544

PragTob commented Feb 1, 2015

subbuss commented Feb 22, 2015

PragTob commented Mar 1, 2015

headius commented Mar 4, 2015

PragTob commented Mar 4, 2015

enebo commented Mar 4, 2015

headius commented May 9, 2015

PragTob commented May 20, 2015

PragTob commented Jan 8, 2017

jruby-head shoes4 performance regression (on rake spec) #2544

jruby-head shoes4 performance regression (on rake spec) #2544

Comments

PragTob commented Feb 1, 2015

subbuss commented Feb 22, 2015

PragTob commented Mar 1, 2015

headius commented Mar 4, 2015

PragTob commented Mar 4, 2015

enebo commented Mar 4, 2015

headius commented May 9, 2015

PragTob commented May 20, 2015

PragTob commented Jan 8, 2017