File Descriptors not closing

[JatinderSingh]

I found this bug while using vanilla chronicle v3.0.1 as well as 3.1.1, I have a long running process and after rolling over Chronicle is still keeping reference of old file descriptors and disk becomes full (df shows 100% disk usage and lsof shows old files being referred from the process). The restart of process brings disk usage back to normal. Can some one point me in a direction how to fix this issue?

[lburgazzoli]

Can you pleas add some more details? e.g. the rolling configuration (daily, hourly, etc) , the number of threads, etc

Some enhancement on the resource management have been added to the latest snapshot but there may be something still not taken into account

[JatinderSingh]

Number of threads that will log excerpt are 8 on a 4 core Centos VM running java 7 update 45. Vanilla Chronicle config is below:-

config.cycleFormat("yyyy-MM-dd/HH"); config.cycleLength(60_60_1000); //every hour config.dataBlockSize(1073741824); //1Gb config.defaultMessageSize(5000); //500 bytes config.entriesPerCycle(4000000); //4 mil per file

Kindly let me know if you face any difficulty in reproducing the bug.

[RobAustin]

jira issue raised https://higherfrequencytrading.atlassian.net/browse/CHRON-47

[JatinderSingh]

Thanks for the update.

[lburgazzoli]

I'm gonna check this in the coming days however in the latest snapshot you can tune the number of entries kept by the cache via VanillaChronicleConfig.dataCacheCapacity(...) so if you set it to the number of threads, unused file descriptors should be closed upon roll

[JatinderSingh]

I tried calling close0() on files which were not in current cycle but still their references somehow remained in jvm.

[JatinderSingh]

Thanks for the update @lburgazzoli Setting the datacache capacity to a lower value will not work as i can find more than 100 file descriptors open when max is being set to 32 in defaults.

[lburgazzoli]

For my information, did you test with the latest snapshot (3.1.2-SNAPSHOT) or the release (3.1.1) ? Because the latest snapshot should also improve resources management

[JatinderSingh]

I tested with 3.1.1. Will test with 3.1.2-SNAPSHOT soon.

[JatinderSingh]

I tested with current master but still find references to all files written by chronicle as open.

[JatinderSingh]

Hey I attached an agent to vm to identify all file open/close calls. File close for chronicle files is happening in constructor of RandomAccessFile, Below is stacktrace for the same:-

Closed chronicle/2014-06-27/06/data-25401-0 by thread:7 on Fri Jun 27 06:00:00 UTC 2014 at java.io.RandomAccessFile.(RandomAccessFile.java:242) at net.openhft.lang.io.VanillaMappedFile.fileChannel(VanillaMappedFile.java:93) at net.openhft.lang.io.VanillaMappedFile.(VanillaMappedFile.java:47) at net.openhft.lang.io.VanillaMappedFile.(VanillaMappedFile.java:40) at net.openhft.lang.io.VanillaMappedFile.readWriteBytes(VanillaMappedFile.java:142) at net.openhft.lang.io.VanillaMappedCache.put(VanillaMappedCache.java:89) at net.openhft.chronicle.VanillaDataCache.dataFor(VanillaDataCache.java:93) at net.openhft.chronicle.VanillaDataCache.dataForLast(VanillaDataCache.java:158)

Close calls are not initiated by channel.close()

[peter-lawrey]

Are you sure the line is not

Line 242: open(name, imode);

which looks like an open to me.

Are you saying you can see the files being opened but not closed?

On 27 June 2014 12:16, JatinderSingh notifications@github.com wrote:

Hey I attached an agent to vm to identify all file open/close calls. File close for chronicle files is happening in constructor of RandomAccessFile, Below is stacktrace for the same:-

Closed chronicle/2014-06-27/06/data-25401-0 by thread:7 on Fri Jun 27 06:00:00 UTC 2014 at java.io.RandomAccessFile.(RandomAccessFile.java:242) at net.openhft.lang.io.VanillaMappedFile.fileChannel(VanillaMappedFile.java:93) at net.openhft.lang.io.VanillaMappedFile.(VanillaMappedFile.java:47) at net.openhft.lang.io.VanillaMappedFile.(VanillaMappedFile.java:40) at net.openhft.lang.io.VanillaMappedFile.readWriteBytes(VanillaMappedFile.java:142) at net.openhft.lang.io.VanillaMappedCache.put(VanillaMappedCache.java:89) at net.openhft.chronicle.VanillaDataCache.dataFor(VanillaDataCache.java:93) at net.openhft.chronicle.VanillaDataCache.dataForLast(VanillaDataCache.java:158)

Close calls are not initiated by channel.close()

— Reply to this email directly or view it on GitHub https://github.com/OpenHFT/Java-Chronicle/issues/75#issuecomment-47328360 .

[lburgazzoli]

VanillaMappedFile.readWriteBytes returns a reference counted buffer which closes the file channel when it has not more references:

    @Override
    protected synchronized void cleanup() {
        if(!this.unmapped) {
            Cleaner cl = ((DirectBuffer)this.buffer).cleaner();
            if (cl != null) {
                cl.clean();
            }

            try {
                if (this.channel != null && this.channel.isOpen()) {
                    this.channel.close();
                }
            } catch(IOException e) {
                throw new AssertionError(e);
            }

            this.unmapped = true;
        }

        super.cleanup();
    }

When a new buffer is added to the cache, its refCount is 2: 1 for the cache, and 1 for the code using it then when the buffer is removed from the cache its refCount is decreased so if there are no more references, channel.close() is invoked.

I've wrote a very simple test:

    VanillaMappedBytes vmb = VanillaMappedFile.readWriteBytes(new File("/tmp/test"),128,-1);

    System.out.println("1> " + vmb.refCount());
    vmb.release();
    System.out.println("2> " + vmb.refCount());

Before vmb.release() I see the file held by the process

$ lsof -p 3579 | grep test
java    3579   lb  mem    REG      252,1      128 1569907 /tmp/test
java    3579   lb   35u   REG      252,1      128 1569907 /tmp/test

Then after release, the file is not more owned by the process:

$ lsof -p 3579 | grep test
$

I suspect there is a problem when the chronicle rolls. I have to complete another task then I will work on it.

[JatinderSingh]

Yes That was a Reference of stack of file close using file-leak-detector-1.7. Even i was shocked as it is a call to open a RandomAccessFile.

I have list of timestamps when chronicle file was opened and closed. Most of them remain in open state.

grep Opened chron-files | wc -l 682 grep Closed chron-files | wc -l 101

Inactive files have been physically deleted by another process but as file descriptors are open in chronicle disk cannot be reclaimed.

[JatinderSingh]

Hey i recompiled Java-Lang also from current master. The dangling descriptors are of files ending with 0 like index-0, data--0 etc other files which do not end with 0 are getting closed. I hope this info helps to pin point the bug.

[lburgazzoli]

@JatinderSingh I've created the following simple single-threaded test that rolls every second with data cache set to 2:

    @Test
    public void testResourcesCleanup3() throws Exception {
        final String baseDir = getTestPath();
        assertNotNull(baseDir);

        System.out.println("BaseDir is :" + baseDir);
        System.out.println("PID     is :" + getPID());

        final VanillaChronicleConfig config = new VanillaChronicleConfig();
        config.entriesPerCycle(1L << 20);
        config.cycleLength(1000, false);
        config.cycleFormat("yyyyMMddHHmmss");
        config.indexBlockSize(64);
        config.dataBlockSize(64);
        config.dataCacheCapacity(2);
        config.indexCacheCapacity(2);

        final VanillaChronicle chronicle = new VanillaChronicle(baseDir, config);
        chronicle.clear();

        try {
            final ExcerptAppender appender = chronicle.createAppender();
            for (int counter = 0; counter < 5; counter++) {
                appender.startExcerpt(20);
                appender.writeInt(counter);
                appender.finish();

                try {
                    Thread.sleep(5000);
                } catch(InterruptedException e) {
                }
            }

            appender.close();

            chronicle.checkCounts(1,1);
        } catch(Exception e) {
            e.printStackTrace();
        } finally {
            chronicle.close();
            chronicle.clear();

            assertFalse(new File(baseDir).exists());
        }
    }

According to lsof the file descriptor is properly released on roll:

 luca@neptune T  ] # while true; do echo "samplig"; lsof -p 6577 | grep vc-testResourcesCleanup3; sleep 5; done
samplig
java    6577 luca  txt      REG               1,3        64 26376693 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200259/index-0
java    6577 luca  txt      REG               1,3        64 26376692 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200259/data-8130560-0
java    6577 luca   61u     REG               1,3        64 26376693 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200259/index-0
java    6577 luca   64u     REG               1,3        64 26376692 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200259/data-8130560-0
samplig
java    6577 luca  txt      REG               1,3        64 26376695 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200304/data-8130560-0
java    6577 luca  txt      REG               1,3        64 26376696 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200304/index-0
java    6577 luca   63u     REG               1,3        64 26376695 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200304/data-8130560-0
java    6577 luca   64u     REG               1,3        64 26376696 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200304/index-0
samplig
java    6577 luca  txt      REG               1,3        64 26376700 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200309/index-0
java    6577 luca  txt      REG               1,3        64 26376699 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200309/data-8130560-0
java    6577 luca   61u     REG               1,3        64 26376699 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200309/data-8130560-0
java    6577 luca   63u     REG               1,3        64 26376700 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200309/index-0
samplig
java    6577 luca  txt      REG               1,3        64 26376702 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200314/data-8130560-0
java    6577 luca  txt      REG               1,3        64 26376703 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200314/index-0
java    6577 luca   61u     REG               1,3        64 26376703 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200314/index-0
java    6577 luca   64u     REG               1,3        64 26376702 /private/var/folders/6f/c4rrgpb90k78nlwj3s5gcm640000gn/T/vc-testResourcesCleanup3/20140703200314/data-8130560-0

Did you tweak dataCacheCapacity/indexCacheCapacity according to your need?

[lburgazzoli]

However in a MT environment index-0 is not released, I'm on it

[JatinderSingh]

I tweaked those params trying to keep data files around 1G. Will try to use this config for chronicle and update you tomorrow.

[lburgazzoli]

I've created a new branch HFT-CHRON-47 on my repo (https://github.com/lburgazzoli/Java-Chronicle/tree/HFT-CHRON-47) that should address this issue. Please note that dataCacheCapacity and indexCacheCapacity are the key for proper resource management(default value is 32)

final VanillaChronicleConfig config = new VanillaChronicleConfig();
config.entriesPerCycle(1L << 20);
config.cycleLength(1000, false);
config.cycleFormat("yyyyMMddHHmmss");
config.indexBlockSize(64);
config.dataBlockSize(64);
config.dataCacheCapacity(nbThreads + 1);
config.indexCacheCapacity(2);

An example is testResourcesCleanup3 on https://github.com/lburgazzoli/Java-Chronicle/blob/HFT-CHRON-47/chronicle/src/test/java/net/openhft/chronicle/VanillaChronicleResourcesTest.java

[JatinderSingh]

This branch your suggestion of default datablocksize has improved resource cleanup a lot but still loads of files are remaining in lsof (mainly because of smaller block size). I have a dump containing all files opened and closed by chronicle with thread id and timestamp which i can share with you. I am unable to attach the same here.

[lburgazzoli]

Well, block size were not supposed to help you as the main trick is to properly set index and cache size .

Please send the dump to luca.burgazzoli at higherfrequencytrading.com

[JatinderSingh]

Have sent you dump of open/closed files...

[brasslock]

I have yet to investigate further, but I think something I encountered in #78 might be a possible cause of file leaks... Under memory pressure, Appenders can be removed from the appenderCache because the WeakReference holding the appender instance is cleared by GC. In this circumstance, it does not appear as if the removed appender is being closed.

In our process we appear to be getting file handle leaks as well, although (so far?) it has not been bad enough to cause failures.

Ross

[lburgazzoli]

Yes this can happen and I'm working on a solution. However this can only happen if you do not hold a reference to the appender/tailer and you never call close.

[brasslock]

My current pattern for using VanillaChronicle has been:

            final ExcerptAppender appender = chronicle.createAppender();
            appender.startExcerpt(bytes.length);
            appender.write(bytes); // ...
            appender.finish();

regardless of whether the thread lives for a long time (since the VanillaChronicle caches the appender).

Should I instead be using a ThreadLocal in my own code to hold the appender instance? or what is the recommended usage pattern?

(Is this a question better asked on the forum?)

Thanks, Ross

[peter-lawrey]

You shouldn't need a thread local appender as this is what VanillaChronicle does already. On 14/07/2014 7:10 AM, "Ross Black" notifications@github.com wrote:

My current pattern for using VanillaChronicle has been:

        final ExcerptAppender appender = chronicle.createAppender();
        appender.startExcerpt(bytes.length);
        appender.write(bytes); // ...
        appender.finish();

regardless of whether the thread lives for a long time (since the VanillaChronicle caches the appender).

Should I instead be using a ThreadLocal in my own code to hold the appender instance? or what is the recommended usage pattern?

(Is this a question better asked on the forum?)

Thanks, Ross

— Reply to this email directly or view it on GitHub https://github.com/OpenHFT/Java-Chronicle/issues/75#issuecomment-48868244 .

[brasslock]

So with that pattern (which seems correct), it is expected to never hold a reference to the appender and hence never call close?

[lburgazzoli]

In a fire-and-forget scenario the pattern should be

            final ExcerptAppender appender = chronicle.createAppender();
            appender.startExcerpt(...);
            ...
            appender.finish();
            appender.close();

So that if the underlying buffers are removed from the cache (data and or index), the resources are cleaned up (you need to use this branch https://github.com/lburgazzoli/Java-Chronicle/tree/HFT-CHRON-47). This patter has a little cost as startExcerpt need to do some work.

If your know your thread will last for some time you can call close at the end of your thread.

[peter-lawrey]

You shouldn't wait for the gc to call close for you as you don't know how long that will be unless you have no choice. On 14/07/2014 7:19 AM, "Ross Black" notifications@github.com wrote:

So with that pattern (which seems correct), it is expected to never hold a reference to the appender and hence never call close?

— Reply to this email directly or view it on GitHub https://github.com/OpenHFT/Java-Chronicle/issues/75#issuecomment-48868596 .

[brasslock]

OK, Thanks.

[JatinderSingh]

Hey when i tried final ExcerptAppender appender = chronicle.createAppender(); appender.startExcerpt(...); ... appender.finish(); appender.close();

using above pattern gave me drastically higher system utilization as compared to one where i did not use appender.close() in branch https://github.com/lburgazzoli/Java-Chronicle/tree/HFT-CHRON-47.

[lburgazzoli]

What do you mean by system utilization? disk, cpu? I guess cpu

[JatinderSingh]

I used utilization as aggregated by top. Mostly it was CPU.

[lburgazzoli]

The patch has been included in Chronicle 3.2.1 (http://search.maven.org/#artifactdetails|net.openhft|chronicle|3.2.1|bundle)

Please close the issue if it solves your problem.

[JatinderSingh]

Will Test release and close the issue.

[JatinderSingh]

Chronicle V 3.2.1 solves the issue.