Project

General

Profile

Actions

Bug #18447

closed

Potential performance regression with String#lines in large strings

Added by ttilberg (Tim Tilberg) about 2 years ago. Updated about 2 years ago.

Status:
Closed
Target version:
-
ruby -v:
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-darwin20]
[ruby-core:106883]

Description

I believe there may be a potential performance regression regarding String#lines worth noting between 3.0.3 and 3.1.0. This came about in this discussion regarding large file parsing performance. We were benchmarking various ways to parse a 10 million row CSV file. Slurping the file took significantly longer than streaming in version 3.1.0, even though the data was able to fit in memory. After further research, we started to feel that there may be something to speak up about here, and I think it's pinned down to String#lines.

I'm running Mac OS Big Sur 11.6.1 on a 13" 2020 MBP with 32 GB ram. Specific Ruby versions are included in the comparison examples below.

The simplest reproduction seems to be:

Ruby 3.0.3: ~1.5 seconds

▶ time ruby -ve '("\n" * 10_000_000).lines'
ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-darwin20]
ruby -ve '("\n" * 10_000_000).lines'  1.38s user 0.39s system 100% cpu 1.756 total

Ruby 3.1.0: ~11.5 seconds

▶ time ruby -ve '("\n" * 10_000_000).lines'
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-darwin20]
ruby -ve '("\n" * 10_000_000).lines'  1.52s user 10.01s system 99% cpu 11.579 total

Some other observations:

An earlier script that I ran ruby-prof against looked like:

puts File.read("sample-data.csv").lines.sum { 1 }
  • It appeared that the time increase stemmed from String#lines, as all other methods had similar time taken between the versions:
 Ruby 3.1.0
  %self      total      self      wait     child     calls  name
 89.93     12.728    12.728     0.000     0.000        1   String#lines
  9.01      1.275     1.275     0.000     0.000        1   Array#sum
  1.05      0.149     0.149     0.000     0.000        1   <Class::IO>#read

  Ruby 3.0.3
   %self      total      self      wait     child     calls  name
 74.91      3.773     3.773     0.000     0.000        1   String#lines
 22.15      1.116     1.116     0.000     0.000        1   Array#sum
  2.93      0.148     0.148     0.000     0.000        1   <Class::IO>#read
  • A similar enumerator without String#lines does not appear to cause this:
▶ time ruby -ve '10_000_000.times.map { nil }'
ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-darwin20]
ruby -ve '10_000_000.times.map { nil }'  0.57s user 0.16s system 102% cpu 0.710 total
▶ time ruby -ve '10_000_000.times.map { nil }'
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-darwin20]
ruby -ve '10_000_000.times.map { nil }'  0.61s user 0.16s system 102% cpu 0.753 total
  • It doesn't seem related to string generation:
▶ time ruby -ve '("\n" * 10_000_000)'
ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-darwin20]
-e:1: warning: possibly useless use of * in void context
ruby -ve '("\n" * 10_000_000)'  0.13s user 0.14s system 107% cpu 0.246 total
▶ time ruby -ve '("\n" * 10_000_000)'
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-darwin20]
-e:1: warning: possibly useless use of * in void context
ruby -ve '("\n" * 10_000_000)'  0.13s user 0.14s system 107% cpu 0.245 total

(Thanks to simpl1g for the discussion on Reddit, and help detecting this potential issue)

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0