Dir[] slow, hot & cold

[LillianZ]

Even when hot (confirmed hot by Thermometer), Dir[] is almost 4x slower than MRI. Code snippet below was run in this directory, and MRI and Truffleruby output below.

	Cold	Hot
MRI	0.003747s	304.699 ips
Truffleruby	0.122712s	82.758 ips

require 'benchmark'
require 'benchmark/ips'
puts  Benchmark.measure {Dir["src/main/java/**/*"]}

Benchmark.ips do |x|
  x.config(:time => 5, :warmup => 10)
  x.report('Dir#[]') {Dir["src/main/java/**/*"]}
end

puts Benchmark.measure {Dir["src/main/java/**/*"]}

ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-darwin19]
  0.000946   0.002803   0.003749 (  0.003747)
Warming up --------------------------------------
          Dir#[]    31.000  i/100ms
Calculating -------------------------------------
          Dir#[]    304.699  (± 5.6%) i/s -      1.519k in   5.000986s
  0.001018   0.002456   0.003474 (  0.003476)

truffleruby (Shopify) 20.3.0-dev-151cfcb0, like ruby 2.6.6, GraalVM CE JVM [x86_64-darwin]
  0.733384   0.017023   0.750407 (  0.122712)
Warming up --------------------------------------
          Dir#[]     6.000  i/100ms
Calculating -------------------------------------
          Dir#[]     82.758  (± 7.3%) i/s -    414.000  in   5.027133s
  0.047519   0.009553   0.057072 (  0.015891)

[wildmaples]

There's a middleware on SFR using Dir#[]. The microbenchmark shows that it's ~1.6x slower than MRI.

[eregon]

I can reproduce the difference locally on Linux:

ruby 2.7.3p183 (2021-04-05 revision 6847ee089d) [x86_64-linux]
  0.000000   0.000860   0.000860 (  0.000862)
Warming up --------------------------------------
              Dir#[]   126.000  i/100ms
Calculating -------------------------------------
              Dir#[]      1.288k (± 1.1%) i/s -      6.552k in   5.089233s
  0.000000   0.000807   0.000807 (  0.000809)


truffleruby 21.2.0-dev-a28e3da1, like ruby 2.7.3, GraalVM CE Native [x86_64-linux]
  0.374936   0.016222   0.391158 (  0.063269)
Warming up --------------------------------------
              Dir#[]    20.000  i/100ms
Calculating -------------------------------------
              Dir#[]    206.467  (±16.5%) i/s -      1.000k in   5.017073s
  0.031048   0.002053   0.033101 (  0.004951)

[eregon]

$ ruby --cpusampler --cpusampler.Mode=roots bench_dir_glob.rb
----------------------------------------------------------------------------------------------------------------------------------------------------
Sampling Histogram. Recorded 12653 samples with period 1ms.
  Self Time: Time spent on the top of the stack.
  Total Time: Time spent somewhere on the stack.
  Opt %: Percent of time spent in compiled and therefore non-interpreted code.
----------------------------------------------------------------------------------------------------------------------------------------------------
 Thread: Thread[main,5,main]
 Name                                                         |      Total Time     |  Opt % ||       Self Time     |  Opt % | Location             
