[GR-31943] Serialize interrupts and cancels of a thread in NativeCallInterrupt

PullRequest: truffleruby/2709

Author: eregon

doc/contributor/debugging.md

@@ -5,6 +5,8 @@ You've got many options for debugging the implementation of TruffleRuby.
 If you want to debug an application running on TruffleRuby, and don't suspect
 any bug in TruffleRuby itself, use GraalVM [tools](../user/tools.md) as usual.
 
+Also see [user debugging docs](../user/debugging.md).
+
 ## Print Debugging
 
 `System.err.println(...);` in Java and `p` in Ruby is a great first tool to use for

doc/user/debugging.md

@@ -40,3 +40,12 @@ When debugging you may want to see this information.
 An option to show more information is `--backtraces-interleave-java=true`, which shows you the Java methods involved in executing each Ruby method.
 
 When you are interoperating with other languages, including C extensions, backtraces for Java exceptions may be missing information, as the Java frames are gone by the time Ruby has a chance to format them into a backtrace.
+
+## Printing Subprocesses
+
+You can print all subprocesses created by TruffleRuby using the option `--log-subprocess`.
+
+```bash
+$ ruby --log-subprocess -e '`ls .`'
+[ruby] INFO: spawn: ls .
+```

src/main/c/rubysignal/src/rubysignal.c

@@ -2,6 +2,8 @@
 #include <pthread.h>
 #include <signal.h>
 
+_Static_assert(sizeof(pthread_t) == sizeof(jlong), "Expected sizeof(pthread_t) == sizeof(jlong)");
+
 static void empty_handler(int sig) {
 }
 

src/main/java/org/truffleruby/RubyContext.java

