OpenSSL::X509::Store#set_default_paths is slower than expected #4238

thomas07vt · 2016-10-19T19:21:00Z

Environment

$ ruby -v
jruby 9.1.2.0 (2.3.0) 2016-05-26 7357c8f Java HotSpot(TM) 64-Bit Server VM 25.102-b14 on 1.8.0_102-b14 +jit [linux-x86_64]

$ java -version
java version "1.8.0_102"
Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)

$ gem list
...
jruby-openssl (0.9.17 java, 0.9.15 java)
...

$ irb
jruby-9.1.2.0 :011 > OpenSSL::X509::DEFAULT_CERT_FILE
=> "/etc/pki/tls/certs/ca-bundle.crt" 

$ stat '/usr/java/jdk1.8.0_102/jre/lib/security/cacerts'
  File: ‘/usr/java/jdk1.8.0_102/jre/lib/security/cacerts’
  Size: 112860      Blocks: 224        IO Block: 4096   regular file

$ stat  '/etc/pki/tls/certs/ca-bundle.crt'
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 863389      Blocks: 1688       IO Block: 4096   regular file

Expected Behavior

I believe this is a jruby-openssl issue, but the readme says to open an issue here.

I would expect OpenSSL::X509::Store#set_default_paths to be fast, or at least comparable to the jruby1.7.20 server I use.

Perhaps the issue is just that it takes a long time to parse the default '/etc/pki/tls/certs/ca-bundle.crt' file? I don't really know whats going on under the hood of #set_default_paths, but that is taking a longer time that in would expect.

Actual Behavior

# bench1.rb
##########################################################################################################################
require 'jruby/profiler'
require 'jruby-openssl'

profile_data = JRuby::Profiler.profile do
  10.times { OpenSSL::X509::Store.new.set_default_paths }
end
profile_printer = JRuby::Profiler::FlatProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)

$ jruby --profile.api bench1.rb
Profiling enabled; ^C shutdown will now dump profile info
Total time: 3.03

     total        self    children       calls  method
----------------------------------------------------------------
      3.03        0.00        3.02           1  Fixnum#times
      3.02        3.02        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10 OpenSSL::X509::Store#initialize

# bench2.rb
##########################################################################################################################
require 'jruby/profiler'
require 'jruby-openssl'

ENV['SSL_CERT_FILE'] = '/usr/java/jdk1.8.0_102/jre/lib/security/cacerts'

profile_data = JRuby::Profiler.profile do
  10.times { OpenSSL::X509::Store.new.set_default_paths }
end
profile_printer = JRuby::Profiler::FlatProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)

$ jruby --profile.api bench2.rb
Profiling enabled; ^C shutdown will now dump profile info
Total time: 0.19

     total        self    children       calls  method
----------------------------------------------------------------
      0.19        0.00        0.19           1  Fixnum#times
      0.19        0.19        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00           10 OpenSSL::X509::Store#initialize

# bench3.rb
##########################################################################################################################
require 'jruby/profiler'
require 'jruby-openssl'

ENV['SSL_CERT_FILE'] = '/etc/pki/tls/certs/ca-bundle.crt'

profile_data = JRuby::Profiler.profile do
  10.times { OpenSSL::X509::Store.new.set_default_paths }
end
profile_printer = JRuby::Profiler::FlatProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)

$ jruby --profile.api bench3.rb 
Profiling enabled; ^C shutdown will now dump profile info
Total time: 3.15

     total        self    children       calls  method
----------------------------------------------------------------
      3.15        0.00        3.15           1  Fixnum#times
      3.15        3.15        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10 OpenSSL::X509::Store#initialize

I also updated ca-bundle.crt file which brought down the file size significantly:

$ curl https://curl.haxx.se/ca/cacert.pem -o /etc/pki/tls/certs/ca-bundle.crt
$ stat '/etc/pki/tls/certs/ca-bundle.crt'
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 261644      Blocks: 512

But bench3.rb is still much slower than the java cacert file:

$ jruby --profile.api bench3.rb
Profiling enabled; ^C shutdown will now dump profile info
Total time: 2.79

     total        self    children       calls  method
----------------------------------------------------------------
      2.79        0.00        2.79           1  Fixnum#times
      2.79        2.79        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10  OpenSSL::X509::Store#initialize

Meanwhile on a separate server with an older setup:

$ java -version
java version "1.8.0_05"
Java(TM) SE Runtime Environment (build 1.8.0_05-b13)

$ jruby -v
jruby 1.7.20 (1.9.3p551) 2015-05-04 3086e6a on Java HotSpot(TM) 64-Bit Server VM 1.8.0_05-b13 +jit [linux-amd64]

$ stat /etc/pki/tls/certs/ca-bundle.crt
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 261644      Blocks: 512        IO Block: 4096   regular file

$ jruby --profile.api bench3.rb 
Profiling enabled; ^C shutdown will now dump profile info
Total time: 0.66

     total        self    children       calls  method
----------------------------------------------------------------
      0.66        0.00        0.66           1  Fixnum#times
      0.66        0.66        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10  OpenSSL::X509::Store#initialize

thomas07vt · 2016-10-27T21:04:23Z

Should I open this issue on jruby-openssl?

kares · 2016-11-02T15:41:52Z

it's a native (Java implemented) Ruby method thus the limited usefulness of the built-in profiler (showing up only Ruby methods). I am not sure if you're also showcasing a speed regression on 9K from JRuby 1.7 ?

thomas07vt · 2016-11-02T15:51:36Z

@kares yeah there seems to be a regression in jruby 9k

In my last benchmark example, I was running jruby 1.7.20 and the OpenSSL::X509::Store#set_default_paths method took 0.66 seconds, while jruby 9k took 3.15 seconds

On both of these machines I had updated to the latest ca-bundle.crt file, and was using that directly:
ENV['SSL_CERT_FILE'] = '/etc/pki/tls/certs/ca-bundle.crt'

These benchmarks ran on aws servers, but I would expect that you could reproduce on your machine too.

kares · 2016-11-02T16:04:23Z

@thomas07vt thanks. than it's probably a valid issue here to have but :

seems that you were running 9.1.2 it would be better to compare with latest (9.1.5) and also somehow your Java 8 version seems to have been changing (might be relevant since 101/102 did some SecureRandom improvements that might be affecting runs)

UPDATE: also 1.7.20 has an older jossl gem version than 9K, so comparison should be re-done.

thomas07vt · 2016-11-02T17:41:04Z

yeah i upgraded the java version on one servers to see if that fixed the issue, which is why there are different versions. 102 was the slow version though, so i don't think the java version has has much of an affect.. but ill run these tests locally to see if the issue is in jruby or jruby-openssl.. stay tuned...

thomas07vt · 2016-11-02T17:59:41Z

Definitely a jruby-openssl issue:

##bench.rb

require 'jruby/profiler'
require 'openssl'

ENV['SSL_CERT_FILE'] = '/etc/pki/tls/certs/ca-bundle.crt'

puts `ruby -v`
puts `java -version`
puts `gem list | grep jruby-openssl`
puts `stat /etc/pki/tls/certs/ca-bundle.crt | grep -E '(File|Size)'`

profile_data = JRuby::Profiler.profile do
  10.times { OpenSSL::X509::Store.new.set_default_paths }
end
profile_printer = JRuby::Profiler::FlatProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)

##Results

$ jruby --profile.api bench.rb 
Profiling enabled; ^C shutdown will now dump profile info
jruby 1.7.19 (1.9.3p551) 2015-01-29 20786bd on Java HotSpot(TM) 64-Bit Server VM 1.8.0_111-b14 +jit [linux-amd64]

jruby-openssl (0.9.5 java)
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 263596      Blocks: 520        IO Block: 4096   regular file
Total time: 0.79

     total        self    children       calls  method
----------------------------------------------------------------
      0.79        0.00        0.79           1  Fixnum#times
      0.79        0.79        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10  OpenSSL::X509::Store#initialize

$ jruby --profile.api bench.rb 
Profiling enabled; ^C shutdown will now dump profile info
jruby 1.7.19 (1.9.3p551) 2015-01-29 20786bd on Java HotSpot(TM) 64-Bit Server VM 1.8.0_111-b14 +jit [linux-amd64]

jruby-openssl (0.9.17 java, 0.9.5 java)
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 263596      Blocks: 520        IO Block: 4096   regular file
Total time: 3.07

     total        self    children       calls  method
----------------------------------------------------------------
      3.07        0.00        3.07           1  Fixnum#times
      3.06        3.06        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10  OpenSSL::X509::Store#initialize

thomas07vt · 2016-11-02T18:08:03Z

And for the sake of completeness.. same issue in jruby 9.1.5.0

$ jruby --profile.api bench.rb
Profiling enabled; ^C shutdown will now dump profile info
jruby 9.1.5.0 (2.3.1) 2016-09-07 036ce39 Java HotSpot(TM) 64-Bit Server VM 25.111-b14 on 1.8.0_111-b14 +jit [linux-x86_64]
java version "1.8.0_111"
Java(TM) SE Runtime Environment (build 1.8.0_111-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.111-b14, mixed mode)

jruby-openssl (0.9.17 java)
  File: ‘/etc/pki/tls/certs/ca-bundle.crt’
  Size: 263596      Blocks: 520        IO Block: 4096   regular file
Total time: 3.17

     total        self    children       calls  method
----------------------------------------------------------------
      3.17        0.00        3.17           1  Fixnum#times
      3.17        3.17        0.00          10  OpenSSL::X509::Store#set_default_paths
      0.00        0.00        0.00          10  Class#new
      0.00        0.00        0.00          10  OpenSSL::X509::Store#initialize

kares · 2016-11-02T18:11:47Z

OK, thanks jossl 0.9.5 really did not do much (mostly dummy set_default_paths), newer actually does smt.
please move this onto jruby-openssl' tracker (your last comment should be enough) - its not a JRuby issue.

thomas07vt · 2016-11-02T18:52:46Z

👍 done: jruby/jruby-openssl#111

kares added this to the Invalid or Duplicate milestone Nov 2, 2016

thomas07vt mentioned this issue Nov 2, 2016

OpenSSL::X509::Store#set_default_paths is much slower in v. 0.9.17 than v. 0.9.5 jruby/jruby-openssl#111

Open

kares closed this as completed Nov 7, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OpenSSL::X509::Store#set_default_paths is slower than expected #4238

OpenSSL::X509::Store#set_default_paths is slower than expected #4238

thomas07vt commented Oct 19, 2016

thomas07vt commented Oct 27, 2016

kares commented Nov 2, 2016

thomas07vt commented Nov 2, 2016

kares commented Nov 2, 2016 •

edited

thomas07vt commented Nov 2, 2016 •

edited

thomas07vt commented Nov 2, 2016

thomas07vt commented Nov 2, 2016

kares commented Nov 2, 2016 •

edited

thomas07vt commented Nov 2, 2016

OpenSSL::X509::Store#set_default_paths is slower than expected #4238

OpenSSL::X509::Store#set_default_paths is slower than expected #4238

Comments

thomas07vt commented Oct 19, 2016

Environment

Expected Behavior

Actual Behavior

thomas07vt commented Oct 27, 2016

kares commented Nov 2, 2016

thomas07vt commented Nov 2, 2016

kares commented Nov 2, 2016 • edited

thomas07vt commented Nov 2, 2016 • edited

thomas07vt commented Nov 2, 2016

thomas07vt commented Nov 2, 2016

kares commented Nov 2, 2016 • edited

thomas07vt commented Nov 2, 2016

kares commented Nov 2, 2016 •

edited

thomas07vt commented Nov 2, 2016 •

edited

kares commented Nov 2, 2016 •

edited