----------------------------------------------------------------------------------------------------------------------------------------------------
 Truffle::POSIX.truffleposix_readdir                          |       4584ms  36.2% |  99.4% ||       2405ms  19.0% |  99.3% | resource:/truffleruby/core/posix.rb~134-168:3839-5070 
 Truffle::POSIX.truffleposix_lstat_mode                       |       3111ms  24.6% |  99.5% ||       2386ms  18.9% |  99.5% | resource:/truffleruby/core/posix.rb~134-168:3839-5070 
 FFI::Pointer#get_string                                      |       1682ms  13.3% |  99.8% ||       1679ms  13.3% |  99.8% | resource:/truffleruby/core/truffle/ffi/pointer.rb~144-146:4775-4899 
 String#<=>                                                   |       1532ms  12.1% |  99.5% ||       1532ms  12.1% |  99.5% | resource:/truffleruby/core/string.rb~1525-1547:40019-40731 
 Truffle::POSIX.opendir                                       |        665ms   5.3% |  97.7% ||        607ms   4.8% |  98.5% | resource:/truffleruby/core/posix.rb~134-168:3839-5070 
 block (2 levels) in POSIX.attach_function_eagerly            |        578ms   4.6% |  98.6% ||        565ms   4.5% |  98.8% | resource:/truffleruby/core/posix.rb~135-138:3897-4131 
 Array#bottom_up_merge                                        |       1056ms   8.3% |  98.2% ||        466ms   3.7% |  96.8% | resource:/truffleruby/core/array.rb~1365-1384:31295-31780 
 Symbol#==                                                    |        359ms   2.8% | 100.0% ||        358ms   2.8% | 100.0% | (core)~1:0 
 Dir::Glob::RecursiveDirectories#call                         |      10310ms  81.5% |  96.4% ||        344ms   2.7% |  74.7% | resource:/truffleruby/core/dir_glob.rb~93-127:3143-4310 
 Truffle::POSIX.closedir                                      |        361ms   2.9% |  99.4% ||        340ms   2.7% |  99.4% | resource:/truffleruby/core/posix.rb~134-168:3839-5070 
 FFI::Pointer#read_string_to_null                             |       1943ms  15.4% |  99.8% ||        259ms   2.0% |  99.6% | resource:/truffleruby/core/truffle/ffi/pointer_extra.rb~85-87:3357-3456 
 Truffle::POSIX.truffleposix_stat_mode                        |        257ms   2.0% |  98.1% ||        211ms   1.7% |  97.6% | resource:/truffleruby/core/posix.rb~134-168:3839-5070 
 Array#isort!                                                 |       1150ms   9.1% |  99.2% ||        208ms   1.6% |  97.6% | resource:/truffleruby/core/array.rb~1452-1477:33316-33746 
 Dir::Glob::EntryMatch#call                                   |       3775ms  29.8% |  99.2% ||        172ms   1.4% |  98.3% | resource:/truffleruby/core/dir_glob.rb~215-231:6804-7322 
 File.fnmatch                                                 |        322ms   2.5% |  98.8% ||        121ms   1.0% |  98.3% | resource:/truffleruby/core/file.rb~668-681:21612-22069 
 Dir#read                                                     |       4714ms  37.3% |  99.3% ||         99ms   0.8% |  90.9% | resource:/truffleruby/core/dir.rb~99-114:3110-3527 
 Array#each                                                   |        614ms   4.9% |  99.3% ||         93ms   0.7% | 100.0% | (core)~1:0 
 Kernel#StringValue                                           |        106ms   0.8% | 100.0% ||         84ms   0.7% | 100.0% | resource:/truffleruby/core/kernel.rb~170-172:5816-5898 
 String#include?                                              |        176ms   1.4% | 100.0% ||         74ms   0.6% | 100.0% | resource:/truffleruby/core/string.rb~150-152:4643-4748 
 Dir::Glob.path_join                                          |         69ms   0.5% |  97.1% ||         69ms   0.5% |  97.1% | resource:/truffleruby/core/dir_glob.rb~337-345:10022-10221 
 Array#<<                                                     |         55ms   0.4% |  98.2% ||         55ms   0.4% |  98.2% | (core)~1:0 
 Dir::Glob::Match#match?                                      |        374ms   3.0% |  98.9% ||         54ms   0.4% | 100.0% | resource:/truffleruby/core/dir_glob.rb~185-187:6066-6136 
 Dir::Glob::Node#path_join                                    |        137ms   1.1% |  89.8% ||         45ms   0.4% |  75.6% | resource:/truffleruby/core/dir_glob.rb~51-53:2110-2203 
 Dir#initialize_internal                                      |        706ms   5.6% |  97.9% ||         33ms   0.3% |  90.9% | resource:/truffleruby/core/dir.rb~48-63:2166-2582 
 String#encoding                                              |         27ms   0.2% | 100.0% ||         27ms   0.2% | 100.0% | resource:/truffleruby/core/string.rb~1521-1523:39949-40016 
 Dir::Glob::Node#separator                                    |         23ms   0.2% |  95.7% ||         23ms   0.2% |  95.7% | resource:/truffleruby/core/dir_glob.rb~47-49:2053-2107 
 Truffle::Type.rb_convert_type                                |         22ms   0.2% | 100.0% ||         22ms   0.2% | 100.0% | resource:/truffleruby/core/type.rb~263-273:9204-9581 
 String#force_encoding                                        |         21ms   0.2% | 100.0% ||         21ms   0.2% | 100.0% | (core)~1:0 
 Dir#close                                                    |        382ms   3.0% |  98.7% ||         19ms   0.2% |  89.5% | resource:/truffleruby/core/dir.rb~116-122:3530-3664 

