indexer fails with 'Too many open files' since 1.1-rc20

[vladak]

Since 1.1-rc20 the indexing of "prepped" (i.e. unpacked with patches applied) version of https://github.com/oracle/solaris-userland gives me:

2018-01-29 09:03:01.638+0100 SEVERE t37 Indexer$1.run: An error occured while updating index
java.nio.file.FileSystemException: /opengrok/data/index/userland-default-prepped: Too many open files
        at sun.nio.fs.UnixException.translateToIOException(UnixException.java:91)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
        at sun.nio.fs.UnixFileSystemProvider.newDirectoryStream(UnixFileSystemProvider.java:427)
        at java.nio.file.Files.newDirectoryStream(Files.java:457)
        at org.apache.lucene.store.FSDirectory.listAll(FSDirectory.java:215)
        at org.apache.lucene.store.FSDirectory.listAll(FSDirectory.java:234)
        at org.apache.lucene.store.FilterDirectory.listAll(FilterDirectory.java:57)
        at org.apache.lucene.index.IndexFileDeleter.refresh(IndexFileDeleter.java:429)
        at org.apache.lucene.index.IndexWriter.rollbackInternalNoCommit(IndexWriter.java:2249)
        at org.apache.lucene.index.IndexWriter.rollbackInternal(IndexWriter.java:2193)
        at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1129)
        at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
        at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:487)
        at org.opensolaris.opengrok.index.Indexer$1.run(Indexer.java:1046)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

Either it became more demanding (I think the default per process limit is 256 fd's) or there is file descriptor leak.

[vladak]

Until this is cleared I am marking this as a bug.

[tulinkry]

it can be connected to the parallelization but the pool of all together processed files is controled with thread count I think. So this would suggest fd leaks. @idodeclare ?

[vladak]

There's no doubt this happened with the transition from rc19 to rc20. I deployed rc20 on Friday around 3 PM and the first indexing that ran at 4 PM contained the exception and almost all indexer runs ever since (15 out of 16).

[vladak]

For completeness, this was per-project indexing (indexpart used in the OpenGrok script). One sample run got some 25k entries for fileRemove and 13k entries for fileAdd. The system has 32 CPUs as reported by psrinfo so the thread pool will have this size I believe.

[vladak]

Today the EMFILE error happened elsewhere (within the same project), interestingly in the index merge operation as mentioned in PR #1936:

2018-01-29 12:58:47.181+0100 WARNING t37 IndexDatabase.indexParallel: 3 failures (0.0%) while parallel-indexing
2018-01-29 12:59:04.750+0100 SEVERE t145 Executor$3.uncaughtException: Uncaught exception in thread Lucene Merge Thread #1 with ID 145: java.nio.file.FileSystemException: /opengrok/data/index/userland-default-prepped/_d5sib_Lucene54_0.dvm: Too many open files
org.apache.lucene.index.MergePolicy$MergeException: java.nio.file.FileSystemException: /opengrok/data/index/userland-default-prepped/_d5sib_Lucene54_0.dvm: Too many open files
        at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:703)
        at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:683)
Caused by: java.nio.file.FileSystemException: /opengrok/data/index/userland-default-prepped/_d5sib_Lucene54_0.dvm: Too many open files
        at sun.nio.fs.UnixException.translateToIOException(UnixException.java:91)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
        at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
        at java.nio.channels.FileChannel.open(FileChannel.java:287)
        at java.nio.channels.FileChannel.open(FileChannel.java:335)
        at org.apache.lucene.store.MMapDirectory.openInput(MMapDirectory.java:238)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:137)
        at org.apache.lucene.codecs.lucene50.Lucene50CompoundFormat.write(Lucene50CompoundFormat.java:93)
        at org.apache.lucene.index.IndexWriter.createCompoundFile(IndexWriter.java:4945)
        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4421)
        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3931)
        at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:624)
        at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:661)

