Possibility to prevent truffle compilation depending on time or degree of completion

[Eisenbert]

We have about 100 engines with shared js code running cyclically in a production environment. Warmup is finished a couple of hours after startup. Problem: About 5 days after initial startup most of the engines are reentering the warmup state (compilation trace prints mostly "opt done"), which endangers production. We can't find any external trigger (same processed and patterns are running all the time). Compilation trace logs showing the same messages like at initial startup.

1. Is there any possibility / hack to prevent warmup / compilation after e.g. 24h runtime?
2. We like to learn more about warmup triggers: Except code changes or the evaluation of yet uncompiled logic - Is there any other trigger for compilation threads, e.g. time or system performance based?

[chumer]

I have two possible explanations for this behavior.

1. The code gets garbage collected between spawned contexts.

The polyglot API uses the Source reference to determine the lifetime of the code cache if no context is alive that uses that code.

For example[1]:

try (Engine engine = Engine.create()) {
    Source source = Source.create("js", "21 + 21");
    try (Context context = Context.newBuilder()
        .engine(engine)
        .build()) {
            int v = context.eval(source).asInt();
            assert v == 42;
    }
    // code cache cannot get collected here since source is on stack
    try (Context context = Context.newBuilder()
        .engine(engine)
        .build()) {
            int v = context.eval(source).asInt();
            assert v == 42;
    }
}

Here as long as the source object is referenced, the code associated with the source in the engine will not be collected between spawned contexts of an engine.

If we slightly change that example to:

try (Engine engine = Engine.create()) {
    try (Context context = Context.newBuilder()
        .engine(engine)
        .build()) {
            Source source = Source.create("js", "21 + 21");
            int v = context.eval(source).asInt();
            assert v == 42;
    }
    // code cache may get collected by the GC here
    try (Context context = Context.newBuilder()
        .engine(engine)
        .build()) {
             Source source = Source.create("js", "21 + 21");
            int v = context.eval(source).asInt();
            assert v == 42;
    }
}

Here the GC may decide to collect the code cache and ASTs between created contexts.

Luckily the solution to such a problem is pretty simple. You just need to keep a strong reference to the Source object around as long as you want the code cache to be alive. This will keep the code cache alive in all engines where this source was evaluated at least once.

Since you run a long-running application, the code associated with your sources probably gets collected during an idle time where no context using the code is alive.

2. HotSpot purges the code cache because it is getting too full.

Whether this is the case, you can find out with:-Xlog:codecache.

(1) is very likely explaining your problem.

We currently lack a diagnostic option to detect (1). But having a trace option for this would be a good idea. We will add that.

Lastly, out of curiosity, why do you spawn 100 engines and not just one?
Are they all running separate workloads in the same process?

[Eisenbert]

Currently, you compile the guest code 100 times for each engine.

Each of the 100 engines are evaluating different code, a different Source object. So as far that I understand there is no code to share between engines. But we do utilize the code sharing between contexts by using the same engine per Source object each time the evaluation is triggered. So with this setup, could there still be a benefit by evaluating different Source objects by the same engine? I did a quick test today but could not see significant difference regarding performance.

We see the compilation logs from each engine, they show how sooner or later each compilation comes to an end. Typically after some hours. Then the application is running for 5 days without further compilation logs. Then as described most of the engines startet the repeated compilation at the same time. If HotSpot can not purge the ASTs because they are in constant use, why else could we see this behavior? We monitor memory usage and GC activity via VisualVM, we can't see any increase that could trigger an purge after days.

[chumer]

It must be HotSpot kicking out our compilations, then.
Can you give -Xlog:codecache a go?

If you can also share the log output of engine.TraceTransferToInterpreter, engine.TraceAssumptions, engine.TraceCompilationDetails and engine.CompilationStatistics as well, that might be helpful too.

What version are you using exactly? What does your command line look like? Any special VM options?

BTW.: We have several internal flags to observe compilations described here:
https://github.com/oracle/graal/blob/master/truffle/docs/Optimizing.md#observing-compilations

[Eisenbert]

We run our application with GraalVM 22.3 and Java 17, contained by Apache Tomcat 9.0.69, without special VM options.

After the incident we temporarily run the application with compilation=false on the affected system. However, we will set up a test environment with your suggested log options.

Regardless of the search for the cause, would it be imaginable to have the possibility to shutdown compilation some time after startup? As you said, if the ASTs are safe, the application would run with good performance but also some safety that prevents / limits sudden increase in CPU usage.

[chumer]

No we do not have a feature like this. I am not sure yet whether ASTs are stable in you case. I need to see some logs. If compilations repeat with the same id after a while then ASTs are probably stable.

However, we will set up a test environment with your suggested log options.

Thanks!

[Eisenbert]

Took us a while to get the chance to run tests on the customers environment again. We startet the application with the following options:

-Xlog:codecache=Debug:file=compilationTrace\codecache.log
-Dpolyglot.log.file=compilationTrace\compilation.log
-Dpolyglot.engine.TraceTransferToInterpreter=true
-Dpolyglot.engine.TraceAssumptions=true
-Dpolyglot.engine.TraceCompilationDetails=true
-Dpolyglot.engine.CompilationStatistics=true

The application is still running, but since we caught the warmup loop, we extracted the logs before they get even bigger. Logs can be downloaded here. Can you get something out of it?