Quite some time spent in native calls, which is expected. Maybe we can group some of them (e.g., do we need Truffle::POSIX.truffleposix_lstat_mode?)

Something else we see in the profile is the cost of sorting the returned entries.

[chrisseaton]

I'm wondering if it really makes the same native calls as MRI - like I can imagine it accidentally being written to stat each component of every path each time, rather than stating a component once and then stating its children once etc. Or something else like that.

[eregon]

We could potentially compare with strace for system calls.
One way to avoid the extra lstat (seems used to find out if a given entry is a directory) would be to use readdir's d_type field, but:

               unsigned char  d_type;      /* Type of file; not supported
                                              by all filesystem types */

              Currently, only some filesystems (among them: Btrfs, ext2, ext3, and ext4) have full support for returning the file type in d_type.  All applications must properly handle a return of DT_UNKNOWN.

So we'd need a fallback to lstat. And know whether that works on macOS too.

[bjfish]

@eregon I suspect d_type works on macOS after seeing some straces from MRI. There appears to be 2 extra lstat in TruffleRuby for every file path currently. I believe this is due to not using d_type.

We also appear to have some duplicated calls to POSIX.opendir on some directories. On mac I captured this CPU sample:

 Name                                                              |      Total Time     |  Opt % ||       Self Time     |  Opt % | Location             
---------------------------------------------------------------------------------------------------------------------------------------------------------
 Truffle::POSIX.opendir                                            |       4327ms  43.8% |  96.4% ||       4285ms  43.4% |  96.8% | src/main/ruby/truffleruby/core/posix.rb~134-168:3839-5070 
 Truffle::POSIX.truffleposix_readdir                               |       2040ms  20.7% |  89.7% ||       1605ms  16.3% |  92.0% | src/main/ruby/truffleruby/core/posix.rb~134-168:3839-5070 
 Truffle::POSIX.truffleposix_lstat_mode                            |       1198ms  12.1% |  90.2% ||       1083ms  11.0% |  93.4% | src/main/ruby/truffleruby/core/posix.rb~134-168:3839-5070 
 Truffle::POSIX.closedir                                           |        473ms   4.8% |  91.8% ||        468ms   4.7% |  92.1% | src/main/ruby/truffleruby/core/posix.rb~134-168:3839-5070 
 

[eregon]

sample from strace output:
CRuby:

openat(AT_FDCWD, "src/main/java/org/truffleruby/interop", O_RDONLY|O_CLOEXEC|O_DIRECTORY) = 8
fstat(8, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl(8, F_GETFL)                       = 0x18000 (flags O_RDONLY|O_LARGEFILE|O_DIRECTORY)
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
getdents64(8, 0xd9e450 /* 19 entries */, 32768) = 880
getdents64(8, 0xd9e450 /* 0 entries */, 32768) = 0
close(8)                                = 0

TruffleRuby:

openat(AT_FDCWD, "src/main/java/org/truffleruby/interop", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 7
fstat(7, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(7, 0x559ac7ad1780 /* 19 entries */, 32768) = 880
lstat("src/main/java/org/truffleruby/interop/InteropNodes.java", {st_mode=S_IFREG|0644, st_size=117806, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/BoxedValue.java", {st_mode=S_IFREG|0644, st_size=1187, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/TranslateInteropExceptionNode.java", {st_mode=S_IFREG|0644, st_size=6267, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/IsStringLikeNode.java", {st_mode=S_IFREG|0644, st_size=1589, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/RubyToForeignArgumentsNode.java", {st_mode=S_IFREG|0644, st_size=2043, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/SymbolToByteOrderNode.java", {st_mode=S_IFREG|0644, st_size=1793, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/InteropManager.java", {st_mode=S_IFREG|0644, st_size=1093, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/PolyglotNodes.java", {st_mode=S_IFREG|0644, st_size=7073, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/TranslateInteropRubyExceptionNode.java", {st_mode=S_IFREG|0644, st_size=9477, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/ToJavaStringWithDefaultNode.java", {st_mode=S_IFREG|0644, st_size=1404, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/ToJavaStringNode.java", {st_mode=S_IFREG|0644, st_size=4141, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/ForeignToRubyArgumentsNode.java", {st_mode=S_IFREG|0644, st_size=2418, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/ForeignToRubyNode.java", {st_mode=S_IFREG|0644, st_size=1588, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/FromJavaStringNode.java", {st_mode=S_IFREG|0644, st_size=2235, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/ProxyForeignObject.java", {st_mode=S_IFREG|0644, st_size=3029, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/OutgoingForeignCallNode.java", {st_mode=S_IFREG|0644, st_size=26132, ...}) = 0
lstat("src/main/java/org/truffleruby/interop/RubyToForeignNode.java", {st_mode=S_IFREG|0644, st_size=1368, ...}) = 0
getdents64(7, 0x559ac7ad1780 /* 0 entries */, 32768) = 0
close(7)                                = 0

So CRuby seems to use the trick I described in #2092 (comment), and that's probably a significant gain.

Probably we need some extra private method to do something like Dir#read + return whether it's a directory/the file type.
We could also add a variant for efficiency which also automatically skip . and .. where that's the correct semantics.

[aardvark179]

I've taken a bit of a look at this, and we'll need an alternative way to read directory entries (we currently return the name from libtruffleposix when we really want the directory entry structs. I think we're also opening and reading every directory twice, once to handle the recursive ** part of the pattern, and then a second time to perform the leaf name matching * part.

The cases where we do need to stat entries can probably be sped up a little by using fstataf and passing in the fd of the directory, but we'd need to test that to see how much of a difference that makes.

[chrisseaton]

Going between Ruby and POSIX calls means that they're doing a lot of overhead to allocate structures and function calls just to read fields and things. Maybe a richer function in libtruffleposix could do most of the globbing work staying in C?

[aardvark179]

Possibly, but I'm not sure I want to be the one to write that implementation. :-) I'll have a think about what we could do to divide the work up in a smarter way, and I'll try benchmarking fstatat and see if that would make a difference, I think it might be sensible to switch anyway because we likely have some horrible race conditions if anybody changes current working directory in another thread while we're in the middle of globbing.

[chrisseaton]

Is this a case where we can copy and paste from MRI?

[aardvark179]

Have you looked at the MRI implementation? Also, they definitely suffer from the race condition problem (because although they use fstatat they use AT_FDCWD as the base, so they are always working relative to the process's current working directory). Maybe the don't release the GVL during a glob and therefore know Ruby code can't change the cwd? I haven't checked that but yet.

[chrisseaton]

This seems to be the inner-most function, for reference.

https://github.com/ruby/ruby/blob/86b4c2fc3fb0ec815e212628f6708c5b777f523e/dir.c#L2255-L2599

Quite a lot of helpers around this.