persistent severe exception with large repository

[jamesosbourn]

Looking for some help if this is a known issue.

I am running the opengrok container version1.7.31 and seeing a persistent crash working with one of our repositories, the message we are getting from the container log is
24-May-2022 16:24:19.955 SEVERE [ForkJoinPool-4-worker-3] org.opengrok.suggest.SuggesterProjectData.initSearchCountMap Could not create ChronicleMap for field defs in directory /opengrok/data/suggester/repository , most popular completion disabled, if you are using JDK9+ make sure to specify: --add-exports java.base/jdk.internal.ref=ALL-UNNAMED --add-exports java.base/jdk.internal.misc=ALL-UNNAMED --add-exports java.base/sun.nio.ch=ALL-UNNAMED java.lang.IllegalStateException: Shutdown in progress at net.openhft.chronicle.hash.impl.ChronicleHashCloseOnExitHook.add(ChronicleHashCloseOnExitHook.java:39) at net.openhft.chronicle.hash.impl.VanillaChronicleHash.addToOnExitHook(VanillaChronicleHash.java:505) at net.openhft.chronicle.map.ChronicleMapBuilder.prepareMapPublication(ChronicleMapBuilder.java:1778) at net.openhft.chronicle.map.ChronicleMapBuilder.createWithFile(ChronicleMapBuilder.java:1753) at net.openhft.chronicle.map.ChronicleMapBuilder.createPersistedTo(ChronicleMapBuilder.java:1593) at net.openhft.chronicle.map.ChronicleMapBuilder.createOrRecoverPersistedTo(ChronicleMapBuilder.java:1614) at net.openhft.chronicle.map.ChronicleMapBuilder.createOrRecoverPersistedTo(ChronicleMapBuilder.java:1604) at net.openhft.chronicle.map.ChronicleMapBuilder.createOrRecoverPersistedTo(ChronicleMapBuilder.java:1598) at org.opengrok.suggest.popular.impl.chronicle.ChronicleMapAdapter.<init>(ChronicleMapAdapter.java:55) at org.opengrok.suggest.SuggesterProjectData.initSearchCountMap(SuggesterProjectData.java:314) at org.opengrok.suggest.SuggesterProjectData.rebuild(SuggesterProjectData.java:241) at org.opengrok.suggest.Suggester.lambda$getRebuildRunnable$2(Suggester.java:352) at java.base/java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1407) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)

I have tried adding the arguments as suggested which seems to have made no difference.

This is a large repo and takes some time to complete its index, although the server never runs for long enough to complete this.

Can anyone offer any suggestions as to the cause of this exception and how I could prevent it from taking place. Should I raise this as an issue?

Many Thanks

[vladak]

SuggesterProjectData.initSearchCountMap() is called either from Suggester init() (webapp startup) or rebuild() (scheduled or after reindex). Either this is a problem in the programming (for the record: the exception bubbles via ChronicleMapAdapter constructor and both init() and rebuild() acquire write lock of associated SuggesterProjectData object when calling initSearchCountMap()) or environmental issue. You mention this is a large repository. Have you done any tuning of the web app as described on https://github.com/oracle/opengrok/wiki/Tuning-for-large-code-bases ?

[vladak]

The reason I ask about the tuning is that sometimes out-of-memory situations turn into weird exceptions, not necessarily the OutOfMemoryError. There is a docker-compose configuration on https://github.com/OpenGrok/opengrok-monitoring-docker that sets up Grafana instance for web app monitoring. Given that you are using the Docker container, it might be helpful to see what is going on.

[jamesosbourn]

Thank you, I had increases the JVM memory, I will look again to see if there are any other improvements that I can apply to the container.

Thank you for the monitor information, I will take a look and see if this helps to narrow anything down.

[vladak]

Looking into the code once again, this starts in the web application by creating new instance of the ChronicleMapAdapter class:

opengrok/suggester/src/main/java/org/opengrok/suggest/SuggesterProjectData.java

Lines 312 to 329 in 1a2ed5c

	ChronicleMapAdapter m;
	try {
	m = new ChronicleMapAdapter(field, conf.getAverageKeySize(), conf.getEntries(), f);
	} catch (IllegalArgumentException e) {
	logger.log(Level.SEVERE, "Could not create ChronicleMap for field " + field + " in directory "
	+ suggesterDir + " due to invalid key size ("
	+ conf.getAverageKeySize() + ") or number of entries: (" + conf.getEntries() + "):", e);
	return;
	} catch (Throwable t) {
	logger.log(Level.SEVERE,
	"Could not create ChronicleMap for field " + field + " in directory "
	+ suggesterDir + " , most popular completion disabled, if you are using "
	+ "JDK9+ make sure to specify: "
	+ "--add-exports java.base/jdk.internal.ref=ALL-UNNAMED "
	+ "--add-exports java.base/jdk.internal.misc=ALL-UNNAMED "
	+ "--add-exports java.base/sun.nio.ch=ALL-UNNAMED", t);
	return;
	}

The ChronicleMapAdapter class comes from Chronicle-Map. The IllegalStateException exception is thrown in the ChronicleHashCloseOnExitHook class (also in Chronicle-Map) which is used in the process of creating the ChronicleMapAdapter instance. The exception originates from the add() method:

https://github.com/OpenHFT/Chronicle-Map/blob/ab814b7122d29d3055331b81653e354a134343e9/src/main/java/net/openhft/chronicle/hash/impl/ChronicleHashCloseOnExitHook.java#L37-L41

    static synchronized void add(VanillaChronicleHash<?, ?, ?, ?> hash) {
        if (maps == null)
            throw new IllegalStateException("Shutdown in progress");
        maps.put(hash.identity, order++);
    }

The maps is private static member of ChronicleHashCloseOnExitHook. The only place in that class where it is being set to null is in the closeAll() method. The closeAll() method is setup in the static block:

https://github.com/OpenHFT/Chronicle-Map/blob/ab814b7122d29d3055331b81653e354a134343e9/src/main/java/net/openhft/chronicle/hash/impl/ChronicleHashCloseOnExitHook.java#L30-L32

    static {
        PriorityHook.add(80, ChronicleHashCloseOnExitHook::closeAll);
    }

The PriorityHook comes from another Java library, Chronicle-Core and is meant to provide hooks that get executed on shutdown: https://github.com/OpenHFT/Chronicle-Core/blob/ce0a4d435e64b91b52124f688c84d20da83b5d04/src/main/java/net/openhft/chronicle/core/shutdown/PriorityHook.java#L5-L8

Which shutdown is that ? The addAndGet() method that is called from the add() calls this https://github.com/OpenHFT/Chronicle-Core/blob/ce0a4d435e64b91b52124f688c84d20da83b5d04/src/main/java/net/openhft/chronicle/core/shutdown/PriorityHook.java#L42

            Runtime.getRuntime().addShutdownHook(registeredHook.shutdownThread());

so this is in fact JVM shutdown.

To sum it up: Suggester is trying to rebuild data. To do so, it is creating new instance of the ChronicleMapAdapter class. In the process, JVM shuts down. The Chronicle-Map class used in the Suggester uses a hook to clean the internal state on JVM shutdown.

What has probably happened is that the JVM shutdown hook was installed (it is in the static block), then JVM initiated the shutdown which resulted in the internal (static) map of ChronicleHashCloseOnExitHook to null, then the construction of ChronicleHashCloseOnExitHook class tried to add a entry to the internal map. The map was null which caused the exception.

Anyhow, there is bigger problem than the exception - JVM is shutting down for some reason. There is not enough data in the question to see the reason.

The Java doc mentioned above states:

The Java virtual machine shuts down in response to two kinds of events:

• The program exits normally, when the last non-daemon thread exits or when the exit (equivalently, System.exit) method is invoked, or
• The virtual machine is terminated in response to a user interrupt, such as typing ^C, or a system-wide event, such as user logoff or system shutdown.

It may be that the size of the repository somehow caused the JVM shutdown. Also, given that this is reported when using Docker container, it reminds me of #3650

[vladak]

Maybe it would be prudent to catch the IllegalStateException in SuggesterProjectData#initSearchCountMap() however that would not fix the underlying problem, just improve the messaging a little bit.

[jamesosbourn]

Thank you for providing the additional code analysis, #3650 certainly looks like it could be related. I may try running the older version commented and see if the problem persists to confirm if this is the case. If I can get the additional logging working I will see if this captures anything helpful.