Unable to complete simple Base64 benchmark #2968

Open
vanjabucic opened this Issue Mar 5, 2014 · 3 comments

Projects

None yet

4 participants

@vanjabucic

Was using a small script to compare ruby20, ruby21, and rubinius (CPU/GC) performance when I noticed that rubinius is not able to complete a single loop without getting stuck. It comest to a crawl, 100% CPU usage with very little useful work done (possibly stuck doing GC operations?).
Code pasted below: ---------------

require 'benchmark'
require 'base64'

REPS = 1000
POOL = ('A'..'z').to_a
def noise(max)
  (0...max).map { POOL[rand(42)] }.join
end

puts 'making dataset'
small  = noise(10_000)
medium = noise(100_000)
large  = noise(1_000_000)

0.upto(4) {
  puts '--------------------------------------------------------------------'
  puts 'encode64'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.encode64(small) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.encode64(medium) } }
    b.report("large: ") { 0.upto(REPS) { Base64.encode64(large) } }
  end

  small_encoded  = Base64.encode64(small)
  medium_encoded = Base64.encode64(medium)
  large_encoded  = Base64.encode64(large)

  puts '--------------------------------------------------------------------'
  puts 'decode64'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.decode64(small_encoded) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.decode64(medium_encoded) } }
    b.report("large: ") { 0.upto(REPS) { Base64.decode64(large_encoded) } }
  end

  puts '--------------------------------------------------------------------'
  puts 'strict_encode'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.strict_encode64(small) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.strict_encode64(medium) } }
    b.report("large: ") { 0.upto(REPS) { Base64.strict_encode64(large) } }
  end

  small_encoded  = Base64.strict_encode64(small)
  medium_encoded = Base64.strict_encode64(medium)
  large_encoded  = Base64.strict_encode64(large)

  puts '--------------------------------------------------------------------'
  puts 'strict_decode'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.strict_decode64(small_encoded) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.strict_decode64(medium_encoded) } }
    b.report("large: ") { 0.upto(REPS) { Base64.strict_decode64(large_encoded) } }
  end

  puts '--------------------------------------------------------------------'
  puts 'urlsafe_encode'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.urlsafe_encode64(small) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.urlsafe_encode64(medium) } }
    b.report("large: ") { 0.upto(REPS) { Base64.urlsafe_encode64(large) } }
  end

  small_encoded  = Base64.urlsafe_encode64(small)
  medium_encoded = Base64.urlsafe_encode64(medium)
  large_encoded  = Base64.urlsafe_encode64(large)

  puts '--------------------------------------------------------------------'
  puts 'urlsafe_decode'
  Benchmark.bm do |b|
    b.report("small: ") { 0.upto(REPS) { Base64.urlsafe_decode64(small_encoded) } }
    b.report("medium: ") { 0.upto(REPS) { Base64.urlsafe_decode64(medium_encoded) } }
    b.report("large: ") { 0.upto(REPS) { Base64.urlsafe_decode64(large_encoded) } }
  end
  puts '--------------------------------------------------------------------'
 }
@chuckremes
Member

I suggest running this is -Xagent.start and then connecting to the running instance from another shell via ‘rbx console’. See instructions on how to do this here:

http://rubini.us/doc/en/tools/memory-analysis/

Then you can get all thread backtraces. Type “help” at the console prompt and take a look. Post that information here as part of the ticket.

On Mar 5, 2014, at 1:00 PM, vanjabucic notifications@github.com wrote:

Was using a small script to compare ruby20, ruby21, and rubinius (CPU/GC) performance when I noticed that rubinius is not able to complete a single loop without getting stuck. It comest to a crawl, 100% CPU usage with very little useful work done (possibly stuck doing GC operations?).
Code pasted below: ---------------

require 'benchmark'
require 'base64'

REPS = 1000
POOL = ('A'..'z').to_a
def noise(max)
(0...max).map { POOL[rand(42)] }.join
end

puts 'making dataset'
small = noise(10_000)
medium = noise(100_000)
large = noise(1_000_000)

0.upto(4) {
puts '--------------------------------------------------------------------'
puts 'encode64'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.encode64(small) } }
b.report("medium: ") { 0.upto(REPS) { Base64.encode64(medium) } }
b.report("large: ") { 0.upto(REPS) { Base64.encode64(large) } }
end

small_encoded = Base64.encode64(small)
medium_encoded = Base64.encode64(medium)
large_encoded = Base64.encode64(large)

puts '--------------------------------------------------------------------'
puts 'decode64'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.decode64(small_encoded) } }
b.report("medium: ") { 0.upto(REPS) { Base64.decode64(medium_encoded) } }
b.report("large: ") { 0.upto(REPS) { Base64.decode64(large_encoded) } }
end

puts '--------------------------------------------------------------------'
puts 'strict_encode'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.strict_encode64(small) } }
b.report("medium: ") { 0.upto(REPS) { Base64.strict_encode64(medium) } }
b.report("large: ") { 0.upto(REPS) { Base64.strict_encode64(large) } }
end