2018-01-29 12:59:04.751+0100 SEVERE t37 Indexer$1.run: An error occured while updating index
java.lang.IllegalStateException: this writer hit an unrecoverable error; cannot commit
        at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:2986)
        at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3244)
        at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1128)
        at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
        at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:487)
        at org.opensolaris.opengrok.index.Indexer$1.run(Indexer.java:1046)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.nio.file.FileSystemException: /opengrok/data/index/userland-default-prepped/_d5sib_Lucene54_0.dvm: Too many open files
        at sun.nio.fs.UnixException.translateToIOException(UnixException.java:91)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
        at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
        at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
        at java.nio.channels.FileChannel.open(FileChannel.java:287)
        at java.nio.channels.FileChannel.open(FileChannel.java:335)
        at org.apache.lucene.store.MMapDirectory.openInput(MMapDirectory.java:238)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99)
        at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:137)
        at org.apache.lucene.codecs.lucene50.Lucene50CompoundFormat.write(Lucene50CompoundFormat.java:93)
        at org.apache.lucene.index.IndexWriter.createCompoundFile(IndexWriter.java:4945)
        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4421)
        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3931)
        at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:624)
        at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:661)

[idodeclare]

So this would suggest fd leaks. (@tulinkry)

File Leak Detector shows no bad usage patterns, and a periodic sampling of lsof -p for a run does not show unbounded growth of active, open descriptors.

Either it became more demanding (I think the default per process limit is 256 fd's) or there is file descriptor leak. (@vladak)

It became more demanding in a couple of ways:

1. indexDown() now accumulates all the work to do before scheduling it, and indexParallel() then tackles it as quickly as it can on the ForkJoinPool. Previously, addFile() would have been called as the Lucene index was traversed, so there was a slight throttling there.

2. Lucene commits still happen on the executor pool not the ForkJoinPool. The executor pool is shrunken in rc20 (previously it was twice the number of processors), and those threads are clients of the ForkJoinPool. The number of threads active is unchanged (i.e. "twice the number of processors" with n for the executor and n for the ForkJoinPool but by design the ForkJoinPool is active nearly the entire time.

ulimit -n of 256 is a bit low for a process that now wants to actively use 32 processors to read and write files in OpenGrok's usage pattern, with six simultaneous descriptors used for each addFile(): two for Ctags pipes, two for REFS and FULL tokenizers' opening read streams, and two for the writeXref() input and output streams.

That leaves only 64 descriptors for all the JARs that the JVM has to keep open plus the Lucene writing threads running for each executor that is targeting a Lucene index.

[vladak]

Okay. The 256 default limit is definitely low. I think we should just try to bump the open files soft (current) limit to hard limit (or maybe also do some funky computation based on the number of on-line CPUs in the system) in the OpenGrok shell script - I am not aware of how to do the setrlimit equivalent in Java (maybe JDK 9 something however I have not done the research).

[vladak]

Plus a note w.r.t. number of CPUs in https://github.com/oracle/opengrok#94-open-file-and-processes-hard-and-soft-limits might be in order.

[vladak]

For reference, ulimit -n 1024 was not enough in my case, using the recommended 10k worked :-)

[vladak]

Looks like 10k is still not enough - it worked previously because I was running the previous test without full "prepping" phase.

[vladak]

Tried 32k (confirmed with dtrace that process.max-file-descriptor was set to 32k upon exece syscall) and even that was not enough. Looks like this should be investigated in more depth.

[tulinkry]

    @Override
    protected void handleInvalidReturn(T t) {
        if (LOGGER.isLoggable(Level.FINE)) {
            LOGGER.log(Level.FINE, "createNew() to handle invalid {0}",
                t.getClass());
        }

        t = objectFactory.createNew();
        executor.submit(new ObjectReturner<T>(objects, t));
    }

Shouldn't this code call also ctags.close for the old instance? That isn't propably the cause here, but just making sure.