Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: JRuby 1.7.0.pre1
    • Component/s: Performance
    • Labels:
      None
    • Number of attachments :
      3

      Description

      I just added a new benchmark called test/bench/bench_file_writing.rb that duplicates the way Rails log flushing works. JRuby is between 120% and 200% slower than MRI in most cases. This adds up to the Rails dark matter.

      1. add_lseek.patch
        8 kB
        Charles Oliver Nutter
      2. append.patch
        9 kB
        Wayne Meissner
      3. lseek_to_avoid_filechannel_size.patch
        23 kB
        Charles Oliver Nutter

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        Circling back to an old bug. Still seems to be valid...we're about 50% slower than 1.8 or 1.9. Here's a runhprof profile of the top 20 methods:

        CPU TIME (ms) BEGIN (total = 145906) Thu Jul 14 15:35:15 2011
        rank   self  accum   count trace method
           1  3.43%  3.43%  250780 344208 org.jruby.RubyIO.write
           2  2.35%  5.77%  250781 344182 bench.bench_file_writing.block_3$RUBY$__file__
           3  2.08%  7.85%  250781 344165 sun.nio.ch.IOUtil.write
           4  2.06%  9.91%  250782 344097 sun.nio.ch.FileChannelImpl.size
           5  1.89% 11.80%  250781 344172 sun.nio.ch.FileChannelImpl.write
           6  1.88% 13.68%  250783 344191 org.jruby.runtime.CompiledBlock.yield
           7  1.85% 15.54%  250781 344157 sun.nio.ch.FileDispatcher.write
           8  1.72% 17.25%  250782 344116 sun.nio.ch.FileChannelImpl.position
           9  1.49% 18.74%  250781 344146 java.nio.DirectByteBuffer.put
          10  1.44% 20.18%  250789 342191 org.jruby.util.io.ChannelDescriptor.internalWrite
          11  1.43% 21.61%  250780 344204 org.jruby.RubyIO.fwrite
          12  1.33% 22.94%  250781 344159 sun.nio.ch.IOUtil.writeFromNativeBuffer
          13  1.33% 24.27%  250789 342192 org.jruby.util.io.ChannelDescriptor.write
          14  1.27% 25.54%  250782 344055 org.jruby.ast.executable.RuntimeCache.getVariable
          15  1.25% 26.79%  250782 344034 org.jruby.runtime.ThreadContext.pushFrameForBlock
          16  1.20% 27.99%  501774 304736 java.lang.ThreadLocal$ThreadLocalMap.getEntry
          17  1.17% 29.16%  501579 342136 java.lang.ThreadLocal.get
          18  1.09% 30.25%  250781 344148 java.nio.DirectByteBuffer.put
          19  1.03% 31.28%  250781 344136 sun.nio.ch.Util$BufferCache.get
          20  0.83% 32.11%  250788 336712 org.jruby.runtime.CompiledBlock.prepareSelf
        
        Show
        Charles Oliver Nutter added a comment - Circling back to an old bug. Still seems to be valid...we're about 50% slower than 1.8 or 1.9. Here's a runhprof profile of the top 20 methods: CPU TIME (ms) BEGIN (total = 145906) Thu Jul 14 15:35:15 2011 rank self accum count trace method 1 3.43% 3.43% 250780 344208 org.jruby.RubyIO.write 2 2.35% 5.77% 250781 344182 bench.bench_file_writing.block_3$RUBY$__file__ 3 2.08% 7.85% 250781 344165 sun.nio.ch.IOUtil.write 4 2.06% 9.91% 250782 344097 sun.nio.ch.FileChannelImpl.size 5 1.89% 11.80% 250781 344172 sun.nio.ch.FileChannelImpl.write 6 1.88% 13.68% 250783 344191 org.jruby.runtime.CompiledBlock.yield 7 1.85% 15.54% 250781 344157 sun.nio.ch.FileDispatcher.write 8 1.72% 17.25% 250782 344116 sun.nio.ch.FileChannelImpl.position 9 1.49% 18.74% 250781 344146 java.nio.DirectByteBuffer.put 10 1.44% 20.18% 250789 342191 org.jruby.util.io.ChannelDescriptor.internalWrite 11 1.43% 21.61% 250780 344204 org.jruby.RubyIO.fwrite 12 1.33% 22.94% 250781 344159 sun.nio.ch.IOUtil.writeFromNativeBuffer 13 1.33% 24.27% 250789 342192 org.jruby.util.io.ChannelDescriptor.write 14 1.27% 25.54% 250782 344055 org.jruby.ast.executable.RuntimeCache.getVariable 15 1.25% 26.79% 250782 344034 org.jruby.runtime.ThreadContext.pushFrameForBlock 16 1.20% 27.99% 501774 304736 java.lang.ThreadLocal$ThreadLocalMap.getEntry 17 1.17% 29.16% 501579 342136 java.lang.ThreadLocal.get 18 1.09% 30.25% 250781 344148 java.nio.DirectByteBuffer.put 19 1.03% 31.28% 250781 344136 sun.nio.ch.Util$BufferCache.get 20 0.83% 32.11% 250788 336712 org.jruby.runtime.CompiledBlock.prepareSelf
        Hide
        Charles Oliver Nutter added a comment -

        I made an interesting discovery! The file in this benchmark is set to sync = true, which means it's flushing after every write. Removing that and letting it buffer and flush naturally puts JRuby's performance on par with 1.8 and faster than 1.9. So there's something about sync mode that means we're doing too much.

        With non-sync writes looking as fast as MRI, I almost want to resolve this, but I'll look into the sync stuff too.

        Show
        Charles Oliver Nutter added a comment - I made an interesting discovery! The file in this benchmark is set to sync = true, which means it's flushing after every write. Removing that and letting it buffer and flush naturally puts JRuby's performance on par with 1.8 and faster than 1.9. So there's something about sync mode that means we're doing too much. With non-sync writes looking as fast as MRI, I almost want to resolve this, but I'll look into the sync stuff too.
        Hide
        Charles Oliver Nutter added a comment -

        Another discovery: removing File::APPEND also brings us on par with 1.8.7 and faster than 1.9.2.

        Show
        Charles Oliver Nutter added a comment - Another discovery: removing File::APPEND also brings us on par with 1.8.7 and faster than 1.9.2.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, a final discovery, and I think I can resolve this in a moment.

        I realized that there must be a way to make the Java FileChannel do the append for us, since that's a pretty standard thing to want to do when writing to a file. It turns out that yes, if you get the FileChannel from a FileOutputStream that was opened in append mode, the underlying channel will do the append for you. I modified the file-opening logic in ChannelDescriptor to use new FileOutputStream(..., true).getChannel() when the modes did not include reading (since FileOutputStream is write-only. At first this didn't help on Java 6, perhaps because they're doing the same manual seek that we were doing. But on Java 7, which has had a good amount of NIO work, it brings our execution time to just slightly slower than 1.8.7, which is comfortably faster than 1.9.

        Since it has now passed tests and specs, I'm going to go with it.

        Show
        Charles Oliver Nutter added a comment - Ok, a final discovery, and I think I can resolve this in a moment. I realized that there must be a way to make the Java FileChannel do the append for us, since that's a pretty standard thing to want to do when writing to a file. It turns out that yes, if you get the FileChannel from a FileOutputStream that was opened in append mode, the underlying channel will do the append for you. I modified the file-opening logic in ChannelDescriptor to use new FileOutputStream(..., true).getChannel() when the modes did not include reading (since FileOutputStream is write-only. At first this didn't help on Java 6, perhaps because they're doing the same manual seek that we were doing. But on Java 7, which has had a good amount of NIO work, it brings our execution time to just slightly slower than 1.8.7, which is comfortably faster than 1.9. Since it has now passed tests and specs, I'm going to go with it.
        Hide
        Charles Oliver Nutter added a comment -

        Shut 'er down! I've pushed the described change to master in the commit below. We're close enough, and considering MRI is only a couple hops from the kernel, we're doing darn good.

        Show
        Charles Oliver Nutter added a comment - Shut 'er down! I've pushed the described change to master in the commit below. We're close enough, and considering MRI is only a couple hops from the kernel, we're doing darn good.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Ola Bini
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: