Bug #10015: Performance regression in Dir#[]

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 2.3.0 [x86_64-darwin13.0]
• Backport: 2.0.0: UNKNOWN, 2.3: UNKNOWN

[tenderlovemaking (Aaron Patterson)]

r44802 seems to have introduced a performance regression in Dir#[].

Here is the test program:

require 'benchmark'

puts Benchmark.realtime {
  glob = "minitest/*_plugin.rb{,.rb,.bundle}"
  $LOAD_PATH.map { |load_path|
    Dir["#{File.expand_path glob, load_path}"]
  }.flatten.select { |file| File.file? file.untaint }
}

Here is the test time for me:

$ ruby -v test.rb
ruby 2.2.0dev (2014-02-04 trunk 44801) [x86_64-darwin13.0]
0.000341
$ ruby -v test.rb
ruby 2.2.0dev (2014-02-04 trunk 44802) [x86_64-darwin13.0]
0.009333

r44801 seems much faster than r44802.

[nobu (Nobuyoshi Nakada)]

• Description updated (diff)

Yes.
Or use case-sensitive platforms.

[tenderlovemaking (Aaron Patterson)]

@nobu (Nobuyoshi Nakada) this change causes a significant increase in Rails boot time on my system.

My application pays a 120ms price for this change. @hsbt (Hiroshi SHIBATA) will pay 520ms:

http://twitter.com/hsbt/status/486378979138367488

Is there a way we can keep the performance on case-insensitive file systems? If there really is no work-around, then we need to make some changes in RubyGems, bundler, minitest, and Rails before trunk is released because many people will complain about slow boot times. :(

[nobu (Nobuyoshi Nakada)]

It might affect unintentionally.
I'll check the bottleneck.

[tenderlovemaking (Aaron Patterson)]

Thanks nobu, I really appreciate it! If it can't be fixed, I have ideas for avoiding the calls to Dir#[], but it will take time to get merged and released.

[normalperson (Eric Wong)]

Btw, you're already paying significant costs for a case-insensitive FS
(not just Ruby, but things like git, too).

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Closed
• % Done changed from 0 to 100

Applied in changeset r48973.

---

ChangeLog: fix ref of r48972. [Bug #10015]

[nagachika (Tomoyuki Chikanaga)]

note: r48975 was reverted at r48976.

[matthewd (Matthew Draper)]

I don't know what I'm talking about, but this seems like it could use fcntl(2) + F_GETPATH, or getattrlist(2) + ATTR_CMN_NAME.. or something along those lines -- we shouldn't need the loop+fnmatch at all, should we?

[nobu (Nobuyoshi Nakada)]

Thanks, that's it.

[Intrepidd (Adrien Siami)]

I've noticed a significant slowdown of a rails app when using ruby 2.2.1 rather than 2.1.5.

A slow page was running in 16 seconds with 2.2.1 where it was running in less than 3 seconds with 2.1.5

I tested this very simple benchmark :

require 'benchmark'

puts Benchmark.realtime {
  800000.times do
    Dir['/tmp']
  end
}

it runs in 3.1289695860032225 secs with 2.2.1 and 2.403 secs with 2.1.5

Is this issue still present ?

[nobu (Nobuyoshi Nakada)]

• Status changed from Closed to Feedback

Adrien Siami wrote:

A slow page was running in 16 seconds with 2.2.1 where it was running in less than 3 seconds with 2.1.5
it runs in 3.1289695860032225 secs with 2.2.1 and 2.403 secs with 2.1.5

What's your platform and filesystem?
As the former seems pretty bigger than the later, they may be caused by different reasons.

[Intrepidd (Adrien Siami)]

Mac OS X Yosemite with the standard filesystem, I believe HFS+ Insensitive

[mkarklins (Magnuss Karklins)]

Experiencing similar results with Adrien's benchmark:
With ruby-2.2.2: 2.9347980790189467
WIth ruby-2.1.5: 1.848318

OS X Yosemite 10.10.3, Journaled HFS+ file system, case insensitive.

[daniel-rikowski (Daniel Rikowski)]

I ran Adrien's benchmark on Windows:

Besides showing a similar performance regression it looks like Dir[] is dramatically slower on Windows:

ruby-2.2.2p95: 161.4
ruby-2.1.6p336: 31.8

(Windows 8.1, SSD, NTFS)

I guess that is because of the GetFileAttributes vs. stat performance difference.

Using Process Monitor I also noticed that in 2.2.2 the (expensive) GetFileAttributesEx function is performed exactly twice as often as in 2.1.6, so part of the problems seems to be repeated (unnecessary?) calls to GetFileAttributes / stat.
(Judging from runtime behaviour only)

[nobu (Nobuyoshi Nakada)]

• Status changed from Feedback to Closed

Applied in changeset r51106.

---

dir.c: update path type

• dir.c (replace_real_basename): update path type by the target
  attributes if possible, to improve the performance. [Bug #10015]

[l.ferreira (Layon Ferreira)]

• ruby -v changed from ruby 2.2.0dev (2014-02-04 trunk 44802) [x86_64-darwin13.0] to ruby 2.3.0 [x86_64-darwin13.0]
• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN to 2.0.0: UNKNOWN, 2.3: UNKNOWN

The problem seems to persist Mac OS X, although is better on 2.3.0, is still a lot slower than 2.1.x.
I have run the benchmark

require "benchmark"
time = []
5.times do
  result = Benchmark.realtime { 800000.times do Dir['/tmp'] end }
  puts result
  time << result
end
average = time.inject{ |sum, el| sum + el }.to_f / time.size

puts "average of: #{average}"

On this machine:

ProductName:	Mac OS X
ProductVersion:	10.11.4
BuildVersion:	15E65

File System Personality:  Case-sensitive Journaled HFS+
Type (Bundle):            hfs
Name (User Visible):      Mac OS Extended (Case-sensitive, Journaled)
Journal:                  Journal size 40960 KB at offset 0xe8e000
Owners:                   Enabled

On the all releases after 2.1.7 and got this results:

=====================================================
2.1.7: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.1.7
2.86774
3.012784
2.867388
2.873973
3.127474
average of: 2.9498717999999995
=====================================================
2.1.8: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.1.8
3.095918
2.981513
2.998208
3.142286
3.048603
average of: 3.0533056000000003
=====================================================
2.1.9: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.1.9
3.022291
2.983054
2.931454
2.944659
3.051114
average of: 2.9865144
=====================================================
2.2.0: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.2.0
4.985971766000148
5.047520838999844
5.066739754000082
5.005606599001112
5.0079711159996805
average of: 5.022762014800174
=====================================================
2.2.1: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.2.1
5.0500176069999725
5.031266175999917
5.011832148000394
5.043594308999673
5.0333263849988725
average of: 5.034007324999766
=====================================================
2.2.2: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.2.2
4.983856856000784
4.975439867999739
5.112457198998527
4.985339404000115
4.961809472000823
average of: 5.003780559799997
=====================================================
2.2.3: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.2.3
4.832416973000363
4.970395954000196
5.007825999999113
4.891315167000357
4.913950877999014
average of: 4.923180994399809
=====================================================
2.2.4: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.2.4
5.083285558999705
5.07147571600035
5.153286901999309
5.110161799999332
5.192000732999077
average of: 5.122042141999555
=====================================================
2.3.0: benchmarking
=====================================================
Using /Users/admin/.rvm/gems/ruby-2.3.0
3.785227087999374
3.9434133479990123
4.052104171998508
3.844644614999197
3.88892919600039
average of: 3.9028636837992963

[nobu (Nobuyoshi Nakada)]

• Related to Feature #5994: Dir.glob without wildcards returns pattern, not filename added

[nobu (Nobuyoshi Nakada)]

• Related to Bug #13167: Dir.glob is 25x slower since Ruby 2.2 added