Skip to content

New strftime#6942

Merged
enebo merged 4 commits intojruby:jruby-9.3from
enebo:new_strftime
Nov 18, 2021
Merged

New strftime#6942
enebo merged 4 commits intojruby:jruby-9.3from
enebo:new_strftime

Conversation

@enebo
Copy link
Member

@enebo enebo commented Nov 16, 2021

TL;DR strftime is faster. For the format string used in logger it is 3.3x faster.

The general strategy for these changes was to eliminate object creation. The first round was just removing small bytelists in exchange for writing to the eventual result bytelist (only stymied by padded results where the value's length is unknown). The second was just reducing anything which was making an object per call.

Once we get a proper callsite cache the lexer/parser part of this can make more objects and pre-calculate things like what
padding it used etc. This in turn can lead to more custom evaluators which can lead to less code and less objects. That hoever is destined for 9.4+.

# frozen_string_literal: true

require 'benchmark/ips'
require 'logger'

puts RUBY_DESCRIPTION

logger = Logger.new(File::NULL)

Benchmark.ips do |x|
  x.config(:time => 30, :warmup => 30)

  x.report('Time.now.strftime') do
    Time.now.strftime("%Y-%m-%dT%H:%M:%S.%6N")
  end

  x.report('Logger#add') do
    logger.add(Logger::DEBUG, "benchmark a logger")
  end

  x.report('Logger#info') do
    logger.info("literally just something")
  end

end

Here are results:

BEFORE:

system ~/work/jruby jruby-9.3 1562% jruby ../snippets/bench_strftime.rb 
Ignoring bcrypt-ruby-3.0.0-java because its extensions are not built. Try: gem pristine bcrypt-ruby --version 3.0.0
jruby 9.3.2.0-SNAPSHOT (2.6.8) 2021-11-15 a482e20f63 OpenJDK 64-Bit Server VM 25.242-b08 on 1.8.0_242-b08 +jit [linux-x86_64]
Warming up --------------------------------------
   Time.now.strftime    32.131k i/100ms
          Logger#add    14.096k i/100ms
         Logger#info    13.551k i/100ms
Calculating -------------------------------------
   Time.now.strftime    290.776k (± 3.0%) i/s -      8.740M in  30.085435s
          Logger#add    148.050k (± 5.1%) i/s -      4.440M in  30.083826s
         Logger#info    144.186k (± 3.3%) i/s -      4.323M in  30.016301s
system ~/work/jruby jruby-9.3 1563% jruby -Xcompile.invokedynamic ../snippets/bench_strftime.rb 
Ignoring bcrypt-ruby-3.0.0-java because its extensions are not built. Try: gem pristine bcrypt-ruby --version 3.0.0
jruby 9.3.2.0-SNAPSHOT (2.6.8) 2021-11-15 a482e20f63 OpenJDK 64-Bit Server VM 25.242-b08 on 1.8.0_242-b08 +indy +jit [linux-x86_64]
Warming up --------------------------------------
   Time.now.strftime    30.297k i/100ms
          Logger#add    16.859k i/100ms
         Logger#info    16.504k i/100ms
Calculating -------------------------------------
   Time.now.strftime    301.153k (± 2.9%) i/s -      9.029M in  30.006521s
          Logger#add    174.820k (± 4.7%) i/s -      5.243M in  30.072275s
         Logger#info    176.989k (± 3.5%) i/s -      5.314M in  30.068419s


AFTER:

jruby ../snippets/bench_strftime.rb 
Ignoring bcrypt-ruby-3.0.0-java because its extensions are not built. Try: gem pristine bcrypt-ruby --version 3.0.0
jruby 9.3.2.0-SNAPSHOT (2.6.8) 2021-11-15 f7df8d0a6d OpenJDK 64-Bit Server VM 25.242-b08 on 1.8.0_242-b08 +jit [linux-x86_64]
Warming up --------------------------------------
   Time.now.strftime   100.407k i/100ms
          Logger#add    23.699k i/100ms
         Logger#info    22.821k i/100ms
Calculating -------------------------------------
   Time.now.strftime    964.240k (± 2.7%) i/s -     28.917M in  30.013077s
          Logger#add    256.086k (± 3.2%) i/s -      7.678M in  30.018332s
         Logger#info    245.748k (± 3.1%) i/s -      7.371M in  30.026685s
system ~/work/jruby new_strftime 1571% jruby -Xcompile.invokedynamic ../snippets/bench_strftime.rb 
Ignoring bcrypt-ruby-3.0.0-java because its extensions are not built. Try: gem pristine bcrypt-ruby --version 3.0.0
jruby 9.3.2.0-SNAPSHOT (2.6.8) 2021-11-15 f7df8d0a6d OpenJDK 64-Bit Server VM 25.242-b08 on 1.8.0_242-b08 +indy +jit [linux-x86_64]
Warming up --------------------------------------
   Time.now.strftime   101.880k i/100ms
          Logger#add    31.154k i/100ms
         Logger#info    29.295k i/100ms
Calculating -------------------------------------
   Time.now.strftime    999.252k (± 2.5%) i/s -     29.953M in  29.993630s
          Logger#add    341.463k (± 3.5%) i/s -     10.250M in  30.072201s
         Logger#info    336.121k (± 2.6%) i/s -     10.077M in  30.003324s
         
MRI26:
mri26 ../snippets/bench_strftime.rb 
ruby 2.6.7p197 (2021-04-05 revision 67941) [x86_64-linux]
Warming up --------------------------------------
   Time.now.strftime    65.008k i/100ms
          Logger#add    13.641k i/100ms
         Logger#info    14.270k i/100ms
Calculating -------------------------------------
   Time.now.strftime    535.604k (± 2.0%) i/s -     16.122M in  30.113361s
          Logger#add    146.675k (± 2.0%) i/s -      4.406M in  30.052030s
         Logger#info    141.943k (± 2.9%) i/s -      4.267M in  30.087328s

enebo added 3 commits November 11, 2021 15:59
@enebo
Redo parts of Time#strftime
ea5503c 
This does two things primarily:
1. Replace the jflex Reader-based lexer with a hand-written one (comes from TR
   with some changes -- very nice they have the exact same tri-license as us
   for that lexer!).
2. Remove making multiple smaller fragments for the result value with a single
   one which is passed around and written to directly.  The main exception to
   this is padding where we cannot write since we don't know how long the value
   is relative to the padding width.

I have not benchmarked this at the smallest level of just calling strftime
directly (which is something I plan on doing soon).  I did take a bench mark
of calling through Logger.  This works thus far improves that benchmark
between 2.2 (default params) and 2.8 times (-Xcompile.invokedynamic).
@enebo
More removal of object creation.
f7df8d0 
For 9.3 less objects the better.  Once we get a proper callsite
cache we will reverse this and make a richer parse which creates
more objects for faster strftime execution.
@enebo
No longer used.
43a06fc
@enebo enebo added this to the JRuby 9.3.2.0 milestone Nov 16, 2021
@enebo enebo merged commit 34b4f88 into jruby:jruby-9.3 Nov 18, 2021
@enebo enebo deleted the new_strftime branch November 18, 2021 15:47
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

core performance

Projects

None yet

Milestone

JRuby 9.3.2.0

Development

Successfully merging this pull request may close these issues.

1 participant

@enebo