Details

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

      Description

      There appears to be a rather severe degradation in performance on the Ruby-based Time.strptime when running on JRuby master with invokedynamic.

      Java 7 without invokedynamic:
      
      Time.strptime  65.929000   0.000000  65.929000 ( 65.930000)
      
      Java 7 with invokedynamic:
      
      Time.strptime 196.221000   0.000000 196.221000 (196.221000)
      

      I investigated a bit. The offending method is eventually Date._strptime_i in date/format.rb. It's a pretty dreadful method...very large, with a giant case/when statement with String cases. It appears that it is actually compiled by the JVM JIT, but it's so large I'm sure many of the dynamic calls are not inlining. I suspect that because non-inlined invokedynamic calls are still very slow, performance suffers.

      This lends some weight to building in a tiered failover that would limit invokedynamic use to smaller methods, failing over to normal CallSite invocation and eventually full interpretation. The compiled version using our simpler inline caching logic manages to perform around 3x faster...a vast margin.

      The benchmark is here: https://gist.github.com/1586648

      Run with --1.9, since it uses strptime from 1.9's time/date libs.

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        It's worth mentioning that 1.9.3 actually implements this as a C extension, so that would be a perfectly fair option for us.

        Ruby 1.9.3:
        
        Time.strptime  18.150000   0.010000  18.160000 ( 18.164598)
        
        Show
        Charles Oliver Nutter added a comment - It's worth mentioning that 1.9.3 actually implements this as a C extension, so that would be a perfectly fair option for us. Ruby 1.9.3: Time.strptime 18.150000 0.010000 18.160000 ( 18.164598)
        Hide
        Charles Oliver Nutter added a comment - - edited

        I made a trivial change to reduce the size of the method: put all the when bodies inside blocks using #tap. The result is pretty amazing:

        Time.strptime  69.278000   0.000000  69.278000 ( 69.278000)
        

        This is almost as fast as the non-indy unmodified version even with block dispatches for every call. Quite impressive that indy can make up for this overhead.

        https://gist.github.com/1586832

        Show
        Charles Oliver Nutter added a comment - - edited I made a trivial change to reduce the size of the method: put all the when bodies inside blocks using #tap. The result is pretty amazing: Time.strptime 69.278000 0.000000 69.278000 ( 69.278000) This is almost as fast as the non-indy unmodified version even with block dispatches for every call. Quite impressive that indy can make up for this overhead. https://gist.github.com/1586832
        Hide
        Charles Oliver Nutter added a comment -

        Some of this will have to wait until the OpenJDK guys get back to working on the JIT compiler for u4; that release will contain numerous improvements to how invokedynamic is optimized and compiled, which may make this issue go away.

        Show
        Charles Oliver Nutter added a comment - Some of this will have to wait until the OpenJDK guys get back to working on the JIT compiler for u4; that release will contain numerous improvements to how invokedynamic is optimized and compiled, which may make this issue go away.
        Hide
        Charles Oliver Nutter added a comment -

        Does seem to be better lately, so I'll mark this fixed. There's also the new indy optimizer coming soon.

        Show
        Charles Oliver Nutter added a comment - Does seem to be better lately, so I'll mark this fixed. There's also the new indy optimizer coming soon.
        Hide
        Charles Oliver Nutter added a comment -
        system ~/projects/jruby $ jruby -v tmp/strptime_bench.rb 
        jruby 1.7.0.preview2.dev (1.9.3p203) 2012-08-02 0804f53 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_05-b06 [darwin-x86_64]
        Rehearsal -------------------------------------------------
        Time.strptime  12.970000   0.120000  13.090000 (  9.213000)
        --------------------------------------- total: 13.090000sec
        
                            user     system      total        real
        Time.strptime   7.240000   0.040000   7.280000 (  6.856000)
        
        system ~/projects/jruby $ jruby -v -Xcompile.invokedynamic=true tmp/strptime_bench.rb 
        jruby 1.7.0.preview2.dev (1.9.3p203) 2012-08-02 0804f53 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_05-b06 +indy [darwin-x86_64]
        Rehearsal -------------------------------------------------
        Time.strptime  12.360000   0.120000  12.480000 (  8.862000)
        --------------------------------------- total: 12.480000sec
        
                            user     system      total        real
        Time.strptime   6.840000   0.030000   6.870000 (  6.454000)
        
        Show
        Charles Oliver Nutter added a comment - system ~/projects/jruby $ jruby -v tmp/strptime_bench.rb jruby 1.7.0.preview2.dev (1.9.3p203) 2012-08-02 0804f53 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_05-b06 [darwin-x86_64] Rehearsal ------------------------------------------------- Time.strptime 12.970000 0.120000 13.090000 ( 9.213000) --------------------------------------- total: 13.090000sec user system total real Time.strptime 7.240000 0.040000 7.280000 ( 6.856000) system ~/projects/jruby $ jruby -v -Xcompile.invokedynamic=true tmp/strptime_bench.rb jruby 1.7.0.preview2.dev (1.9.3p203) 2012-08-02 0804f53 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_05-b06 +indy [darwin-x86_64] Rehearsal ------------------------------------------------- Time.strptime 12.360000 0.120000 12.480000 ( 8.862000) --------------------------------------- total: 12.480000sec user system total real Time.strptime 6.840000 0.030000 6.870000 ( 6.454000)

          People

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

            Dates

            • Created:
              Updated:
              Resolved: