jruby-head shoes4 performance regression (on rake spec) #2544
Description
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