rubinius/rubinius — Issue #1481: #readlines significantly slower than MRI
Author: jmstacey
Created: 2012-01-03 05:25:17+00:00
State: open

Calling #readline in Rubinius is significantly slower than MRI. For example, MRI #readlines requires just a tenth of a second or so, but Rubinius #readlines requires over 5 seconds on a file with 500,000 words separated by line break.

### Steps to reproduce

* Prepare a sample source file to read. For example, run the following with Ruby18 or 19. You can't use Rubinius because of a different issue with map which I'll file another bug for. The following will create a source file with 500,000 words consisting of 8 random characters.

```
SOURCE = 'source.txt'

# File.open(SOURCE, 'w') do |f|
# 500000.times do
# f.puts (0...8).map{65.+(rand(25)).chr}.join # http://stackoverflow.com/questions/88311/how-best-to-generate-a-random-string-in-ruby
# end
# end
```

* Run an example of the troubled code:

```
SOURCE = 'source.txt'
file = File.new(SOURCE)
words = file.readlines

p words.size
```

### Timed Benchmarks

#### Ruby 1.9.2p312

```
Jon-Staceys-MacBook-Pro:Desktop jon$ time ruby readline_speed.rb
500000

real	0m0.183s
user	0m0.143s
sys	0m0.034s
```

#### Rubinius 2.0.testing @ 27509446430f53e1c10293339170bf11a5d6db2f

```
Jon-Staceys-MacBook-Pro:Desktop jon$ time rubinius_bin/bin/rbx ./readline_speed.rb
500000

real	0m5.965s
user	0m6.245s
sys	0m0.188s
```

### Profiles

#### Ruby 1.9.2p312 with ruby-prof

```
Jon-Staceys-MacBook-Pro:Desktop jon$ ruby-prof ./readline_speed.rb
500000
Thread ID: 70308421914320
Total: 0.141768

%self total self wait child calls name
99.69 0.14 0.14 0.00 0.00 1 IO#readlines
0.19 0.14 0.00 0.00 0.14 1 Kernel#load
0.05 0.00 0.00 0.00 0.00 1 Kernel#p
0.03 0.14 0.00 0.00 0.14 2 Global#[No method]
0.01 0.00 0.00 0.00 0.00 1 File#initialize
0.01 0.00 0.00 0.00 0.00 1 Kernel#inspect
0.01 0.00 0.00 0.00 0.00 4 Hash#default
0.01 0.00 0.00 0.00 0.00 2 IO#set_encoding
0.00 0.00 0.00 0.00 0.00 1 #new
0.00 0.00 0.00 0.00 0.00 1 Fixnum#to_s
0.00 0.00 0.00 0.00 0.00 1 #allocate
```

#### Rubinius 2.0.testing @ 27509446430f53e1c10293339170bf11a5d6db2f

```
Jon-Staceys-MacBook-Pro:Desktop jon$ time rubinius_bin/bin/rbx ./readline_speed.rb
500000
Thread 1: total running time: 19.015297034s

% cumulative self self total
time seconds seconds calls ms/call ms/call name
------------------------------------------------------------
16.76 6.59 3.19 1015628 0.00 0.01 Rubinius::Channel#as_lock
13.06 13.57 2.48 500001 0.00 0.03 IO#read_to_separator
8.75 17.91 1.66 500001 0.00 0.04 IO#gets
8.54 1.99 1.62 1000002 0.00 0.00 Rubinius::GlobalVariables#[]=
6.03 1.15 1.15 115 9.97 9.97 GC.collect_young
4.89 1.19 0.93 507814 0.00 0.00 IO::InternalBuffer::fill_from<63> {}
4.79 1.13 0.91 507814 0.00 0.00 IO::InternalBuffer::shift<152> {}
4.43 5.17 0.84 507814 0.00 0.01 IO::InternalBuffer#fill_from
3.34 19.01 0.64 1 635.60 19014.62 IO#readlines
3.26 0.72 0.62 500001 0.00 0.00 IO#ensure_open_and_readable
2.91 0.60 0.55 1015628 0.00 0.00 Rubinius::Channel#receive
2.79 0.58 0.53 1015628 0.00 0.00 Rubinius::Channel#<<
2.76 3.59 0.52 507814 0.00 0.01 IO::InternalBuffer#shift
2.66 0.51 0.51 7 72.29 72.29 GC.collect_mature
2.26 0.89 0.43 500005 0.00 0.00 Kernel#StringValue
2.05 0.48 0.39 507814 0.00 0.00 IO::InternalBuffer#find
1.96 0.46 0.37 500006 0.00 0.00 Rubinius::Type.coerce_to
1.65 0.44 0.31 500000 0.00 0.00 Array#<<
0.74 0.16 0.14 507814 0.00 0.00 String.from_chararray
0.69 0.18 0.13 1000002 0.00 0.00 Rubinius::LookupTable#[]=
0.68 0.18 0.13 1000002 0.00 0.00 String#empty?
0.61 0.16 0.12 1015628 0.00 0.00 IO::InternalBuffer#size
0.61 0.16 0.12 1007816 0.00 0.00 IO::InternalBuffer#exhausted?
0.55 0.15 0.10 1000006 0.00 0.00 Rubinius::LookupTable#key?
0.53 0.12 0.10 500000 0.00 0.00 Array#set_index
0.43 0.13 0.08 1000007 0.00 0.00 Rubinius::LookupTable#[]
0.37 0.09 0.07 507815 0.00 0.00 IO::InternalBuffer#empty_to
0.33 0.09 0.06 507814 0.00 0.00 Rubinius::CharArray#locate
0.31 0.08 0.06 500006 0.00 0.00 Rubinius::Type.object_kind_of?
0.31 0.08 0.06 507815 0.00 0.00 IO::InternalBuffer#empty?
0.22 0.04 0.04 8791 0.00 0.00 IO::InternalBuffer#fill
0.21 0.06 0.04 500004 0.00 0.00 Fixnum#&
0.19 0.06 0.04 500011 0.00 0.00 IO#ensure_open
0.18 0.06 0.03 500000 0.00 0.00 Kernel#taint
0.11 0.03 0.02 7813 0.00 0.00 String#<<
0.02 0.00 0.00 8791 0.00 0.00 IO::InternalBuffer#reset!
0.01 0.00 0.00 7813 0.00 0.00 String#append
0.01 0.00 0.00 7813 0.00 0.00 String#modify!
0.00 19.01 0.00 1 0.38 19015.00 Object::__script__<16> {}

39 methods called a total of 20,181,855 times

real	0m20.618s
user	0m20.862s
sys	0m0.301s
```

