File.new/File.open Performance Regression

One thought: Looks like in commit 8ca2281b9c741c6f4f8462cf0d556eab7624143b we started checking respond_to("read") every time before we do a read operation. We should only be doing that if it's not a RubyIO and doesn't have a custom version of read, though. Investigating.

Nevermind, I read it wrong...it's not doing it before each read.

Hmm, is there a way you can package up something I can run myself? I do not (yet) see any changes to IOInputStream that would cause a perf regression.

OK, sure!

If I run jruby --1.9 -Ilib test/scratch.rb on the attached files, then I get the behavior I described.

I profiled both versions with the Netbeans profiler. I think I got something - when comparing the hotspots side by side (cf. PNG image), ChannelDescriptor.<init> stands out for the trunk version (trunk is on the right). I looked into the sources and I found the difference:
https://github.com/jruby/jruby/blob/master/src/org/jruby/util/io/ChannelDescriptor.java#L171-L173. Looks like the instanceofs take up some time. But I haven't found out yet what the topmost entry represents (test$scratch$block_0$RUBY$_file_.call) - it's missing in the 1.6.5.1 version and it takes most of the time. I suppose this to be the real culprit, maybe you can figure it out? I attached both profiler files.

Martin: Hmm...that seems like a red herring. instanceof checks should be very fast, and shouldn't make any difference for reads/writes after the ChannelDescriptor has already been allocated. I'll have a look at this in more depth today.

Ahh, after finally looking at your benchmark I see it's File.new and File.open you're concerned about?

Ok, so it's IOInputStream that's a red herring. Here's numbers for your benchmark, modified to bmbm and to bench the File.open/File.new logic separately. It seems the slowdown could be explained entirely by loss of perf in File.open/File.new.

system ~/projects/jruby/ioinputstream $ jruby -v -I lib test/scratch.rb 
jruby 1.7.0.dev (ruby-1.9.3-p28) (2012-02-19 56c8e4a) (OpenJDK 64-Bit Server VM 1.7.0-u2-b21) [darwin-amd64-java]
Rehearsal ---------------------------------------------------------
File.new alone:         4.530000   0.000000   4.530000 (  4.530000)
File.open alone:        3.506000   0.000000   3.506000 (  3.506000)
File.new:               5.384000   0.000000   5.384000 (  5.384000)
File.open:              5.155000   0.000000   5.155000 (  5.155000)
File.open(..., 'rb'):   5.447000   0.000000   5.447000 (  5.447000)
----------------------------------------------- total: 24.022000sec

                            user     system      total        real
File.new alone:         3.434000   0.000000   3.434000 (  3.434000)
File.open alone:        3.395000   0.000000   3.395000 (  3.395000)
File.new:               5.037000   0.000000   5.037000 (  5.037000)
File.open:              4.826000   0.000000   4.826000 (  4.826000)
File.open(..., 'rb'):   5.106000   0.000000   5.106000 (  5.106000)

system ~/projects/jruby/ioinputstream $ rvm use jruby-1.6.5.1 do ruby -v -I lib test/scratch.rb 
jruby 1.6.5.1 (ruby-1.8.7-p330) (2011-12-27 1bf37c2) (OpenJDK 64-Bit Server VM 1.7.0-u2-b21) [darwin-amd64-java]
Rehearsal ---------------------------------------------------------
File.new alone:         3.554000   0.000000   3.554000 (  3.522000)
File.open alone:        2.527000   0.000000   2.527000 (  2.528000)
File.new:               4.303000   0.000000   4.303000 (  4.303000)
File.open:              4.077000   0.000000   4.077000 (  4.077000)
File.open(..., 'rb'):   4.253000   0.000000   4.253000 (  4.253000)
----------------------------------------------- total: 18.714000sec

                            user     system      total        real
File.new alone:         2.411000   0.000000   2.411000 (  2.411000)
File.open alone:        2.425000   0.000000   2.425000 (  2.425000)
File.new:               4.065000   0.000000   4.065000 (  4.065000)
File.open:              4.257000   0.000000   4.257000 (  4.257000)
File.open(..., 'rb'):   4.580000   0.000000   4.580000 (  4.580000)

I'll update the description accordingly.

My top sampled profile items look like the same methods in 1.6.5.1 to 1.7 (--sample... not super accurate, but it can show egregious hotspots sometimes):

1.7:

         Stub + native   Method                        
 23.7%    47  +   272    java.io.UnixFileSystem.getBooleanAttributes0
 16.7%     0  +   225    java.lang.Class.getClassLoader0
 16.6%    11  +   213    java.io.RandomAccessFile.open

1.6.5.1:

         Stub + native   Method                        
 27.3%    30  +   251    java.io.UnixFileSystem.getBooleanAttributes0
 19.0%    12  +   184    java.io.RandomAccessFile.open
 17.4%     0  +   179    java.lang.Class.getClassLoader0

I confirmed that removing the instanceof checks in ChannelDescriptor constructor don't appear to have an effect.

Hmm, so far no luck. I ran some profiles that were inconclusive. I eyeballed the execution paths. So far nothing has popped up.

However, I wonder...given that the perf issue is actually just in opening a new file, is this still a critical case? Actual IO against a nontrivial file has to vastly outweigh opening it, doesn't it? We're talking about a maybe 20-30% reduction in File-opening perf...

Glad you found the real reason! Seems to be one of the many cases where profiling sends you one off

No, I think in my own case it's not critical at all - it's just something I noticed in my benchmark - since krypt currently is a pure Java extension these were the only figures that changed for me when switching form 1.6.5.1 to 1.7trunk. I just thought I should let you know, in case it had more drastic consequences. But if it's just for opening files then I guess it's not too relevant. I'm pretty sure you guys have more important tasks to work on, so I guess we can close this?

We'll leave it open for now and I'll let it taunt me. At some point we'll either find the solution, it will go away on its own, or we'll decide we don't care anymore

OK, sounds fair to me

Circling around to this...I see the following in a sampled profile:

14.7% 0 + 235 java.lang.Throwable.fillInStackTrace

Not good! Need to figure out where these are coming from.

Ok, so the stack traces were coming from EOFExceptions during read; we throw one to indicate EOF, but constructing them is expensive. I modified our logic to use a single cached EOFException, since we always just catch it and throw a Ruby error. This speeds up your benchmark substantially, but it's unlikely that this is the original cause of slowdown since this logic hasn't changed for a long time.

Baby steps, I guess. At least EOF reads are significantly faster now.

Nice, that sounds good. Is it already in master? I'm excited to see the improvements in action

Yes, the EOFException change is already in master and will be in pre2.