[#JRUBY-2597] Performance problem for nil string in SSLSocket.sysread

JRuby

Performance problem for nil string in SSLSocket.sysread

Created: 30/May/08 04:58 PM Updated: 14/Aug/08 04:51 AM

Component/s:

OpenSSL, Performance

Affects Version/s:

None

Fix Version/s:

JRuby 1.1+

Time Tracking:

Not Specified

File Attachments:	1. test.rb (0.5 kb)
Environment:	jruby 1.1.2 and ruby 1.8.6

Description

« Hide

If data provided to any SSL request is nil then the request takes a very long time. I followed the data all the way to
SSLSocket.sysread in jopenssl.

require 'net/https'
require 'benchmark'

Only effects SSL
Effects get requests as well haven't checked put and delete

def request(data)
connection = Net::HTTP.new("www.google.com", 443)
connection.use_ssl = true
connection.verify_mode = OpenSSL::SSL::VERIFY_NONE
connection.start do |connection|
connection.request_post("/tbproxy/spell?lang=en", data, { 'User-Agent' => "Test", 'Accept' => 'text/xml' })
end
end

puts "is nil: #{Benchmark.measure { request(nil) }.to_s.chomp} puts "is not: #{Benchmark.measure { request(" ") }.to_s.chomp} [#{RUBY_PLATFORM}">{RUBY_PLATFORM}]"
puts "is not: #{Benchmark.measure { request(" ") }.to_s.chomp} [#{RUBY_PLATFORM}"

Output I'm seeing when running with ruby and then jruby:
is nil: 0.000000 0.010000 0.010000 ( 0.067843) [x86_64-linux]
is not: 0.000000 0.000000 0.000000 ( 0.107844) [x86_64-linux]
is nil: 10.454000 0.000000 10.454000 ( 10.454042) [java]
is not: 0.191000 0.000000 0.191000 ( 0.192685) [java]

All

Comments

Work Log

Change History

Sort Order:

Ascending order - Click to sort in descending order

[ Permlink | « Hide ]

Brian Tatnall - 30/May/08 05:01 PM

Forgot to mention a few things.

I'm using jruby-openssl-0.2.3.

After following the data to sysread as the bottleneck I did and search and found the History.txt file had a line that is probably relevant to the problem.

== 0.2

Enable remaining tests; fix a nil string issue in SSLSocket.sysread (~~JRUBY-1888~~)

[ Permlink | « Hide ]

Brian Tatnall - 05/Jun/08 04:12 PM

Dug a little further into the issue.

I can recreate the performance hit using both nil and "" by varying the value sent to @io.sysread in net/protocol.rb

def rbuf_fill
timeout(@read_timeout) { # @rbuf << @io.sysread(1024*16) @rbuf << @io.sysread(10) }
end

is "": 10.302000 0.000000 10.302000 ( 10.302537) [java]
is nil: 10.271000 0.000000 10.271000 ( 10.269867) [java]

The bug is dependent on the length allocated by the ByteBuffer for the response. If the resposne is bigger than the allocation (currently 1024 * 16) then it's going to take 10+ seconds to recover.

[ Permlink | « Hide ]

Brian Tatnall - 06/Jun/08 09:45 AM

Looked at the problem a little more.

SSLSocket.sysread calls waitSelect with rsel and tries to select on rsel with a blocking select.

If i change waitSelect from:

sel.select();

sel.selectNow();

Speed increases, but this clearly isn't a solution because the while loop in protocol.rb#read is far more CPU intensive because it's no longer blocking.

[ Permlink | « Hide ]

Charles Oliver Nutter - 16/Jul/08 03:09 AM

Hey, this one slipped off my radar. Is it still an issue? Clock's ticking on 1.1.3.

[ Permlink | « Hide ]

Brian Tatnall - 16/Jul/08 01:38 PM

Problem still exists using:
jruby 1.1.3-dev (ruby 1.8.6 patchlevel 114) (2008-07-16 rev 7192) [i386-java]
jruby-openssl-0.2.3

[ Permlink | « Hide ]

Charles Oliver Nutter - 16/Jul/08 02:37 PM

Ok, looks like this is squarely a JRuby-OpenSSL issue, and won't hold up the 1.1.3 release. But we obviously need to fix it. I'm bringing up JOSSL now to see if it's something simple.

[ Permlink | « Hide ]

Charles Oliver Nutter - 16/Jul/08 05:14 PM

I couldn't find anything obvious, but one suggestion I'd have for whoever works on this (including me) is that we should probably start looking at removing the SSL implementations of various IO/socket methods and falling back on IO's versions, since they're more in line with Ruby behavior. Punting to post 1.1.3, since it probably won't be a change in JRuby to fix it.

[ Permlink | « Hide ]

Ola Bini - 13/Aug/08 12:53 PM

The problem was that the SSLSocket was blocking on a read when there was still SSL data to process in buffers. It's been fixed on trunk now, and a test added (but commented out, since it takes time).