I tried the 19 syntax, but it was even slower:

```
Jon-Staceys-MacBook-Pro:Desktop jon$ rubinius_bin/bin/rbx -X19 ./readline_speed.rb
500000
Thread 1: total running time: 28.908094775000002s

% cumulative self self total
time seconds seconds calls ms/call ms/call name
------------------------------------------------------------
11.80 6.95 3.41 1015628 0.00 0.01 Rubinius::Channel#as_lock
11.64 19.59 3.37 500001 0.01 0.04 IO::EachReader#read_to_separator
9.01 27.05 2.60 500001 0.01 0.05 IO#each
5.90 2.08 1.71 1000001 0.00 0.00 Rubinius::GlobalVariables#[]=
5.82 1.68 1.68 208 8.09 8.09 GC.collect_young
5.39 3.08 1.56 500002 0.00 0.01 Rubinius::CharArray#dup
4.08 5.00 1.18 507815 0.00 0.01 String#<<
3.55 20.72 1.03 500001 0.00 0.04 IO::EachReader#each
3.50 1.30 1.01 507814 0.00 0.00 IO::InternalBuffer::fill_from<63> {}
3.37 1.21 0.97 507814 0.00 0.00 IO::InternalBuffer::shift<152> {}
2.50 0.72 0.72 9 80.43 80.43 GC.collect_mature
2.40 27.74 0.69 500001 0.00 0.06 IO#gets
2.36 0.79 0.68 500001 0.00 0.00 IO#ensure_open_and_readable
2.32 28.91 0.67 1 670.57 28907.34 IO#readlines
2.16 0.78 0.62 500002 0.00 0.00 Rubinius::CharArray.new
2.14 4.90 0.62 507814 0.00 0.01 IO::InternalBuffer#fill_from
2.03 0.69 0.59 500002 0.00 0.00 Kernel#initialize_copy
1.83 0.58 0.53 1015628 0.00 0.00 Rubinius::Channel#receive
1.82 3.19 0.53 507814 0.00 0.01 IO::InternalBuffer#shift
1.81 3.60 0.52 507815 0.00 0.01 String#modify!
1.71 1.43 0.49 500000 0.00 0.00 IO::gets<391> {}
1.69 0.54 0.49 1015628 0.00 0.00 Rubinius::Channel#<<
1.31 0.46 0.38 507813 0.00 0.00 IO::InternalBuffer#find
1.17 0.46 0.34 500000 0.00 0.00 Array#<<
0.95 0.30 0.27 500001 0.00 0.00 IO::EachReader#initialize
0.66 2.54 0.19 500001 0.00 0.01 Class#allocate
0.54 0.18 0.16 507814 0.00 0.00 String.from_chararray
0.48 0.19 0.14 1015628 0.00 0.00 IO::InternalBuffer#size
0.44 0.15 0.13 500000 0.00 0.00 IO#increment_lineno
0.42 0.17 0.12 1007815 0.00 0.00 IO::InternalBuffer#exhausted?
0.42 0.17 0.12 1000001 0.00 0.00 Rubinius::LookupTable#[]=
0.42 0.14 0.12 507815 0.00 0.00 String#append
0.39 0.16 0.11 1000005 0.00 0.00 Rubinius::LookupTable#key?
0.34 0.12 0.10 500000 0.00 0.00 Array#set_index
0.31 0.14 0.09 1000006 0.00 0.00 Rubinius::LookupTable#[]
0.29 0.11 0.08 507815 0.00 0.00 IO::InternalBuffer#empty_to
0.28 0.13 0.08 1000004 0.00 0.00 Kernel#__class__
0.27 0.12 0.08 1000002 0.00 0.00 Proc.__from_block__
0.27 0.10 0.08 500002 0.00 0.00 Rubinius::CharArray.allocate_sized
0.25 0.10 0.07 500002 0.00 0.00 String#empty?
0.22 0.09 0.06 500001 0.00 0.00 Module#===
0.21 0.08 0.06 507813 0.00 0.00 Rubinius::CharArray#locate
0.21 0.08 0.06 507814 0.00 0.00 IO::InternalBuffer#empty?
0.20 0.08 0.06 507822 0.00 0.00 Kernel#kind_of?
0.17 0.07 0.05 500002 0.00 0.00 BasicObject#initialize

9 methods omitted

54 methods called a total of 29,697,594 times
```

Code used for Rubinius test:

```
require 'profiler'
SOURCE = 'source.txt'

profiler = Rubinius::Profiler::Instrumenter.new

profiler.profile do
file = File.new(SOURCE)
words = file.readlines

p words.size
end
```

### Conclusion

It appears that IO#read_to_separator and/or IO#gets need some performance tuning in 18, and 19 needs some work in other areas.