[GR-55996] Implement source cache statistics for Truffle.

PullRequest: graal/20958

Author: jchalou

sdk/CHANGELOG.md

@@ -15,6 +15,8 @@ This changelog summarizes major changes between GraalVM SDK versions. The main f
 * GR-22699(EE-only) Added the ability to spawn `Engine` or `Context` isolated in a separate process by setting `Context.Builder.option("engine.IsolateMode", "external").`.
 * GR-64087 Removed the dependency on `org.graalvm.truffle:truffle-enterprise` from all language and tool POM artifacts. As a result, the community Maven artifacts (those with an artifact ID ending in `-community`) are now identical to their corresponding non-community artifacts. Consequently, all community language and tool POM artifacts have been deprecated. The only exception is `org.graalvm.truffle:java-community` vs. `org.graalvm.truffle:java`, which differ in the bundled Java runtime. Embedders using auxiliary engine caching, polyglot isolates, a isolated/untrusted sandbox policy, or the sandbox resource limits must now explicitly add the `org.graalvm.truffle:truffle-enterprise` Maven artifact to the classpath or module path.
 * GR-66339 Truffle now checks that its multi-release classes ([JEP 238](https://openjdk.org/jeps/238)) are loaded correctly and provides a descriptive error message if they are not.
+* GR-55996 Added the options `engine.SourceCacheStatistics` and `engine.SourceCacheStatisticDetails` to print polyglot source cache statistics on engine close.
+
 
 ## Version 24.2.0
 * GR-54905 When using Truffle NFI with the Panama backend, native access must now be granted to the Truffle module instead of the NFI Panama module. Use the `--enable-native-access=org.graalvm.truffle` Java command line option to enable the native access for the NFI Panama backend.

sdk/src/org.graalvm.polyglot/src/org/graalvm/polyglot/impl/AbstractPolyglotImpl.java

@@ -668,6 +668,8 @@ protected AbstractSourceDispatch(AbstractPolyglotImpl engineImpl) {
 
         public abstract URI getURI(Object impl);
 
+        public abstract URI getOriginalURI(Object impl);
+
         public abstract Reader getReader(Object impl);
 
         public abstract InputStream getInputStream(Object impl);

truffle/docs/Options.md

@@ -50,6 +50,8 @@ They are useful to users and language and tool implementers.
 ```shell
 - `--engine.PreinitializeContexts` : Preinitialize language contexts for given languages.
 - `--engine.RelaxStaticObjectSafetyChecks` : On property accesses, the Static Object Model does not perform shape checks and uses unsafe casts
+- `--engine.SourceCacheStatisticDetails` : Print source cache statistics for an engine when the engine is closed. With the details enabled, statistics for all individual sources are printed.
+- `--engine.SourceCacheStatistics` : Print source cache statistics for an engine when the engine is closed.
 - `--engine.SynchronousThreadLocalActionMaxWait=[0, inf)` : How long to wait for other threads to reach a synchronous ThreadLocalAction before cancelling it, in seconds. 0 means no limit.
 - `--engine.SynchronousThreadLocalActionPrintStackTraces` : Print thread stacktraces when a synchronous ThreadLocalAction is waiting for more than SynchronousThreadLocalActionMaxWait seconds.
 - `--engine.TraceSourceCache` : Print information for source cache misses/evictions/failures.

truffle/src/com.oracle.truffle.api.test/src/com/oracle/truffle/api/test/source/SourceCacheTest.java

@@ -64,9 +64,9 @@
 import org.graalvm.polyglot.Engine;
 import org.graalvm.polyglot.PolyglotException;
 import org.graalvm.polyglot.Source;
+import org.graalvm.polyglot.io.ByteSequence;
 import org.junit.Assert;
 import org.junit.Test;
-import org.junit.function.ThrowingRunnable;
 
 import com.oracle.truffle.api.CallTarget;
 import com.oracle.truffle.api.Option;
@@ -81,19 +81,74 @@
 
 public class SourceCacheTest {
 
+    private static final String STATISTICS_RESULT_PATTERN_STRING = """
+                    \\[engine] Polyglot source cache statistics for engine \\d+\\s?
+                    --- SHARING LAYER \\d+; WEAK CACHE -------------------------\\s?
+                        Languages                                  :\\s?
+                             com_oracle_truffle_api_test_source_sourcecachetest_sourcecachetestlanguage:\\s?
+                                Character Based Sources Stats      :\\s?
+                                    Sources                        : count=              1\\s?
+                                        Size \\(C\\)                   : count=              1, sum=                       0, min=       0, avg=     0\\.00, max=          0, maxSource=0x12ea5c6b TestSource\\s?
+                                        Biggest Sources            :\\s?
+                                            0x12ea5c6b             : size=               0, name=TestSource\\s?
+                                    Cache                          : parse time\\(ms\\)= +\\d+, parse rate\\(C/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%\\s?
+                                        Parse Successful           : count=              1\\s?
+                                            Time \\(ms\\)              : count=              1, sum= +\\d+, min= +\\d+, avg= +\\d+\\.\\d+, max= +\\d+, maxSource=0x12ea5c6b TestSource\\s?
+                                            Size \\(C\\)               : count=              1, sum=                       0, min=       0, avg=     0\\.00, max=          0, maxSource=0x12ea5c6b TestSource\\s?
+                                        Sources With Most Hits     :\\s?
+                                            0x12ea5c6b             : parse time\\(ms\\)= +\\d+, parse rate\\(C/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Sources With Most Misses   :\\s?
+                                            0x12ea5c6b             : parse time\\(ms\\)= +\\d+, parse rate\\(C/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Sources With Most Evictions:\\s?
+                                            0x12ea5c6b             : parse time\\(ms\\)= +\\d+, parse rate\\(C/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Failures                   : count=              0\\s?
+                                Byte Based Sources Stats           :\\s?
+                                    Sources                        : count=              1\\s?
+                                        Size \\(B\\)                   : count=              1, sum=                       0, min=       0, avg=     0\\.00, max=          0, maxSource=0xb9ecef28 TestSource\\s?
+                                        Biggest Sources            :\\s?
+                                            0xb9ecef28             : size=               0, name=TestSource\\s?
+                                    Cache                          : parse time\\(ms\\)= +\\d+, parse rate\\(B/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%\\s?
+                                        Parse Successful           : count=              1\\s?
+                                            Time \\(ms\\)              : count=              1, sum= +\\d+, min= +\\d+, avg= +\\d+\\.\\d+, max= +\\d+, maxSource=0xb9ecef28 TestSource\\s?
+                                            Size \\(B\\)               : count=              1, sum=                       0, min=       0, avg=     0\\.00, max=          0, maxSource=0xb9ecef28 TestSource\\s?
+                                        Sources With Most Hits     :\\s?
+                                            0xb9ecef28             : parse time\\(ms\\)= +\\d+, parse rate\\(B/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Sources With Most Misses   :\\s?
+                                            0xb9ecef28             : parse time\\(ms\\)= +\\d+, parse rate\\(B/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Sources With Most Evictions:\\s?
+                                            0xb9ecef28             : parse time\\(ms\\)= +\\d+, parse rate\\(B/s\\)= +(\\d+\\.\\d+|NaN), hits=      1, misses=     1, evictions=    0, failures=    0, hit rate=50%, name=TestSource\\s?
+                                        Failures                   : count=              0\\s?
+                    \\s?
+                    """;
+
+    private static final String FAILURE_RESULT_PATTERN_STRING = """
+                                        Failures                   : count=              1\\s?
+                                            Sources With Failures  : count=              1\\s?
+                                                0x7595adef         : parse time\\(ms\\)= +\\d+, parse rate\\(C/s\\)= +(\\d+\\.\\d+|NaN), hits=      0, misses=     1, evictions=    0, failures=    1, hit rate= 0%, name=TestSource\\s?
+                                                    Failure #1     : count=              1, failure=com\\.oracle\\.truffle\\.api\\.test\\.source\\.SourceCacheTest\\$ParseException: DummyParseException\\s?
+                    [\\s\\S]*
+                                        Failures                   : count=              1\\s?
+                                            Sources With Failures  : count=              1\\s?
+                                                0x1c9840ac         : parse time\\(ms\\)= +\\d+, parse rate\\(B/s\\)= +(\\d+\\.\\d+|NaN), hits=      0, misses=     1, evictions=    0, failures=    1, hit rate= 0%, name=TestSource\\s?
+                                                    Failure #1     : count=              1, failure=com\\.oracle\\.truffle\\.api\\.test\\.source\\.SourceCacheTest\\$ParseException: DummyParseException\\s?
+                    """;
+
+    private static final Pattern STATISTICS_RESULT_PATTERN = Pattern.compile(STATISTICS_RESULT_PATTERN_STRING);
+    private static final Pattern FAILURE_RESULT_PATTERN = Pattern.compile(FAILURE_RESULT_PATTERN_STRING);
+
     @Test
     public void testTraceSourceCache() throws Throwable {
-        testCommon(SourceCacheTestLanguage.ID, Map.of("engine.TraceSourceCache", "true"), "[miss]", null);
+        testCommon(SourceCacheTestLanguage.ID, Map.of("engine.TraceSourceCache", "true", "engine.SourceCacheStatistics", "true"), "[miss, miss]", null);
     }
 
     @Test
     public void testTraceSourceCacheDetails() throws Throwable {
-        testCommon(SourceCacheTestLanguage.ID, Map.of("engine.TraceSourceCacheDetails", "true"), "[miss, hit]", null);
+        testCommon(SourceCacheTestLanguage.ID, Map.of("engine.TraceSourceCacheDetails", "true", "engine.SourceCacheStatistics", "true"), "[miss, miss, hit, hit]", null);
     }
 
     @Test
     public void testTraceSourceCacheFailure() throws Throwable {
-        testCommon(SourceCacheFailureTestLanguage.ID, Map.of("engine.TraceSourceCache", "true"), "[fail]", "DummyParseException");
+        testCommon(SourceCacheFailureTestLanguage.ID, Map.of("engine.TraceSourceCache", "true", "engine.SourceCacheStatistics", "true"), "[fail, fail]", "DummyParseException");
     }
 
     @Test
@@ -151,36 +206,58 @@ private static void forEachLog(byte[] logBytes, Consumer<Matcher> logConsumer) t
     }
 
     private static void testCommon(String languageId, Map<String, String> options, String expectedLogs, String failMessage) throws Throwable {
-        try (ByteArrayOutputStream out = new ByteArrayOutputStream(); Context context = Context.newBuilder().options(options).out(out).err(out).build()) {
+        ByteArrayOutputStream out = new ByteArrayOutputStream();
+        try (Context context = Context.newBuilder().options(options).out(out).err(out).build()) {
             String sourceName = "TestSource";
-            Source source = Source.newBuilder(languageId, "", sourceName).build();
-            String[] sourceHash = new String[1];
-            ThrowingRunnable testRunnable = () -> {
-                int sourceHashCode = context.eval(source).asInt();
-                sourceHash[0] = String.format("0x%08x", sourceHashCode);
-            };
+            Source source1 = Source.newBuilder(languageId, "", sourceName).build();
+            Source source2 = Source.newBuilder(languageId, ByteSequence.create(new byte[0]), sourceName).mimeType("text/binary").build();
+            String[] sourceHash = new String[2];
             if (failMessage != null) {
-                Assert.assertThrows(PolyglotException.class, testRunnable);
+                Assert.assertThrows(PolyglotException.class, () -> context.eval(source1));
+                Assert.assertThrows(PolyglotException.class, () -> context.eval(source2));
             } else {
-                testRunnable.run();
-                context.eval(source);
+                int sourceHashCode = context.eval(source1).asInt();
+                sourceHash[0] = String.format("0x%08x", sourceHashCode);
+                sourceHashCode = context.eval(source2).asInt();
+                sourceHash[1] = String.format("0x%08x", sourceHashCode);
+                context.eval(source1);
+                context.eval(source2);
             }
             List<String> logs = new ArrayList<>();
+            int[] cnt = new int[1];
             forEachLog(out.toByteArray(), (matcher) -> {
                 String logType = matcher.group(1);
                 logs.add(logType);
                 if (!"fail".equals(logType)) {
-                    Assert.assertEquals(sourceHash[0], matcher.group(2));
+                    Assert.assertEquals(sourceHash[cnt[0] % 2], matcher.group(2));
                 } else {
-                    Assert.assertTrue(matcher.group().endsWith("Error " + failMessage));
+                    Assert.assertTrue(matcher.group(), matcher.group().endsWith("Error " + ParseException.class.getName() + ": " + failMessage));
                 }
                 Assert.assertEquals(sourceName, matcher.group(3));
+                cnt[0]++;
             });
             Assert.assertEquals(expectedLogs, Arrays.toString(logs.toArray()));
         }
+        String fullOutput = out.toString();
+        int statisticsBeginIndex = fullOutput.indexOf("[engine] Polyglot source cache statistics for engine");
+        if (statisticsBeginIndex < 0) {
+            throw new AssertionError("Source cache statistics not found in the output: " + fullOutput);
+        }
+        String statisticsOutput = fullOutput.substring(statisticsBeginIndex);
+        if (failMessage == null) {
+            Matcher matcher = STATISTICS_RESULT_PATTERN.matcher(statisticsOutput);
+            if (!matcher.matches()) {
+                throw new AssertionError("Statistics output doesn't match the expected pattern. Check the output: " + statisticsOutput);
+            }
+        } else {
+            Matcher matcher = FAILURE_RESULT_PATTERN.matcher(statisticsOutput);
+            if (!matcher.find()) {
+                throw new AssertionError("Statistics output doesn't match the expected pattern. Check the output: " + statisticsOutput);
+            }
+        }
     }
 
-    @TruffleLanguage.Registration(contextPolicy = TruffleLanguage.ContextPolicy.SHARED)
+    @TruffleLanguage.Registration(contextPolicy = TruffleLanguage.ContextPolicy.SHARED, characterMimeTypes = "text/plain", byteMimeTypes = "text/binary", defaultMimeType = "text/plain")
     static class SourceCacheTestLanguage extends TruffleLanguage<TruffleLanguage.Env> {
         static final String ID = TestUtils.getDefaultLanguageId(SourceCacheTestLanguage.class);
 
@@ -226,7 +303,7 @@ static class ParseException extends AbstractTruffleException {
         }
     }
 
-    @TruffleLanguage.Registration
+    @TruffleLanguage.Registration(characterMimeTypes = "text/plain", byteMimeTypes = "text/binary", defaultMimeType = "text/plain")
     static class SourceCacheFailureTestLanguage extends TruffleLanguage<TruffleLanguage.Env> {
         static final String ID = TestUtils.getDefaultLanguageId(SourceCacheFailureTestLanguage.class);
 

truffle/src/com.oracle.truffle.api/src/com/oracle/truffle/api/impl/Accessor.java

@@ -262,6 +262,8 @@ public abstract Object getOrCreatePolyglotSource(Source source,
         public abstract void setPath(SourceBuilder builder, String path);
 
         public abstract Map<String, String> getSourceOptions(Source source);
+
+        public abstract URI getOriginalURI(Source source);
     }
 
     public abstract static class InteropSupport extends Support {

truffle/src/com.oracle.truffle.api/src/com/oracle/truffle/api/source/Source.java

@@ -796,13 +796,9 @@ TextMap createTextMap() {
     }
 
     private URI getNamedURI(String name, byte[] bytes) {
-        return getNamedURI(name, bytes, 0, bytes.length);
-    }
-
-    private URI getNamedURI(String name, byte[] bytes, int byteIndex, int length) {
         String digest;
         if (bytes != null) {
-            digest = digest(bytes, byteIndex, length);
+            digest = digest(bytes, 0, bytes.length);
         } else {
             digest = Integer.toString(System.identityHashCode(this), 16);
         }

truffle/src/com.oracle.truffle.api/src/com/oracle/truffle/api/source/SourceAccessor.java

@@ -179,5 +179,10 @@ public void mergeLoadedSources(Source[] sources) {
                 }
             }
         }
+
+        @Override
+        public URI getOriginalURI(Source source) {
+            return source.getOriginalURI();
+        }
     }
 }

truffle/src/com.oracle.truffle.polyglot/src/com/oracle/truffle/polyglot/PolyglotContextImpl.java

@@ -3779,7 +3779,7 @@ boolean patch(PolyglotContextConfig newConfig) {
         }
         PolyglotSharingLayer.Shared s = layer.shared;
         if (s != null) {
-            s.sourceCache.patch(TracingSourceCacheListener.createOrNull(engine));
+            s.sourceCache.patch(TracingSourceCacheListener.createOrNull(engine), engine.sourceCacheStatisticsListener);
         }
         return true;
     }

truffle/src/com.oracle.truffle.polyglot/src/com/oracle/truffle/polyglot/PolyglotEngineImpl.java

@@ -265,6 +265,8 @@ final class PolyglotEngineImpl implements com.oracle.truffle.polyglot.PolyglotIm
     final long engineId;
     final boolean allowExperimentalOptions;
 
+    SourceCacheStatisticsListener sourceCacheStatisticsListener; // effectively final
+
     @SuppressWarnings("unchecked")
     PolyglotEngineImpl(PolyglotImpl impl, SandboxPolicy sandboxPolicy, String[] permittedLanguages,
                     DispatchOutputStream out, DispatchOutputStream err, InputStream in, OptionValuesImpl engineOptions,
@@ -320,6 +322,8 @@ final class PolyglotEngineImpl implements com.oracle.truffle.polyglot.PolyglotIm
         this.engineLogger = initializeEngineLogger(engineLoggerSupplier, logLevels);
         this.engineOptionValues = engineOptions;
 
+        this.sourceCacheStatisticsListener = SourceCacheStatisticsListener.createOrNull(this);
+
         Map<String, PolyglotLanguage> publicLanguages = new LinkedHashMap<>();
         for (String key : this.idToLanguage.keySet()) {
             PolyglotLanguage languageImpl = idToLanguage.get(key);
@@ -559,6 +563,7 @@ void notifyCreated() {
         this.hostLanguage = createLanguage(LanguageCache.createHostLanguageCache(prototype.getHostLanguageSPI()), HOST_LANGUAGE_INDEX, null);
         this.engineLoggerSupplier = prototype.engineLoggerSupplier;
         this.engineLogger = prototype.engineLogger;
+        this.sourceCacheStatisticsListener = prototype.sourceCacheStatisticsListener;
 
         this.polyglotHostService = prototype.polyglotHostService;
         this.internalResourceRoots = prototype.internalResourceRoots;
@@ -742,6 +747,8 @@ boolean patch(SandboxPolicy newSandboxPolicy,
         Map<PolyglotInstrument, Map<String, String>> instrumentsOptions = new HashMap<>();
         parseOptions(newOptions, languagesOptions, instrumentsOptions);
 
+        sourceCacheStatisticsListener = SourceCacheStatisticsListener.createOrNull(this);
+
         RUNTIME.onEnginePatch(this.runtimeData, engineOptions, logSupplier, sandboxPolicy);
 
         List<OptionDescriptor> deprecatedDescriptors = new ArrayList<>();
@@ -1363,6 +1370,9 @@ void ensureClosed(boolean force, boolean initiatedByContext) {
             }
 
             RUNTIME.onEngineClosed(this.runtimeData);
+            if (sourceCacheStatisticsListener != null) {
+                sourceCacheStatisticsListener.onEngineClose(this);
+            }
 
             Object loggers = getEngineLoggers();
             if (loggers != null) {