JRuby

Performance degradation in Time.strptime with invokedynamic

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

Ascending order - Click to sort in descending order
Hide
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Vote (0)
Watch (2)

Dates

  • Created:
    Updated:
    Resolved: