OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

HarlemSquirrel · 2017-11-17T19:28:21Z

OpenSSL::Cipher#random_iv is about 12x slower for me on Ubuntu 16.04 with OpenJDK 1.8.0_151.

➤  java -version
openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-0ubuntu0.16.04.2-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

I have java set to use /dev/urandom instead of /dev/random.

➤  cat /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/security/java.security | grep securerandom.source=
securerandom.source=file:/dev/urandom
➤  cat /usr/lib/jvm/java-8-openjdk-i386/jre/lib/security/java.security | grep securerandom.source= 
securerandom.source=file:/dev/urandom

JRuby 9.1.13.0

➤  JRUBY_OPTS='--profile' ruby -e "puts RUBY_VERSION, RUBY_ENGINE, RUBY_ENGINE_VERSION; require 'openssl'; OpenSSL::Cipher.new('AES-128-CBC').random_iv"
Profiling enabled; ^C shutdown will now dump profile info
2.3.3
jruby
9.1.13.0

main profile results:
Total time: 2.22

     total        self    children       calls  method
----------------------------------------------------------------
      1.87        0.04        1.83         221  Kernel.require
      1.42        0.00        1.41          91  Kernel.require
      0.86        0.11        0.75          35  Kernel.load
      0.78        0.77        0.01           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.38        0.00        0.38           2  Object#require_jar
      0.38        0.00        0.38           2  Jars.require_jar
      0.37        0.00        0.37           2  Jars.require_jar_with_block
      0.37        0.00        0.37           2  Jars.do_require
      0.37        0.00        0.37           2  Jars.home
      0.37        0.00        0.37           2  Jars.local_maven_repo
      0.36        0.00        0.36           1  Jars.maven_local_settings
      0.30        0.04        0.26          99  Array#each
      0.24        0.00        0.24           1  Gem::Specification.load_defaults
      0.24        0.00        0.24           1  Gem::Specification.each_spec
      0.24        0.00        0.24           1  Gem::Specification.each_gemspec
      0.21        0.05        0.16         285  Class#new
      0.16        0.00        0.16          16  Gem::Specification.load
      0.14        0.03        0.11          16  Kernel.eval
      0.13        0.00        0.13          28  Kernel.gem
      0.12        0.00        0.12           3  Gem::Dependency#to_spec
      0.11        0.00        0.11           3  Gem::Dependency#to_specs
      0.11        0.00        0.11           3  Gem::Dependency#matching_specs
      0.10        0.00        0.10          27  Kernel.send
      0.09        0.01        0.07          15  Gem::Specification#initialize
      0.08        0.00        0.08          12  Gem.register_default_spec
      0.07        0.00        0.07           3  Gem::Specification.stubs_for
      0.06        0.06        0.00          24  Java::JavaPackage#method_missing
      0.05        0.02        0.03          83  Array#map
      0.04        0.04        0.00        1424  String#sub
      0.03        0.02        0.01           2  Fixnum#times
      0.03        0.00        0.03           3  Gem::Specification.dirs
      0.03        0.01        0.02          44  Gem::Specification#add_dependency_with_type
      0.03        0.03        0.00         120  String#=~
      0.03        0.00        0.03          41  Gem::Specification#add_development_dependency
      0.03        0.00        0.03           9  Gem::Specification.gemspec_stubs_in
      0.03        0.00        0.02          86  Gem::Version.new
      0.02        0.00        0.02          99  Gem::Requirement#initialize
      0.02        0.00        0.02          25  Gem::Version#<=>
      0.02        0.00        0.02           4  Enumerable.find
      0.02        0.01        0.01          78  Array#map!
      0.02        0.00        0.02           1  Gem.win_platform?
      0.02        0.02        0.00           1  Time.now
      0.02        0.00        0.02          94  Gem::Requirement.create
      0.02        0.00        0.02           1  URI::RFC2396_Parser#initialize
      0.02        0.00        0.02          27  Gem.remove_unresolved_default_spec
      0.02        0.02        0.00          15  IO.read
      0.02        0.00        0.02          72  Gem::Dependency#initialize
      0.02        0.01        0.00           4  Hash#each
      0.02        0.00        0.02          50  Gem::Version#canonical_segments
      0.02        0.00        0.02           4  Gem::StubSpecification#to_spec

JRuby 9.1.14.0

➤  JRUBY_OPTS='--profile' ruby -e "puts RUBY_VERSION, RUBY_ENGINE, RUBY_ENGINE_VERSION; require 'openssl'; OpenSSL::Cipher.new('AES-128-CBC').random_iv"
Profiling enabled; ^C shutdown will now dump profile info
2.3.3
jruby
9.1.14.0

main profile results:
Total time: 27.28

     total        self    children       calls  method
----------------------------------------------------------------
     24.30       24.30        0.00           1  OpenSSL::Cipher#random_iv
      2.52        0.05        2.47         221  Kernel.require
      1.94        0.00        1.94          91  Kernel.require
      1.18        0.15        1.03          35  Kernel.load
      0.82        0.82        0.01           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.68        0.00        0.68           2  Object#require_jar
      0.68        0.00        0.68           2  Jars.require_jar
      0.66        0.00        0.66           2  Jars.require_jar_with_block
      0.66        0.00        0.65           2  Jars.do_require
      0.65        0.00        0.65           2  Jars.home
      0.65        0.00        0.65           2  Jars.local_maven_repo
      0.65        0.00        0.65           1  Jars.maven_local_settings
      0.47        0.08        0.39          97  Array#each
      0.33        0.00        0.33           1  Gem::Specification.load_defaults
      0.33        0.00        0.33           1  Gem::Specification.each_spec
      0.33        0.00        0.33           1  Gem::Specification.each_gemspec
      0.30        0.09        0.21         271  Class#new
      0.20        0.00        0.20          15  Gem::Specification.load
      0.19        0.00        0.18          28  Kernel.gem
      0.17        0.04        0.13          15  Kernel.eval
      0.17        0.00        0.16           3  Gem::Dependency#to_spec
      0.16        0.00        0.16           3  Gem::Dependency#to_specs
      0.16        0.00        0.16           3  Gem::Dependency#matching_specs
      0.15        0.00        0.14          12  Gem.register_default_spec
      0.14        0.00        0.14          27  Kernel.send
      0.10        0.00        0.10           3  Gem::Specification.stubs_for
      0.09        0.01        0.08          14  Gem::Specification#initialize
      0.09        0.08        0.00          24  Java::JavaPackage#method_missing
      0.08        0.08        0.00        1424  String#sub
      0.07        0.04        0.04          82  Array#map
      0.05        0.02        0.03           2  Fixnum#times
      0.05        0.00        0.05          27  Gem.remove_unresolved_default_spec
      0.05        0.00        0.05           1  URI::RFC2396_Parser#initialize
      0.05        0.00        0.05           3  Gem::Specification.dirs
      0.04        0.00        0.04           9  Gem::Specification.gemspec_stubs_in
      0.04        0.00        0.03          79  Gem::Version.new
      0.04        0.00        0.03           1  URI::RFC2396_Parser#initialize_regexp
      0.03        0.03        0.01           4  Hash#each
      0.03        0.03        0.00          29  Regexp#initialize
      0.03        0.00        0.03           2  Object#java_import
      0.03        0.03        0.00           1  Time.now
      0.03        0.00        0.03          41  Gem::Specification#add_dependency_with_type
      0.03        0.00        0.03          95  Gem::Requirement#initialize
      0.03        0.00        0.03          38  Gem::Specification#add_development_dependency
      0.03        0.03        0.00          14  IO.read
      0.03        0.01        0.02          73  Array#map!
      0.03        0.00        0.03           3  Gem::Specification.installed_stubs
      0.03        0.00        0.02          69  Gem::Dependency#initialize
      0.03        0.00        0.03           3  Gem::Specification.map_stubs
      0.03        0.00        0.03           3  Enumerable.flat_map

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

HarlemSquirrel · 2017-11-18T02:25:18Z

This seems to only occur when installing with RVM. When downloading and running from the included binary file it's working as expected. I'm puzzled as to why this would be the case.

➤  time bin/jruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�E��A14�zp�O�ϡ5
bin/jruby -e   2.81s user 0.14s system 155% cpu 1.895 total

➤  rvm install jruby-9.1.14.0 
Searching for binary rubies, this might take some time.
Found remote file /home/k/.rvm/archives/jruby-bin-9.1.14.0.tar.gz
Checking requirements for ubuntu.
Requirements installation successful.
jruby-9.1.14.0 - #configure
jruby-9.1.14.0 - #download
jruby-9.1.14.0 - #validate archive
jruby-9.1.14.0 - #extract
jruby-9.1.14.0 - #validate binary
jruby-9.1.14.0 - #setup
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0@global
jruby-9.1.14.0 - #importing gemset /home/k/.rvm/gemsets/jruby/global.gems..
jruby-9.1.14.0 - #generating global wrappers.......
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0
jruby-9.1.14.0 - #importing gemsetfile /home/k/.rvm/gemsets/default.gems evaluated to empty gem list
jruby-9.1.14.0 - #generating default wrappers.......

➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
\������}	�N�����
ruby -e   35.84s user 0.17s system 108% cpu 33.190 total

headius · 2017-11-20T06:04:25Z

Run the slow case with the following flag, so we can get some lower-level profiling: --sample

If it's running that long it should be pretty obvious what it's spending its time on.

The main differences I can think of when installing via RVM would be the default gem set and the jruby-launcher gem. The latter is our native executable; to be portable, the tarball does not normally include it. RVM installs it when installing JRuby, since there's some use cases that don't work with the bash script.

But this doesn't give me any idea why there's such a big difference.

kares · 2017-11-20T12:51:13Z

this seems like (yet another) depleting entropy issue. although you have java.security setup properly
... maybe from within RVM these are getting "lost" or maybe launching another JVM on your machine?
you could verify by connecting with jvisualvm that the time is being spent at Java's SecureRandom
... from there you would need to figure out whether any security related system properties were set ...

headius · 2017-11-20T14:27:06Z

@kares @HarlemSquirrel I discovered that the securerandom.source property and a couple others have a little quirk: they're hardcoded to force /dev/urandom back to /dev/random.

https://bugs.openjdk.java.net/browse/JDK-6202721

The workaround there is what I'm using for JRuby 9.1.15 in the launchers: specify the path in such a way that the JDK can't detect it, such as /dev/./urandom.

See 1a4f888 and 65a004f.

kares · 2017-11-20T16:11:58Z

@headius EPIC find :) ... this must be it than, or not?

HarlemSquirrel · 2017-11-20T19:13:04Z

I'm getting the following from visualvm

I set securerandom.source=file:/dev/./urandom but that doesn't seem to help.

Here's the sample output when running

JRUBY_OPTS='--sample' rvm jruby-9.1.14.0 do ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"

https://gist.github.com/HarlemSquirrel/112821bdf3fe2b9d6446867329daf4b4

headius · 2017-11-21T03:30:43Z

Ah-ha! All those SeedGenerator threads gave me something to search, and this looks very interesting: https://bz.apache.org/bugzilla/show_bug.cgi?id=56139

tldr: if /dev/urandom isn't readable, the random number generator will fall back on a threaded pseudo-random number generator.

This seems like it could be related, but I don't understand why it would work with our tarball and not with an RVM install.

headius · 2017-11-21T03:31:51Z

Here's another interesting article that shows how to test whether entropy is being exhausted, along with other tips: https://liuzy163.wordpress.com/2015/03/20/tomcat-server-slow-due-to-blocked-seedgenerator-thread-on-insufficient-random-number-on-linux/

headius · 2017-11-21T03:43:09Z

I think I know the connection!

You are not running 9.1.15.0, which includes the urandom change in the jruby bash script. However when you install from RVM, it installs jruby-launcher...which does have the urandom change.

So something about the way I'm setting security to use urandom is wrong. I confirmed I'm seeing these threads locally, and my local startup is also slower (I thought I just messed up my env).

I would recommend doing installing the 1.1.2 version of jruby-launcher gem, which should overwrite the one with the urandom tweak. I'll figure out what's wrong with it and spin a new release.

Apparently the JDK will fail to use the egd path without a file URL. Stop the madness! See https://bz.apache.org/bugzilla/show_bug.cgi?id=56139

headius · 2017-11-21T04:06:37Z

I've fixed this in jruby-launcher 1.1.4. Please confirm it both works and doesn't run out of entropy (i.e. the urandom setting is still working).

HarlemSquirrel · 2017-11-21T15:16:30Z

@headius you, sir, are the man! That seems to have done it.

➤  gem list jruby-launcher
 
*** LOCAL GEMS ***

jruby-launcher (1.1.3 java)
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
=��d'q`)�/��_���
ruby -e   35.72s user 0.15s system 108% cpu 33.195 total
➤  gem install jruby-launcher                                                                              
Fetching: jruby-launcher-1.1.4-java.gem (100%)
Building native extensions. This could take a while...
Successfully installed jruby-launcher-1.1.4-java
1 gem installed
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�|_�x��G%�����
ruby -e   2.88s user 0.12s system 156% cpu 1.923 total

headius added a commit that referenced this issue Nov 21, 2017

Improvement to Java security random source. Fixes #4857.

fe83edd

Apparently the JDK will fail to use the egd path without a file URL. Stop the madness! See https://bz.apache.org/bugzilla/show_bug.cgi?id=56139

headius closed this as completed in jruby/jruby-launcher@545da13 Nov 21, 2017

This was referenced Nov 29, 2017

Workaround slow JRuby build activeadmin/activeadmin#5033

Merged

OpenSSL::Random.random_bytes specs seem to get stuck on Travis #4696

Closed

Slowdown of pretty straight Rails app when switching to Java 8, enabling invokedynamic #1569

Closed

enebo added this to the JRuby 9.1.15.0 milestone Dec 7, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GitHub Sponsors

OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

HarlemSquirrel commented Nov 17, 2017 •

edited

Loading

HarlemSquirrel commented Nov 18, 2017

headius commented Nov 20, 2017

kares commented Nov 20, 2017

headius commented Nov 20, 2017

kares commented Nov 20, 2017

HarlemSquirrel commented Nov 20, 2017 •

edited

Loading

headius commented Nov 21, 2017

headius commented Nov 21, 2017

headius commented Nov 21, 2017

headius commented Nov 21, 2017

HarlemSquirrel commented Nov 21, 2017

OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

Comments

HarlemSquirrel commented Nov 17, 2017 • edited Loading

HarlemSquirrel commented Nov 18, 2017

headius commented Nov 20, 2017

kares commented Nov 20, 2017

headius commented Nov 20, 2017

kares commented Nov 20, 2017

HarlemSquirrel commented Nov 20, 2017 • edited Loading

headius commented Nov 21, 2017

headius commented Nov 21, 2017

headius commented Nov 21, 2017

headius commented Nov 21, 2017

HarlemSquirrel commented Nov 21, 2017

HarlemSquirrel commented Nov 17, 2017 •

edited

Loading

HarlemSquirrel commented Nov 20, 2017 •

edited

Loading