Why does `File.write` slow down sometimes?

Question

This is my code:

start = Time.now
File.write('/tmp/a.txt', 'Hello, world!')
puts "Saved in #{Time.now - start}"

In some cases, I see this in the log:

Saved in 0.001
Saved in 0.002
Saved in 0.245
Saved in 0.002

Why is there occasionally such a spike? What could that be? I'm not using flock anywhere. My suspicion is that some library has overridden the method File.write() and added some locking/synchronization there. Is it possible?

Update: It seems that Dir.new(), which regularly gets access to the directory, blocks access to it.

Answer 1

It seems that Dir.new() in another place of the app completely locks the entire directory and doesn't allow File.write() to work fast. This is the test to reproduce the problem (using threads gem):

require 'tmpdir'
require 'threads'
Dir.mktmpdir do |dir|
  file = File.join(dir, 'hey.txt')
  Thread.start do
    loop do
      Dir.new(dir)
    end
  end
  Threads.new(100).assert do
    start = Time.now
    File.open(file, 'w+') do |f|
      f.write('test')
    end
    puts("Saved in #{Time.now - start}")
    sleep 1
  end
end

This one will work slow. However, if you replace Dir.new with this, everything moves fast again:

`ls #{dir}`.split(' ')

Ruby bug? I don't know.

BTW, the same is true for Dir.glob() - it's also very slow.

Answer 2

I am not sure, but I would be very surprise those spoke of time does not come from Ruby but from your underlying operating system (Linux I guess).

I wrote a similar script than yours in Python, I could watch same difference than you.

I watch it's systemcall using:

sudo strace -T -e trace=open,close,write -p <my_process_pid>

And at least for the open syscall, I could also watch some call taking 100 time long than others.