Bug #20587
closeddir.c calls blocking filesystem APIs/system calls while holding the GVL
Added by ivoanjo (Ivo Anjo) 5 months ago. Updated 4 months ago.
Description
Hey! I work for Datadog on the Ruby profiler part of the datadog
(previously ddtrace
) gem.
While I was investigating https://bugs.ruby-lang.org/issues/20586, I spotted that there's a number of cases where, in dir.c
, blocking system calls are being made (e.g. readdir()
, , ... see comments for more detailed list...) without releasing the GVL.opendir()
This means that if they block for a long time (as happens in the gcsfuse example in https://bugs.ruby-lang.org/issues/20586 ), the Ruby VM will just be blocked and not make any progress.
The combination of not releasing the GVL + slow system calls actually makes the issue in https://bugs.ruby-lang.org/issues/20586 more likely to happen with the Datadog profiler, although even if the code releases the GVL the underlying issue could still happen, and this is why I decided to file this bug separately.
Files
Updated by ivoanjo (Ivo Anjo) 5 months ago
- Subject changed from dir.c calls blocking system calls while holding the GVL to dir.c calls blocking filesystem APIs/system calls while holding the GVL
Updated by jeremyevans0 (Jeremy Evans) 4 months ago
@ivoanjo (Ivo Anjo) Can you be specific about which places this affects? I examined all opendir
calls in dir.c
:
- Called in
nogvl_opendir
- Called in
opendir_without_gvl
when VM is not initialized - Called in
nogvl_opendir_at
- Called in
nogvl_dir_empty_p
Tracing those function calls, if the VM is initialized, it appears that all calls use the IO_WITHOUT_GVL
macro to release the GVL around the call.
Updated by ivoanjo (Ivo Anjo) 4 months ago ยท Edited
jeremyevans0 (Jeremy Evans) wrote in #note-2:
@ivoanjo (Ivo Anjo) Can you be specific about which places this affects? I examined all
opendir
calls indir.c
:
- Called in
nogvl_opendir
- Called in
opendir_without_gvl
when VM is not initialized- Called in
nogvl_opendir_at
- Called in
nogvl_dir_empty_p
Tracing those function calls, if the VM is initialized, it appears that all calls use the
IO_WITHOUT_GVL
macro to release the GVL around the call.
Hey Jeremy, thanks for taking a look at this!
You are right -- I think I was overeager in including opendir
on the list. I'll update my original description to correct for this.
Here's my attempt at a more specific report of blocking calls while holding the GVL in dir.c
(I've omitted cases where the GVL is released):
-
fdopendir
-> called bydir_s_for_fd
-
readdir
-> called bydir_read
,dir_each_entry
,glob_helper
,glob_getent
-
chdir
-> called bydir_chdir0
(Although this one is somewhat weird already so perhaps it being blocking is not the weirdest part?) -
fchdir
-> called bydir_fchdir
(same aschrdir
) -
chroot
-> called bydir_s_chroot
-
lstat
-> called bydo_lstat
-
stat
-> called bydo_stat
-
fstatat
-> called bydo_stat
/do_lstat
-
fgetattrlist
-> called byneed_normalization
,is_case_sensitive
-
getattrlist
-> called byis_case_sensitive
,replace_real_basename
,rb_dir_s_empty_p
,need_normalization
,dir_initialize
-
getpwnam
-> called bydir_s_home
Updated by jeremyevans0 (Jeremy Evans) 4 months ago
@ivoanjo (Ivo Anjo) Thank you for your analysis. I worked on a pull request that handles most of the system calls you listed: https://github.com/ruby/ruby/pull/11147
It doesn't handle getattrlist
or fgetattrlist
, because I wasn't able to test with those (they appear to be Mac OS only).
Could you test that pull request and see if it addresses the issues you were seeing? If so and it fixes the issues, I can work on getattrlist
and fgetattrlist
and rely on CI to check that it works on Mac OS. I can also work on getpwnam
and other system calls in process.c
and ext/etc/etc.c
that are mentioned in the pull request.
Updated by ivoanjo (Ivo Anjo) 4 months ago
Nice!
I've tried the PR and it actually makes the issue in https://bugs.ruby-lang.org/issues/20586#How-to-reproduce disappear in my tests.
(It does not fully solve the issue, but what made it trigger a lot more often was that the readdir
call blocked with the GVL held, since the Datadog profiler tries to interrupt only threads holding the GVL. With the GVL released, this can only happen in the remote chance the profiler decided to interrupt the thread just as it was preparing to call readdir
).
I also decided recover an old experiment I had to try to trigger some of these problems using a custom "adversarial" FUSE filesystem. Here's my script to trigger the syscalls:
$liveness = true
$looping = false
liveness_check = Thread.new do
print "Is Ruby alive? (Should print every 0.1s) "
while $liveness do
print '.'
before_sleep = Time.now
$looping = true
sleep 0.1
delay = Time.now - before_sleep
puts "\n[HICCUP -- VM was probably blocked for #{delay - 0.1}s!]" if delay > 0.5
end
end
Thread.pass while !$looping
directory = ARGV.last
result = case ARGV.first.to_sym
when :readdir
d = Dir.new(directory)
print "(Opened!)"
d.children
when :fdopendir
# This one doesn't seem to work as a reproducer, the opendir for d0 seems to get reused by libc and that one already
# released the GVL
raise 'Broken?'
d0 = Dir.new(directory)
d1 = Dir.for_fd(d0.fileno)
d1.to_s
when :chdir
Dir.chdir(directory) { }
when :fchdir
d = Dir.new(directory)
print "(Opened!)"
d.chdir { }
when :chroot
begin
Dir.chroot(directory)
rescue => e
e
end
when :lstat
Dir.glob("#{directory}/*", File::FNM_DOTMATCH)
when :stat
Dir.glob("#{directory}/", File::FNM_DOTMATCH)
when :fstatat
raise 'Did not figure out this one?'
else
raise "Unknown syscall #{ARGV.first}"
end
$liveness = false
liveness_check.join
puts "\n#{result.inspect}"
...and here's how it looks before your PR:
$ ./miniruby repro.rb readdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ........................................(Opened!)
[HICCUP -- VM was probably blocked for 1.9858527449999999s!]
["hello"]
$ ./miniruby repro.rb chdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) .
[HICCUP -- VM was probably blocked for 1.9008266639999998s!]
nil
$ ./miniruby repro.rb fchdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ........................................(Opened!)
[HICCUP -- VM was probably blocked for 1.987699879s!]
nil
$ ./miniruby repro.rb chroot /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) .
[HICCUP -- VM was probably blocked for 1.9008783179999997s!]
#<Errno::EPERM: Operation not permitted @ dir_s_chroot - /home/ivo.anjo/tmp-hello-mount-deleteme>
$ ./miniruby repro.rb lstat /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ........................................
[HICCUP -- VM was probably blocked for 3.9877458889999997s!]
["/home/ivo.anjo/tmp-hello-mount-deleteme/.", "/home/ivo.anjo/tmp-hello-mount-deleteme/hello"]
$ ./miniruby repro.rb stat /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) .
[HICCUP -- VM was probably blocked for 1.9009780909999998s!]
["/home/ivo.anjo/tmp-hello-mount-deleteme/"]
...here's how it looks after your PR:
$ ./miniruby repro.rb readdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ........................................(Opened!)....................
["hello"]
$ ./miniruby repro.rb chdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ....................
nil
$ ./miniruby repro.rb fchdir /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ........................................(Opened!)....................
nil
$ ./miniruby repro.rb chroot /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ....................
#<Errno::EPERM: Operation not permitted @ dir_s_chroot - /home/ivo.anjo/tmp-hello-mount-deleteme>
$ ./miniruby repro.rb lstat /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ................................................................................
["/home/ivo.anjo/tmp-hello-mount-deleteme/.", "/home/ivo.anjo/tmp-hello-mount-deleteme/hello"]
$ ./miniruby repro.rb stat /home/ivo.anjo/tmp-hello-mount-deleteme
Is Ruby alive? (Should print every 0.1s) ....................
["/home/ivo.anjo/tmp-hello-mount-deleteme/"]
I'm also attaching the "adversarial" FUSE filesystem -- I basically added a bunch of sleeps to https://github.com/libfuse/libfuse/blob/master/example/hello.c (my version attached), built the examples and mounted the filesystem.
Hopefully this helps, and thanks again for picking this one up :))
Updated by jeremyevans0 (Jeremy Evans) 4 months ago
I merged https://github.com/ruby/ruby/pull/11147 . I'll work on getattrlist
and fgetattrlist
next, and then I'll work on similar GVL-releasing work in process.c
and ext/ext/etc.c
.
Updated by jeremyevans0 (Jeremy Evans) 4 months ago
I submitted https://github.com/ruby/ruby/pull/11176 for the getattrlist
and fgetattrlist
changes.
Updated by jeremyevans (Jeremy Evans) 4 months ago
- Status changed from Open to Closed
Applied in changeset git|dabb6c49aa561ba8a222e8b9baf2cbf2e1a1608d.
Release GVL around {,f}getattrlist calls in dir.c
Fixes [Bug #20587]