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

Answer 1

It could be McAfee antivirus installed on my machine. I had to install it... But the problem also shows up if I disable the on-access scan.

To only way to verify it's not antivirus is somebody repeat the test on his machine (without antivirus) and get the same problem I guess.

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.