@@ -164,7 +164,6 @@ public class RubyContext {
     public RubyContext(RubyLanguage language, TruffleLanguage.Env env) {
         Metrics.printTime("before-context-constructor");
 
-        this.logger = env.getLogger("");
         this.language = language;
         this.callStack = new CallStackManager(language, this);
         setEnv(env);
@@ -392,6 +391,7 @@ private void setEnv(Env env) {
         this.env = env;
         this.outStream = printStreamFor(env.out());
         this.errStream = printStreamFor(env.err());
+        this.logger = env.getLogger("");
         this.hasOtherPublicLanguages = computeHasOtherPublicLanguages(env);
         this.preInitializing = env.isPreInitialization();
     }

src/main/java/org/truffleruby/core/thread/NativeCallInterrupter.java

@@ -9,6 +9,7 @@
  */
 package org.truffleruby.core.thread;
 
+import com.oracle.truffle.api.CompilerDirectives;
 import com.oracle.truffle.api.TruffleSafepoint;
 import org.truffleruby.signal.LibRubySignal;
 
@@ -19,7 +20,7 @@ class NativeCallInterrupter implements TruffleSafepoint.Interrupter {
 
     private final Timer timer;
     private final long threadID;
-    private volatile Task currentTask = null;
+    private Task currentTask = null;
 
     NativeCallInterrupter(Timer timer, long threadID) {
         this.timer = timer;
@@ -28,16 +29,25 @@ class NativeCallInterrupter implements TruffleSafepoint.Interrupter {
 
     @Override
     public void interrupt(Thread thread) {
-        final Task task = new Task(threadID);
-        currentTask = task;
-        timer.schedule(task, 0, Task.PERIOD);
+        synchronized (this) {
+            final Task previousTask = this.currentTask;
+            if (previousTask != null) {
+                previousTask.cancel();
+            }
+
+            final Task task = new Task(threadID);
+            this.currentTask = task;
+            timer.schedule(task, 0, Task.PERIOD);
+        }
     }
 
     @Override
     public void resetInterrupted() {
-        Task task = currentTask;
-        if (task != null) {
-            task.cancel();
+        synchronized (this) {
+            final Task task = this.currentTask;
+            if (task != null) {
+                task.cancel();
+            }
         }
     }
 
@@ -49,18 +59,39 @@ static class Task extends TimerTask {
 
         private final long threadID;
         private int executed = 0;
+        private boolean cancelled = false;
 
         Task(long threadID) {
             this.threadID = threadID;
         }
 
+        @Override
+        public boolean cancel() {
+            // Ensure this task does not run later when this method returns.
+            // If it was running at the time of cancel(), wait for that.
+            synchronized (this) {
+                cancelled = true;
+                return super.cancel();
+            }
+        }
+
         @Override
         public void run() {
-            if (executed < MAX_EXECUTIONS) {
-                executed++;
-                LibRubySignal.sendSIGVTALRMToThread(threadID);
-            } else {
-                cancel();
+            synchronized (this) {
+                if (cancelled) {
+                    return;
+                }
+
+                if (executed < MAX_EXECUTIONS) {
+                    executed++;
+                    int result = LibRubySignal.sendSIGVTALRMToThread(threadID);
+                    if (result != 0) {
+                        throw CompilerDirectives.shouldNotReachHere(
+                                String.format("pthread_kill(%x, SIGVTALRM) failed with result=%d", threadID, result));
+                    }
+                } else {
+                    cancel();
+                }
             }
         }
     }

src/main/java/org/truffleruby/core/thread/ThreadManager.java

@@ -295,21 +295,23 @@ private void threadMain(RubyThread thread, Node currentNode, Supplier<Object> ta
             final Object result = task.get();
             setThreadValue(thread, result);
             // Handlers in the same order as in FiberManager
+            // Each catch must either setThreadValue() (before rethrowing) or setException()
         } catch (KillException e) {
             setThreadValue(thread, Nil.INSTANCE);
         } catch (ThreadDeath e) { // Context#close(true)
+            setThreadValue(thread, Nil.INSTANCE);
             throw e;
         } catch (RaiseException e) {
             setException(thread, e.getException(), currentNode);
         } catch (DynamicReturnException e) {
             setException(thread, context.getCoreExceptions().unexpectedReturn(currentNode), currentNode);
         } catch (ExitException e) {
-            rethrowOnMainThread(currentNode, e);
             setThreadValue(thread, Nil.INSTANCE);
+            rethrowOnMainThread(currentNode, e);
         } catch (Throwable e) {
             final RuntimeException runtimeException = printInternalError(e);
-            rethrowOnMainThread(currentNode, runtimeException);
             setThreadValue(thread, Nil.INSTANCE);
+            rethrowOnMainThread(currentNode, runtimeException);
         } finally {
             assert thread.value != null || thread.exception != null;
             cleanupKillOtherFibers(thread);
@@ -344,18 +346,18 @@ private void setThreadValue(RubyThread thread, Object value) {
     }
 
     private void setException(RubyThread thread, RubyException exception, Node currentNode) {
-        // A Thread is always shared (Thread.list)
-        SharedObjects.propagate(language, thread, exception);
-
         // We materialize the backtrace eagerly here, as the exception escapes the thread and needs
         // to capture the backtrace from this thread.
         final RaiseException truffleException = exception.backtrace.getRaiseException();
         if (truffleException != null) {
             TruffleStackTrace.fillIn(truffleException);
         }
 
-        final RubyThread mainThread = context.getThreadManager().getRootThread();
+        // A Thread is always shared (Thread.list)
+        SharedObjects.propagate(language, thread, exception);
+        thread.exception = exception;
 
+        final RubyThread mainThread = context.getThreadManager().getRootThread();
         if (thread != mainThread) {
             final boolean isSystemExit = exception instanceof RubySystemExit;
 
@@ -372,7 +374,6 @@ private void setException(RubyThread thread, RubyException exception, Node curre
                         .raiseInThread(language, context, mainThread, exception, currentNode);
             }
         }
-        thread.exception = exception;
     }
 
     // Share the Ruby Thread before it can be accessed concurrently, and before it is added to Thread.list

src/main/java/org/truffleruby/debug/TruffleDebugNodes.java

@@ -330,36 +330,53 @@ protected int getCacheLimit() {
 
     }
 
-    @CoreMethod(names = "log_config", onSingleton = true, required = 1)
-    public abstract static class LogConfigNode extends CoreMethodArrayArgumentsNode {
+    @CoreMethod(names = "log_warning", onSingleton = true, required = 1)
+    public abstract static class LogWarningNode extends CoreMethodArrayArgumentsNode {
 
         @Specialization
-        protected Object logConfig(Object value,
+        protected Object logWarning(Object value,
+                @Cached ToJavaStringNode toJavaStringNode) {
+            warning(toJavaStringNode.executeToJavaString(value));
+            return nil;
+        }
+
+        @TruffleBoundary
+        static void warning(String message) {
+            RubyLanguage.LOGGER.warning(message);
+        }
+
+    }
+
+    @CoreMethod(names = "log_info", onSingleton = true, required = 1)
+    public abstract static class LogInfoNode extends CoreMethodArrayArgumentsNode {
+
+        @Specialization
+        protected Object logInfo(Object value,
                 @Cached ToJavaStringNode toJavaStringNode) {
             config(toJavaStringNode.executeToJavaString(value));
             return nil;
         }
 
         @TruffleBoundary
         static void config(String message) {
-            RubyLanguage.LOGGER.config(message);
+            RubyLanguage.LOGGER.info(message);
         }
 
     }
 
-    @CoreMethod(names = "log_warning", onSingleton = true, required = 1)
-    public abstract static class LogWarningNode extends CoreMethodArrayArgumentsNode {
+    @CoreMethod(names = "log_config", onSingleton = true, required = 1)
+    public abstract static class LogConfigNode extends CoreMethodArrayArgumentsNode {
 
         @Specialization
-        protected Object logWarning(Object value,
+        protected Object logConfig(Object value,
                 @Cached ToJavaStringNode toJavaStringNode) {
-            warning(toJavaStringNode.executeToJavaString(value));
+            config(toJavaStringNode.executeToJavaString(value));
             return nil;
         }
 
         @TruffleBoundary
-        static void warning(String message) {
-            RubyLanguage.LOGGER.warning(message);
+        static void config(String message) {
+            RubyLanguage.LOGGER.config(message);
         }
 
     }

src/main/java/org/truffleruby/language/TruffleBootNodes.java

@@ -319,7 +319,8 @@ protected Object getOption(Object optionName,
             if (descriptor == null) {
                 throw new RaiseException(
                         getContext(),
-                        coreExceptions().nameError("option not defined", nil, optionNameString, this));
+                        coreExceptions()
+                                .nameError("option not defined: " + optionNameString, nil, optionNameString, this));
             }
 
             Object value = getContext().getOptions().fromDescriptor(descriptor);

src/main/java/org/truffleruby/options/Options.java

@@ -71,6 +71,8 @@ public class Options {
     public final boolean HASHING_DETERMINISTIC;
     /** --fiber-leave-context=true */
     public final boolean FIBER_LEAVE_CONTEXT;
+    /** --log-subprocess=false */
+    public final boolean LOG_SUBPROCESS;
     /** --exceptions-store-java=false */
     public final boolean EXCEPTIONS_STORE_JAVA;
     /** --exceptions-print-java=false */
@@ -215,6 +217,7 @@ public Options(Env env, OptionValues options, LanguageOptions languageOptions) {
         PATCHING = options.get(OptionsCatalog.PATCHING_KEY);
         HASHING_DETERMINISTIC = options.get(OptionsCatalog.HASHING_DETERMINISTIC_KEY);
         FIBER_LEAVE_CONTEXT = options.get(OptionsCatalog.FIBER_LEAVE_CONTEXT_KEY);
+        LOG_SUBPROCESS = options.get(OptionsCatalog.LOG_SUBPROCESS_KEY);
         EXCEPTIONS_STORE_JAVA = options.get(OptionsCatalog.EXCEPTIONS_STORE_JAVA_KEY);
         EXCEPTIONS_PRINT_JAVA = options.get(OptionsCatalog.EXCEPTIONS_PRINT_JAVA_KEY);
         EXCEPTIONS_PRINT_UNCAUGHT_JAVA = options.get(OptionsCatalog.EXCEPTIONS_PRINT_UNCAUGHT_JAVA_KEY);
@@ -326,6 +329,8 @@ public Object fromDescriptor(OptionDescriptor descriptor) {
                 return HASHING_DETERMINISTIC;
             case "ruby.fiber-leave-context":
                 return FIBER_LEAVE_CONTEXT;
+            case "ruby.log-subprocess":
+                return LOG_SUBPROCESS;
             case "ruby.exceptions-store-java":
                 return EXCEPTIONS_STORE_JAVA;
             case "ruby.exceptions-print-java":

src/main/ruby/truffleruby/core/truffle/process_operations.rb

@@ -350,7 +350,8 @@ def convert_env_value(value)
 
       def spawn_setup(alter_process)
         env = @options.delete(:unsetenv_others) ? {} : ENV.to_hash
-        if add_to_env = @options.delete(:env)
+        @add_to_env = add_to_env = @options.delete(:env)
+        if add_to_env
           add_to_env.each do |key, value|
             if value
               env[key] = value
@@ -415,6 +416,7 @@ def redirect_file_descriptor(from, to, alter_process)
       end
 
       def spawn
+        log_command 'spawn'
         pid = posix_spawnp @command, @argv, @env_array, @options
         # Check if the command exists *after* invoking posix_spawn so we have a pid
         if not resolve_in_path(@command)
@@ -497,6 +499,7 @@ def posix_spawnp(command, args, env_array, options)
       end
 
       def exec
+        log_command('exec')
         # exec validates the command only if it searches in $PATH
         if should_search_path?(@command)
           if resolved = resolve_in_path(@command)
@@ -516,6 +519,17 @@ def exec
         raise SystemCallError.new('execve() should not return', 0)
       end
 
+      Truffle::Boot.delay do
+        LOG_SUBPROCESS = Truffle::Boot.get_option 'log-subprocess'
+      end
+
+      def log_command(type)
+        if LOG_SUBPROCESS
+          env = (@add_to_env || {}).map { |k,v| "#{k}=#{v}" }.join(' ')
+          Truffle::Debug.log_info "#{type}: #{env}#{' ' unless env.empty?}#{@argv.join(' ')}"
+        end
+      end
+
       def should_use_shell?(command)
         command.b.match?(SHELL_META_CHAR_PATTERN)
       end