Closing a RandomAccessFile sometimes takes exactly 45 seconds

Question

In my program, closing a java.util.RandomAccessFile sometimes takes exactly 45 seconds (well, almost exactly: between 44.998 and 45.003 seconds). The program creates and closes lots of small files. Usually closing the file is very quick (between 0 and 0.1 seconds). If I debug the program, it's stuck in the native method RandomAccessFile.close0.

The same problem also occurs when using FileOutputStream instead of RandomAccessFile (in which case the program is blocked in the native method FileOutputStream.close0).

Has somebody an idea what that could be? Can you reproduce the problem on your system (I can reproduce it only on a Mac, not on Windows XP; I didn't test yet on Linux)?

---

Update 2:

This only seems to happend on Mac OS X. I use JDK 1.6.0_22-b04. It happens on both 32-bit and 64-bit. On Windows XP it doesn't seem to occur.

My test case is:

import java.io.File;
import java.io.RandomAccessFile;
public class TestFileClose {
    public static void main(String... args) throws Exception {
        for (int i = 0; i < 100000; i++) {
            String name = "test" + i;
            RandomAccessFile r = new RandomAccessFile(name, "rw");
            r.write(0);
            long t = System.currentTimeMillis();
            r.close();
            long close = System.currentTimeMillis() - t;
            if (close > 200) {
                System.out.println("closing " + name +
                        " took " + close + " ms!");
            }
            if (i % 2000 == 0) {
                System.out.println("test " + i + "/100000");
            }
            new File(name).delete();
        }
    }
}

Example output on my machine:

test 0/100000
test 2000/100000
test 4000/100000
test 6000/100000
test 8000/100000
test 10000/100000
closing test10030 took 44998 ms!
test 12000/100000
test 14000/100000
test 16000/100000
closing test16930 took 44998 ms!
test 18000/100000
test 20000/100000

Olethea

I don't know why it takes so long, but surely you can move the fileThatTakes45SecondsToClose.close() to another thread no? You could have a unique thread dedicated to closing such files (coming from a queue for example) and instead of calling f.close() you could call queue.put. If you generate more than one such "long to close" file every 45 seconds, you'll need more threads dequeuing obviously. Just a crappy workaround in case you need a quick'n'dirty fix or something ;) – Giamo

"sometimes takes almost exactly 45 seconds"... This is somehow weirdly formulated :) – Giamo

It can depend on how much uncommited data there is. When you close a file it can force the OS to commit all data to disk. – Posology

With 'almost exactly' I mean: between 44999 and 45003 milliseconds. Most of the time it's exactly 45 seconds. I don't use that constant anywhere in my program. It may be some kind of timeout (thread sleep timeout?) that is part of the VM or operating system. – Olethea

I'm seeing this on OS 10.10 and Java 8. It was exactly the same 45 seconds as well, but the difference is I don't run antivirus of any sort. – Arbiter

Answer 1

In my case, it turned out to be McAfee antivirus installed on my machine. I had to install it (company policy)...

The problem also showed up if I disabled the on-access scan.

Olethea

I couldn't reproduce the problem on another Mac, with JDK 5, without virus scanner – Olethea

It is the McAfee. Reason: There is a "Maximum scan time (in seconds)", default 45 seconds. If I set it to 49 seconds, then the delay in my program is 49 seconds. If I set it to 11 the delay is 11. By the way this is even if I disable the on-access scan. – Olethea

Have you tried to exclude the file paths your program is working on from McAfee? Maybe those exclusions are also respected when on-access-scan is disabled ;-) – Quadrivalent

I think I tried that as well, but I'm not sure (too long ago). – Olethea

I just ran into this problem again, with a new version of McAfee. It affects Eclipse: when trying to use SVN, the thread is stuck at at java.io.FileInputStream.open(Native Method) – Olethea

Answer 2

It could be garbage collection activity, triggered by opening/closing a large number of RandomAccessFile objects; there may be nothing magic about 45 seconds - it could just be the time it takes the JVM on your machine to traverse the heap scavenging for objects to free. Having said that, 45 seconds is an awfully long GC pause; One application I worked on recently always suffered full GC's of about 11 seconds.

Try monitoring your program using JConsole or JVisualVM, or when you start the program try adding the following options:

-verbose:gc -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

Then have a look in the gc.log file produced to see what the application stop times are; if you instrument your code to print timestamps you may be able to tie the close() behaviour to specific GC activity:

...
if (close > 200) {
    System.out.println(new Date());
    System.out.println("closing " + name +
                    " took " + close + " ms!");
}
...

If it is GC related, in the gc.log file, you'd be looking for Full garbage collections and/or application stop times at around the timestamps your program outputs files.

Tinkering with the heap settings (-Xmx=... and XX:MaxPermSize=...) may then give you a completely different profile.

On a side note, if it is a temporary file, try using File file = File.createTempFile(prefix, suffix) and pass that into the RandomAccessFile - this may create files in /var/tmp (or whatever its called) on OS X, thus using an in-memory file system instead of a disk-based file system.

Schaumberger

It's definitely not garbage collection. The test program simply doesn't generate enough garbage. Garbage collection doesn't kick in at all (gc.log is empty). Using File.createTempFile() doesn't help (but /var/folders/../.../-Tmp-/ is not an in-memory file system). I tried creating the files on a large ramdisk - it doesn't help either. – Olethea

Only other thing I would suggest using JvisualVM to get a thread dump while the pause occurs and see exactly what the blocked main thread is actually doing. – Schaumberger

As I already wrote in the question, the thread is in RandomAccessFile.close0. The state of the thread is 'running'. – Olethea