small_encoded = Base64.strict_encode64(small)
medium_encoded = Base64.strict_encode64(medium)
large_encoded = Base64.strict_encode64(large)

puts '--------------------------------------------------------------------'
puts 'strict_decode'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.strict_decode64(small_encoded) } }
b.report("medium: ") { 0.upto(REPS) { Base64.strict_decode64(medium_encoded) } }
b.report("large: ") { 0.upto(REPS) { Base64.strict_decode64(large_encoded) } }
end

puts '--------------------------------------------------------------------'
puts 'urlsafe_encode'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.urlsafe_encode64(small) } }
b.report("medium: ") { 0.upto(REPS) { Base64.urlsafe_encode64(medium) } }
b.report("large: ") { 0.upto(REPS) { Base64.urlsafe_encode64(large) } }
end

small_encoded = Base64.urlsafe_encode64(small)
medium_encoded = Base64.urlsafe_encode64(medium)
large_encoded = Base64.urlsafe_encode64(large)

puts '--------------------------------------------------------------------'
puts 'urlsafe_decode'
Benchmark.bm do |b|
b.report("small: ") { 0.upto(REPS) { Base64.urlsafe_decode64(small_encoded) } }
b.report("medium: ") { 0.upto(REPS) { Base64.urlsafe_decode64(medium_encoded) } }
b.report("large: ") { 0.upto(REPS) { Base64.urlsafe_decode64(large_encoded) } }
end
puts '--------------------------------------------------------------------'
}


Reply to this email directly or view it on GitHub.

@dbussink
Member
dbussink commented Mar 5, 2014

Took a quick look and this seems mostly about String#tr performance because that is used in urlsafe_encode64.

@vanjabucic

Updating with a backtrace:

console> backtrace
Thread 0:
0x7fff536334f0: String#each_char in kernel/common/string.rb:312 (+56 jit)
0x7fff53633c10: String#tr_trans in kernel/common/string.rb:0 (+285)
0x7fff536344c0: String#tr! in kernel/common/string.rb:635 (+10)
0x7fff53634cc0: String#tr in kernel/common/string.rb:631 (+15)
0x7fff536354d0: Base64.urlsafe_encode64 in /usr/local/rubinius/2.2/gems/gems/rubysl-base64-2.0.0/lib/rubysl/base64/base64.rb:81 (+16)
0x7fff53635cc0: __block__ in /Users/vanjab/RubymineProjects/RubyBase_SVN/scratch/vanjab/serialization/encode_benchmark.rb:63 (+8)
0x7fff536365c0: Integer#upto in kernel/common/integer.rb:209 (+34)
0x7fff53636e50: __block__ in /Users/vanjab/RubymineProjects/RubyBase_SVN/scratch/vanjab/serialization/encode_benchmark.rb:63 (+8)
0x7fff53637760: Benchmark.measure in /usr/local/rubinius/2.2/gems/gems/rubysl-benchmark-2.0.1/lib/rubysl/benchmark/benchmark.rb:279 (+37)
0x7fff53637fb0: Benchmark::Report#report in /usr/local/rubinius/2.2/gems/gems/rubysl-benchmark-2.0.1/lib/rubysl/benchmark/benchmark.rb:361 (+52)
0x7fff53638870: __block__ in /Users/vanjab/RubymineProjects/RubyBase_SVN/scratch/vanjab/serialization/encode_benchmark.rb:63 (+21)
0x7fff53639190: Benchmark.benchmark in /usr/local/rubinius/2.2/gems/gems/rubysl-benchmark-2.0.1/lib/rubysl/benchmark/benchmark.rb:172 (+149)
0x7fff536399f0: Benchmark.bm in /usr/local/rubinius/2.2/gems/gems/rubysl-benchmark-2.0.1/lib/rubysl/benchmark/benchmark.rb:204 (+39)
0x7fff5363a2c0: __block__ in /Users/vanjab/RubymineProjects/RubyBase_SVN/scratch/vanjab/serialization/encode_benchmark.rb:61 (+195)
0x7fff5363ac00: Integer#upto in kernel/common/integer.rb:209 (+34)
0x7fff5363b490: Object#__script__ in /Users/vanjab/RubymineProjects/RubyBase_SVN/scratch/vanjab/serialization/encode_benchmark.rb:18 (+117)
0x7fff5363bdc0: Rubinius::CodeLoader#load_script in kernel/delta/code_loader.rb:66 (+52)
0x7fff5363c750: Rubinius::CodeLoader.load_script in kernel/delta/code_loader.rb:152 (+40)
0x7fff5363d0e0: Rubinius::Loader#script in kernel/loader.rb:649 (+214)
0x7fff5363da80: Rubinius::Loader#main in kernel/loader.rb:831 (+77)

Thread 1:
Thread 2:
Thread 3:
Thread 4:
Thread 5:
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment