Simple File IO is slower in JRuby 9.x than 1.7.x #4681

alobmaier · 2017-06-21T20:30:03Z

When doing a simple benchmark for file IO (reading a big text file several times), I encountered a performance regression.

Used text file: test.txt

Benchmark code:

require 'benchmark'

Benchmark.bm do |x|
  5.times do 
    x.report do 
      1000.times do
        file = File.open('test.txt') 
        file.readlines
        file.seek 0
      end
    end
  end
end

Environment

Running on Windows 10 (Version 1607).

Expected Behavior

I expected at least the same performance than JRuby 1.7.26.

Actual Behavior

JRuby 1.7.26:

C:\code> jruby -v .\io.rb
jruby 1.7.26 (1.9.3p551) 2016-08-26 69763b8 on Java HotSpot(TM) Client VM 1.8.0_111-b14 +jit [Windows 10-x86]
       user     system      total        real
   1.466000   0.000000   1.466000 (  1.466000)
   1.332000   0.000000   1.332000 (  1.331000)
   0.887000   0.000000   0.887000 (  0.887000)
   1.108000   0.000000   1.108000 (  1.108000)
   1.301000   0.000000   1.301000 (  1.301000)

JRuby 9.1.10.0:

C:\code> jruby -v .\io.rb
jruby 9.1.10.0 (2.3.3) 2017-05-25 b09c48a Java HotSpot(TM) Client VM 25.111-b14 on 1.8.0_111-b14 +jit [mswin32-x86]
       user     system      total        real
  19.523000   0.000000  19.523000 ( 19.522826)
  21.285000   0.000000  21.285000 ( 21.284657)
  20.799000   0.000000  20.799000 ( 20.799130)
  19.675000   0.000000  19.675000 ( 19.675062)
  19.823000   0.000000  19.823000 ( 19.823282)

enebo · 2017-06-21T21:05:33Z

Almost looks like some buffering went away to get that much slower.

original-brownbear · 2017-08-27T08:05:47Z

@alobmaier @enebo I can't reproduce any issue with the current master:

I see the following from this code:

➜  bench git:(4681) ✗ jruby -v bench_io.rb
jruby 1.7.26 (1.9.3p551) 2016-08-26 69763b8 on Java HotSpot(TM) 64-Bit Server VM 1.8.0_131-b11 +jit [darwin-x86_64]
       user     system      total        real
   0.590000   0.070000   0.660000 (  0.225000)
   0.180000   0.070000   0.250000 (  0.213000)
   0.200000   0.070000   0.270000 (  0.209000)
   0.130000   0.070000   0.200000 (  0.198000)
   0.170000   0.070000   0.240000 (  0.204000)

➜  bench git:(4681) ✗ ../bin/jruby -v bench_io.rb 
jruby 9.2.0.0-SNAPSHOT (2.4.1) 2017-08-27 2e6f9d9 Java HotSpot(TM) 64-Bit Server VM 25.131-b11 on 1.8.0_131-b11 +jit [darwin-x86_64]
       user     system      total        real
   0.820000   0.070000   0.890000 (  0.272160)
   0.140000   0.060000   0.200000 (  0.184638)
   0.290000   0.060000   0.350000 (  0.179713)
   0.130000   0.060000   0.190000 (  0.178701)
   0.120000   0.060000   0.180000 (  0.170780)

looks like we even got a little faster?

enebo · 2017-08-28T14:37:50Z

@original-brownbear Windows is not fully native like MacOS/Linux are for IO so I am betting this is still an issue on windows.

original-brownbear · 2017-08-28T14:42:03Z

@enebo ah right my bad, forget I said anything :)

headius · 2019-08-07T19:22:01Z

Still a problem with JRuby 9.2.8 (on master). I'm pretty sure this relates to how we handle text mode, but I'll poke at it for a few minutes.

headius · 2019-08-07T19:38:56Z

