Merge pull request #4395 from jruby/truffle-perf-warnings

Truffle perf warnings
jruby · Dec 18, 2016 · 53074f5 · 53074f5
2 parents 20966c5 + 6c6bf76
commit 53074f5
Show file tree

Hide file tree

Showing 15 changed files with 101 additions and 81 deletions.
diff --git a/samples/truffle/logging.properties b/samples/truffle/logging.properties
@@ -0,0 +1,15 @@
+# Use this configuration with -J-Djava.util.logging.config.file=samples/truffle/logging.properties
+
+# Use the standard file logger. If we set any handlers then the default one
+# will be unset. You can add it back by name -
+# org.jruby.truffle.Log$RubyHandler.
+
+org.jruby.truffle.handlers=java.util.logging.FileHandler
+
+# Say where to send file output.
+
+java.util.logging.FileHandler.pattern=ruby.log
+
+# Configure the logging level.
+
+org.jruby.truffle.level=WARNING
diff --git a/tool/truffle/options.yml b/tool/truffle/options.yml
@@ -97,7 +97,6 @@ CALL_GRAPH_WRITE: [callgraph.write, string, null, File to write the call graph t
 CHAOS: [chaos, boolean, false, Randomly modify the representation of objects]
 
 GRAAL_WARNING_UNLESS: [graal.warn_unless, boolean, true, Warn unless the JVM has the Graal compiler]
-PERF_WARNING: [perf.warn, boolean, false, Warn when using a fature which is not optimized yet]
 
 SHARED_OBJECTS_ENABLED: [shared.objects, boolean, true, Enable shared objects]
 SHARED_OBJECTS_DEBUG: [shared.objects.debug, boolean, false, Print information about shared objects]

diff --git a/truffle/src/main/java/org/jruby/truffle/Log.java b/truffle/src/main/java/org/jruby/truffle/Log.java
@@ -9,39 +9,92 @@
  */
 package org.jruby.truffle;
 
+import com.oracle.truffle.api.CompilerDirectives;
 import com.oracle.truffle.api.CompilerDirectives.TruffleBoundary;
 
+import java.util.Collections;
+import java.util.Set;
+import java.util.concurrent.ConcurrentHashMap;
 import java.util.logging.Handler;
+import java.util.logging.Level;
+import java.util.logging.LogManager;
 import java.util.logging.LogRecord;
 import java.util.logging.Logger;
 
 public class Log {
 
+    private static class RubyLevel extends Level {
+
+        public RubyLevel(String name, Level parent) {
+            super(name, parent.intValue(), parent.getResourceBundleName());
+        }
+
+    }
+
+    public static final Level PERFORMANCE = new RubyLevel("PERFORMANCE", Level.WARNING);
+
     private static final Logger LOGGER = createLogger();
 
+    public static class RubyHandler extends Handler {
+
+        @Override
+        public void publish(LogRecord record) {
+            System.err.printf("[ruby] %s %s%n", record.getLevel().getName(), record.getMessage());
+        }
+
+        @Override
+        public void flush() {
+        }
+
+        @Override
+        public void close() throws SecurityException {
+        }
+
+    }
+
     private static Logger createLogger() {
         final Logger logger = Logger.getLogger("org.jruby.truffle");
 
-        logger.setUseParentHandlers(false);
+        if (LogManager.getLogManager().getProperty("org.jruby.truffle.handlers") == null) {
+            logger.setUseParentHandlers(false);
+            logger.addHandler(new RubyHandler());
+        }
 
-        logger.addHandler(new Handler() {
+        return logger;
+    }
 
-            @Override
-            public void publish(LogRecord record) {
-                System.err.printf("[ruby] %s %s%n", record.getLevel().getName(), record.getMessage());
-            }
+    private static final Set<String> displayedWarnings = Collections.newSetFromMap(new ConcurrentHashMap<>());
 
-            @Override
-            public void flush() {
-            }
+    public static final String KWARGS_NOT_OPTIMIZED_YET = "keyword arguments are not yet optimized";
 
-            @Override
-            public void close() throws SecurityException {
-            }
+    /**
+     * Warn about code that works but is not yet optimized as Truffle code normally would be. Only prints the warning
+     * once, and only if called from compiled code. Don't call this method from behind a boundary, as it will never
+     * print the warning because it will never be called from compiled code. Use {@link #performanceOnce} instead
+     * if you need to warn in code that is never compiled.
+     */
+    public static void notOptimizedOnce(String message) {
+        if (CompilerDirectives.inCompiledCode()) {
+            performanceOnce(message);
+        }
+    }
 
-        });
+    /**
+     * Warn about something that has lower performance than might be expected. Only prints the warning once.
+     */
+    @TruffleBoundary
+    public static void performanceOnce(String message) {
+        if (displayedWarnings.add(message)) {
+            performance(message);
+        }
+    }
 
-        return logger;
+    /**
+     * Warn about something that has lower performance than might be expected.
+     */
+    @TruffleBoundary
+    public static void performance(String message) {
+        LOGGER.log(PERFORMANCE, message);
     }
 
     @TruffleBoundary

diff --git a/truffle/src/main/java/org/jruby/truffle/RubyEngine.java b/truffle/src/main/java/org/jruby/truffle/RubyEngine.java
@@ -60,7 +60,7 @@ public RubyEngine(
 
     public int execute(String path) {
         if (!Graal.isGraal() && context.getOptions().GRAAL_WARNING_UNLESS) {
-            Log.warning("This JVM does not have the Graal compiler - performance will be limited - " +
+            Log.performanceOnce("This JVM does not have the Graal compiler - performance will be limited - " +
                     "see https://github.com/jruby/jruby/wiki/Truffle-FAQ#how-do-i-get-jrubytruffle");
         }
 

diff --git a/truffle/src/main/java/org/jruby/truffle/core/hash/HashNodes.java b/truffle/src/main/java/org/jruby/truffle/core/hash/HashNodes.java
@@ -25,6 +25,7 @@
 import com.oracle.truffle.api.profiles.ConditionProfile;
 import com.oracle.truffle.api.source.SourceSection;
 import org.jruby.truffle.Layouts;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
 import org.jruby.truffle.builtins.CoreClass;
 import org.jruby.truffle.builtins.CoreMethod;
@@ -37,7 +38,6 @@
 import org.jruby.truffle.core.hash.HashNodesFactory.GetIndexNodeFactory;
 import org.jruby.truffle.core.hash.HashNodesFactory.InternalRehashNodeGen;
 import org.jruby.truffle.language.NotProvided;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyGuards;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.SnippetNode;
@@ -1004,7 +1004,7 @@ public DynamicObject mergeBucketsPacked(VirtualFrame frame, DynamicObject hash,
 
         @Specialization(guards = "isRubyHash(other)")
         public DynamicObject merge(VirtualFrame frame, DynamicObject hash, DynamicObject other, DynamicObject block) {
-            PerformanceWarnings.warn("Hash#merge with a block is not yet optimized");
+            Log.notOptimizedOnce("Hash#merge with a block is not yet optimized");
             final boolean compareByIdentity = Layouts.HASH.getCompareByIdentity(hash);
 
             final int capacity = BucketsStrategy.capacityGreaterThan(Layouts.HASH.getSize(hash) + Layouts.HASH.getSize(other));

diff --git a/truffle/src/main/java/org/jruby/truffle/interop/InteropNodes.java b/truffle/src/main/java/org/jruby/truffle/interop/InteropNodes.java
@@ -32,6 +32,7 @@
 import com.oracle.truffle.api.profiles.BranchProfile;
 import com.oracle.truffle.api.source.Source;
 import org.jcodings.specific.ASCIIEncoding;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.builtins.CoreClass;
 import org.jruby.truffle.builtins.CoreMethod;
 import org.jruby.truffle.builtins.CoreMethodArrayArgumentsNode;
@@ -41,7 +42,6 @@
 import org.jruby.truffle.core.rope.Rope;
 import org.jruby.truffle.core.string.StringCachingGuards;
 import org.jruby.truffle.core.string.StringOperations;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.SnippetNode;
 import org.jruby.truffle.language.control.JavaException;
@@ -118,7 +118,7 @@ public Object executeForeignUncached(
                 VirtualFrame frame,
                 TruffleObject receiver,
                 Object[] args) {
-            PerformanceWarnings.warn("megamorphic interop EXECUTE message send");
+            Log.notOptimizedOnce("megamorphic interop EXECUTE message send");
 
             final Node executeNode = createExecuteNode(args.length);
 
@@ -184,7 +184,7 @@ public Object invokeUncached(
                 TruffleObject receiver,
                 DynamicObject identifier,
                 Object[] args) {
-            PerformanceWarnings.warn("megamorphic interop INVOKE message send");
+            Log.notOptimizedOnce("megamorphic interop INVOKE message send");
 
             final Node invokeNode = createInvokeNode(args.length);
 

diff --git a/truffle/src/main/java/org/jruby/truffle/interop/OutgoingForeignCallNode.java b/truffle/src/main/java/org/jruby/truffle/interop/OutgoingForeignCallNode.java
@@ -27,8 +27,8 @@
 import com.oracle.truffle.api.nodes.Node;
 import com.oracle.truffle.api.profiles.BranchProfile;
 import com.oracle.truffle.api.source.SourceSection;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.control.JavaException;
 
@@ -72,7 +72,7 @@ public Object callUncached(
             TruffleObject receiver,
             Object[] args,
             @Cached("create()") ForeignToRubyNode toRubyNode) {
-        PerformanceWarnings.warn("megamorphic outgoing foreign call");
+        Log.notOptimizedOnce("megamorphic outgoing foreign call");
 
         if (megamorphicToForeignNode == null) {
             CompilerDirectives.transferToInterpreterAndInvalidate();

diff --git a/truffle/src/main/java/org/jruby/truffle/language/PerformanceWarnings.java b/truffle/src/main/java/org/jruby/truffle/language/PerformanceWarnings.java
diff --git a/truffle/src/main/java/org/jruby/truffle/language/arguments/CheckKeywordArityNode.java b/truffle/src/main/java/org/jruby/truffle/language/arguments/CheckKeywordArityNode.java
@@ -14,10 +14,10 @@
 import com.oracle.truffle.api.object.DynamicObject;
 import com.oracle.truffle.api.profiles.BranchProfile;
 import com.oracle.truffle.api.source.SourceSection;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
 import org.jruby.truffle.core.hash.HashOperations;
 import org.jruby.truffle.core.hash.KeyValue;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyGuards;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.control.RaiseException;
@@ -56,6 +56,7 @@ public void executeVoid(VirtualFrame frame) {
 
         if (keywordArguments != null) {
             receivedKeywordsProfile.enter();
+            Log.notOptimizedOnce(Log.KWARGS_NOT_OPTIMIZED_YET);
             checkArityKeywordArguments(keywordArguments, given);
         }
     }
@@ -68,8 +69,6 @@ public Object execute(VirtualFrame frame) {
 
     @TruffleBoundary
     private void checkArityKeywordArguments(Object keywordArguments, int given) {
-        PerformanceWarnings.warn(PerformanceWarnings.KWARGS_NOT_OPTIMIZED_YET);
-
         final DynamicObject keywordHash = (DynamicObject) keywordArguments;
 
         for (KeyValue keyValue : HashOperations.iterableKeyValues(keywordHash)) {

diff --git a/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadKeywordRestArgumentNode.java b/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadKeywordRestArgumentNode.java
@@ -15,11 +15,11 @@
 import com.oracle.truffle.api.profiles.ConditionProfile;
 import com.oracle.truffle.api.source.SourceSection;
 import org.jruby.truffle.Layouts;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
 import org.jruby.truffle.core.hash.BucketsStrategy;
 import org.jruby.truffle.core.hash.HashOperations;
 import org.jruby.truffle.core.hash.KeyValue;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyGuards;
 import org.jruby.truffle.language.RubyNode;
 
@@ -53,13 +53,13 @@ private Object lookupRestKeywordArgumentHash(VirtualFrame frame) {
             return Layouts.HASH.createHash(coreLibrary().getHashFactory(), null, 0, null, null, null, null, false);
         }
 
+        Log.notOptimizedOnce(Log.KWARGS_NOT_OPTIMIZED_YET);
+
         return extractKeywordHash(hash);
     }
 
     @TruffleBoundary
     private Object extractKeywordHash(final Object hash) {
-        PerformanceWarnings.warn(PerformanceWarnings.KWARGS_NOT_OPTIMIZED_YET);
-
         final DynamicObject hashObject = (DynamicObject) hash;
 
         final List<KeyValue> entries = new ArrayList<>();

diff --git a/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadOptionalArgumentNode.java b/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadOptionalArgumentNode.java
@@ -15,10 +15,10 @@
 import com.oracle.truffle.api.profiles.BranchProfile;
 import com.oracle.truffle.api.source.SourceSection;
 import org.jruby.truffle.Layouts;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
 import org.jruby.truffle.core.array.ArrayReadNormalizedNode;
 import org.jruby.truffle.core.array.ArrayReadNormalizedNodeGen;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyGuards;
 import org.jruby.truffle.language.RubyNode;
 
@@ -70,7 +70,7 @@ public Object execute(VirtualFrame frame) {
         defaultValueProfile.enter();
 
         if (considerRejectedKWArgs) {
-            PerformanceWarnings.warn(PerformanceWarnings.KWARGS_NOT_OPTIMIZED_YET);
+            Log.notOptimizedOnce(Log.KWARGS_NOT_OPTIMIZED_YET);
 
             final Object rest = readRestArgumentNode.execute(frame);
 

diff --git a/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadRestArgumentNode.java b/truffle/src/main/java/org/jruby/truffle/language/arguments/ReadRestArgumentNode.java
@@ -13,9 +13,9 @@
 import com.oracle.truffle.api.object.DynamicObject;
 import com.oracle.truffle.api.profiles.BranchProfile;
 import com.oracle.truffle.api.source.SourceSection;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.RubyContext;
 import org.jruby.truffle.core.array.ArrayUtils;
-import org.jruby.truffle.language.PerformanceWarnings;
 import org.jruby.truffle.language.RubyGuards;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.SnippetNode;
@@ -81,7 +81,7 @@ public Object execute(VirtualFrame frame) {
         final DynamicObject rest = createArray(resultStore, resultLength);
 
         if (keywordArguments) {
-            PerformanceWarnings.warn(PerformanceWarnings.KWARGS_NOT_OPTIMIZED_YET);
+            Log.notOptimizedOnce(Log.KWARGS_NOT_OPTIMIZED_YET);
 
             Object kwargsHash = readUserKeywordsHashNode.execute(frame);
 

diff --git a/truffle/src/main/java/org/jruby/truffle/language/arguments/RunBlockKWArgsHelperNode.java b/truffle/src/main/java/org/jruby/truffle/language/arguments/RunBlockKWArgsHelperNode.java
@@ -13,7 +13,7 @@
 import com.oracle.truffle.api.frame.FrameSlot;
 import com.oracle.truffle.api.frame.VirtualFrame;
 import org.jruby.truffle.Layouts;
-import org.jruby.truffle.language.PerformanceWarnings;
+import org.jruby.truffle.Log;
 import org.jruby.truffle.language.RubyNode;
 import org.jruby.truffle.language.SnippetNode;
 import org.jruby.truffle.language.locals.ReadFrameSlotNode;
@@ -37,7 +37,7 @@ public RunBlockKWArgsHelperNode(FrameSlot arrayFrameSlot, Object kwrestName) {
 
     @Override
     public Object execute(VirtualFrame frame) {
-        PerformanceWarnings.warn(PerformanceWarnings.KWARGS_NOT_OPTIMIZED_YET);
+        Log.notOptimizedOnce(Log.KWARGS_NOT_OPTIMIZED_YET);
 
         final Object array = readArrayNode.executeRead(frame);
 

diff --git a/truffle/src/main/java/org/jruby/truffle/options/Options.java b/truffle/src/main/java/org/jruby/truffle/options/Options.java
@@ -101,7 +101,6 @@ public class Options {
     public final String CALL_GRAPH_WRITE;
     public final boolean CHAOS;
     public final boolean GRAAL_WARNING_UNLESS;
-    public final boolean PERF_WARNING;
     public final boolean SHARED_OBJECTS_ENABLED;
     public final boolean SHARED_OBJECTS_DEBUG;
     public final boolean SHARED_OBJECTS_FORCE;
@@ -193,7 +192,6 @@ public class Options {
         CALL_GRAPH_WRITE = builder.getOrDefault(OptionsCatalog.CALL_GRAPH_WRITE);
         CHAOS = builder.getOrDefault(OptionsCatalog.CHAOS);
         GRAAL_WARNING_UNLESS = builder.getOrDefault(OptionsCatalog.GRAAL_WARNING_UNLESS);
-        PERF_WARNING = builder.getOrDefault(OptionsCatalog.PERF_WARNING);
         SHARED_OBJECTS_ENABLED = builder.getOrDefault(OptionsCatalog.SHARED_OBJECTS_ENABLED);
         SHARED_OBJECTS_DEBUG = builder.getOrDefault(OptionsCatalog.SHARED_OBJECTS_DEBUG);
         SHARED_OBJECTS_FORCE = builder.getOrDefault(OptionsCatalog.SHARED_OBJECTS_FORCE);