Yep, confirmed. Because we can't specify O_TEXT at the file-opening level on Windows. Our workaround for that installs a transcoding stage that handles the newlines as a separate transcoding pass, which is likely why this is many times faster when specifying binary mode (binary mode does not do crlf translation):

$ jruby test.rb
       user     system      total        real
   0.374000   0.000000   0.374000 (  0.365714)
   0.210000   0.000000   0.210000 (  0.205973)
   0.203000   0.000000   0.203000 (  0.201782)
   0.203000   0.000000   0.203000 (  0.197571)
   0.189000   0.000000   0.189000 (  0.191546)

These binary read numbers are also significantly faster than JRuby 1.7.27:

$ ../jruby-1.7.27/bin/jruby.exe -v test.rb
jruby 1.7.27 (1.9.3p551) 2017-05-11 8cdb01a on OpenJDK 64-Bit Server VM 1.8.0_222-b10 +jit [Windows 10-amd64]
io/console not supported; tty will not be manipulated
       user     system      total        real
   0.718000   0.000000   0.718000 (  0.719000)
   0.578000   0.000000   0.578000 (  0.578000)
   0.578000   0.000000   0.578000 (  0.578000)
   0.578000   0.000000   0.578000 (  0.578000)
   0.578000   0.000000   0.578000 (  0.578000)

headius · 2019-08-07T19:40:05Z

Here's interleaved text and binary mode numbers:

$ jruby test.rb
                                     user     system      total        real
text mode (default)              3.149000   0.000000   3.149000 (  3.150188)
binary mode                      0.263000   0.000000   0.263000 (  0.261618)
text mode (default)              2.836000   0.000000   2.836000 (  2.836484)
binary mode                      0.194000   0.000000   0.194000 (  0.194265)
text mode (default)              2.616000   0.000000   2.616000 (  2.616108)
binary mode                      0.197000   0.000000   0.197000 (  0.197624)
text mode (default)              2.605000   0.000000   2.605000 (  2.604855)
binary mode                      0.185000   0.000000   0.185000 (  0.185601)
text mode (default)              2.569000   0.000000   2.569000 (  2.569859)
binary mode                      0.201000   0.000000   0.201000 (  0.201081)

headius · 2019-08-07T21:08:54Z

Ok so we're not going to get to this in 9.2.8. I am filling in what information we have so we can do this for 9.2.9.

Basically the problem here is that Java IO provides no way to set O_TEXT when opening a file, forcing us to do all our own CRLF translation using the transcoding subsystem. That is much slower than allowing Windows do to the translation for us.

However as of 9.2.8 we have incorporated code (from #5809 and related issues) that allows us to dig out a file descriptor from Windows IO channels. This combined with the _setmode Windows C API should make it possible to set binary or text mode when the file descriptor logic works.

@byteit101 This may be something you are interested in playing with? Basically we have a number of places in our ported IO logic where I've commented out O_BINARY or O_TEXT logic; other locations may have been deleted, but we can audit the MRI code and see where they do these sets. If we're able to access the real file descriptor and set these flags, we can remove the logic that forces manual CRLF translation.

Commented code:

jruby/core/src/main/java/org/jruby/RubyIO.java

Lines 552 to 561 in 50afda4

    
           if (OpenFlags.O_BINARY.defined()) { 
        
               // TODO: Windows 
        
               //            if (fptr.readconv == null) { 
        
               //                SET_BINARY_MODE_WITH_SEEK_CUR(fptr); 
        
               //            } 
        
               //            else { 
        
               // TODO: setmode O_BINARY means what via NIO? 
        
               //                setmode(fptr->fd, O_BINARY); 
        
               //            } 
        
           }

jruby/core/src/main/java/org/jruby/RubyIO.java

Lines 264 to 268 in 50afda4

    
           //            if (!runtime.getPosix().isatty(fd)) { 
        
           //                fmode |= OpenFile.BINMODE; 
        
                           // TODO: setmode O_BINARY means what via NIO? 
        
           //                setmode(fd, OpenFlags.O_BINARY); 
        
           //            }

jruby/core/src/main/java/org/jruby/RubyIO.java

Lines 3090 to 3103 in 50afda4

    
                       //        #if defined(RUBY_TEST_CRLF_ENVIRONMENT) || defined(_WIN32) 
        
                       //        previous_mode = set_binary_mode_with_seek_cur(fptr); 
        
                       //        #endif 
        
                       n = fptr.fread(context, str, 0, len); 
        
                   } finally { 
        
                       if (locked) fptr.unlock(); 
        
                   } 
        
                   ((RubyString)str).setReadLength(n); 
        
           //        #if defined(RUBY_TEST_CRLF_ENVIRONMENT) || defined(_WIN32) 
        
           //        if (previous_mode == O_TEXT) { 
        
           //            setmode(fptr->fd, O_TEXT); 
        
           //        } 
        
           //        #endif

jruby/core/src/main/java/org/jruby/RubyIO.java

Lines 4167 to 4187 in 50afda4

    
                   if (EncodingUtils.DEFAULT_TEXTMODE != 0) { 
        
                       if ((fptr.getMode() & OpenFile.TEXTMODE) != 0 && (fmode_p[0] & OpenFile.BINMODE) != 0) { 
        
                           fptr.setMode(fptr.getMode() & ~OpenFile.TEXTMODE); 
        
                           // TODO: setmode O_BINARY means what via NIO? 
        
           //                setmode(fptr->fd, O_BINARY); 
        
                       } 
        
                       if (Platform.IS_WINDOWS) { // #if defined(RUBY_TEST_CRLF_ENVIRONMENT) || defined(_WIN32) 
        
                           if ((fptr.encs.ecflags & EncodingUtils.ECONV_DEFAULT_NEWLINE_DECORATOR) != 0) { 
        
                               fptr.encs.ecflags |= EConvFlags.UNIVERSAL_NEWLINE_DECORATOR; 
        
                           } 
        
                       } 
        
                   } 
        
                   fptr.setMode(fptr.getMode() | fmode_p[0]); 
        
                   if (EncodingUtils.DEFAULT_TEXTMODE != 0) { 
        
                       if ((fptr2.getMode() & OpenFile.TEXTMODE) != 0 && (fmode_p[0] & OpenFile.BINMODE) != 0) { 
        
                           fptr2.setMode(fptr2.getMode() & ~OpenFile.TEXTMODE); 
        
                           // TODO: setmode O_BINARY means what via NIO? 
        
           //                setmode(fptr2->fd, O_BINARY); 
        
                       } 
        
                   }

jruby/core/src/main/java/org/jruby/util/io/OpenFile.java

Lines 2120 to 2129 in 50afda4

    
           //        #if defined(RUBY_TEST_CRLF_ENVIRONMENT) || defined(_WIN32) 
        
           //        #define fmode (fptr->mode) 
        
           //        else if (MODE_BTMODE(DEFAULT_TEXTMODE,0,1)) { 
        
           //        if ((fptr->mode & FMODE_READABLE) && 
        
           //                !(fptr->encs.ecflags & ECONV_NEWLINE_DECORATOR_MASK)) { 
        
           //            setmode(fptr->fd, O_BINARY); 
        
           //        } 
        
           //        else { 
        
           //            setmode(fptr->fd, O_TEXT); 
        
           //        }

Forced CRLF transcoding:

jruby/core/src/main/java/org/jruby/util/io/OpenFile.java

Lines 913 to 929 in 50afda4

    
           // MRI: NEED_READCONV 
        
           public boolean needsReadConversion() { 
        
               return Platform.IS_WINDOWS ? 
        
                       (encs.enc2 != null || (encs.ecflags & ~EConvFlags.CRLF_NEWLINE_DECORATOR) != 0) || isTextMode() 
        
                       : 
        
                       (encs.enc2 != null || NEED_NEWLINE_DECORATOR_ON_READ()); 
        
           } 
        
           // MRI: NEED_WRITECONV 
        
           public boolean needsWriteConversion(ThreadContext context) { 
        
               Encoding ascii8bit = context.runtime.getEncodingService().getAscii8bitEncoding(); 
        
               return Platform.IS_WINDOWS ? 
        
                       ((encs.enc != null && encs.enc != ascii8bit) || (encs.ecflags & ((EConvFlags.DECORATOR_MASK & ~EConvFlags.CRLF_NEWLINE_DECORATOR)|EConvFlags.STATEFUL_DECORATOR_MASK)) != 0) 
        
                       : 
        
                       ((encs.enc != null && encs.enc != ascii8bit) || NEED_NEWLINE_DECORATOR_ON_WRITE() || (encs.ecflags & (EConvFlags.DECORATOR_MASK|EConvFlags.STATEFUL_DECORATOR_MASK)) != 0); 
        
           }

headius · 2019-08-07T21:14:43Z

FWIW if you are reading text files you know do not contain CRLF line terminators, you can just tell it to use binary mode (using b mode as in File.open("blah", "rb")) to get the faster performance.

byteit101 · 2019-08-08T00:28:21Z

Hmm, possibly.

Of note: getting the real fd for _setmode requires calling ChannelFD#bestFileno(true), as bestFileno()/bestFileno(false) return fake fileno's on windows by default, until requested. This, I suppose, would have the effect of using 2x the file handles when opening a file in text mode.

headius · 2019-08-19T22:22:32Z

Given the cost of manually doing CRLF translation, I think the cost of additional handles/descriptors is tolerable.

headius · 2020-02-12T17:40:46Z

Detargeting. This could happen any time, but someone needs to sit down on Windows and make native IO work.

enebo added the regression label Jun 21, 2017

enebo added this to the JRuby 9.2.0.0 milestone Jun 21, 2017

enebo added the windows label Aug 28, 2017

enebo modified the milestones: JRuby 9.2.0.0, JRuby 9.2.1.0 May 24, 2018

headius modified the milestones: JRuby 9.2.1.0, JRuby 9.2.2.0 Sep 19, 2018

enebo modified the milestones: JRuby 9.2.2.0, JRuby 9.2.3.0, JRuby 9.2.4.0, JRuby 9.2.5.0 Nov 7, 2018

enebo modified the milestones: JRuby 9.2.5.0, JRuby 9.2.6.0 Dec 6, 2018

enebo modified the milestones: JRuby 9.2.6.0, JRuby 9.2.7.0 Dec 19, 2018

enebo modified the milestones: JRuby 9.2.7.0, JRuby 9.2.8.0 Jan 9, 2019

headius modified the milestones: JRuby 9.2.8.0, JRuby 9.2.9.0 Aug 7, 2019

enebo modified the milestones: JRuby 9.2.9.0, JRuby 9.2.10.0 Oct 21, 2019

headius removed this from the JRuby 9.2.10.0 milestone Feb 12, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GitHub Sponsors

Simple File IO is slower in JRuby 9.x than 1.7.x #4681

Simple File IO is slower in JRuby 9.x than 1.7.x #4681

alobmaier commented Jun 21, 2017

enebo commented Jun 21, 2017

original-brownbear commented Aug 27, 2017

enebo commented Aug 28, 2017

original-brownbear commented Aug 28, 2017

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

byteit101 commented Aug 8, 2019

headius commented Aug 19, 2019

headius commented Feb 12, 2020

Simple File IO is slower in JRuby 9.x than 1.7.x #4681

Simple File IO is slower in JRuby 9.x than 1.7.x #4681

Comments

alobmaier commented Jun 21, 2017

Environment

Expected Behavior

Actual Behavior

enebo commented Jun 21, 2017

original-brownbear commented Aug 27, 2017

enebo commented Aug 28, 2017

original-brownbear commented Aug 28, 2017

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

headius commented Aug 7, 2019

byteit101 commented Aug 8, 2019

headius commented Aug 19, 2019

headius commented Feb 12, 2020