Further fixes.

Improvements for the teardown failure/warning logics.

Author: christianhaeubl

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/SubstrateOptions.java

@@ -24,7 +24,6 @@
  */
 package com.oracle.svm.core;
 
-import static com.oracle.svm.core.SubstrateOptions.DeprecatedOptions.TearDownFailureNanos;
 import static com.oracle.svm.core.option.RuntimeOptionKey.RuntimeOptionKeyFlag.Immutable;
 import static com.oracle.svm.core.option.RuntimeOptionKey.RuntimeOptionKeyFlag.RegisterForIsolateArgumentParser;
 import static com.oracle.svm.core.option.RuntimeOptionKey.RuntimeOptionKeyFlag.RelevantForCompilationIsolates;
@@ -618,17 +617,13 @@ protected void onValueUpdate(EconomicMap<OptionKey<?>, Object> values, Boolean o
             }
         };
 
-        public static final String TEAR_DOWN_WARNING_NANOS_ERROR = "Can't set both TearDownWarningSeconds and TearDownWarningNanos at the same time. Use TearDownWarningSeconds.";
-        @Option(help = "The number of nanoseconds before and between which tearing down an isolate gives a warning message. 0 implies no warning.", //
+        @Option(help = "The number of nanoseconds that the isolate teardown can take before warnings are printed. Disabled if less or equal to 0.", //
                         deprecated = true, deprecationMessage = "Use -XX:TearDownWarningSeconds=<secs> instead")//
-        public static final RuntimeOptionKey<Long> TearDownWarningNanos = new RuntimeOptionKey<>(0L,
-                        (key) -> UserError.guarantee(!(key.hasBeenSet() && TearDownWarningSeconds.hasBeenSet()), TEAR_DOWN_WARNING_NANOS_ERROR),
-                        RelevantForCompilationIsolates);
+        public static final RuntimeOptionKey<Long> TearDownWarningNanos = new RuntimeOptionKey<>(0L, RelevantForCompilationIsolates);
 
-        @Option(help = "The number of nanoseconds before tearing down an isolate gives a failure message and returns from a tear-down call. 0 implies no message.", //
-                        deprecated = true, deprecationMessage = "This call leaks resources. Instead, terminate java threads cooperatively, or use System#exit")//
+        @Option(help = "The number of nanoseconds that the isolate teardown can take before a fatal error is thrown. Disabled if less or equal to 0.", //
+                        deprecated = true, deprecationMessage = "Use -XX:TearDownFailureSeconds=<secs> instead")//
         public static final RuntimeOptionKey<Long> TearDownFailureNanos = new RuntimeOptionKey<>(0L, RelevantForCompilationIsolates);
-
     }
 
     @LayerVerifiedOption(kind = Kind.Changed, severity = Severity.Error)//
@@ -870,24 +865,18 @@ private static void validateZapNativeMemory(HostedOptionKey<Boolean> optionKey)
         }
     }
 
-    /*
-     * Isolate tear down options.
-     */
-    @Option(help = "The number of seconds before and between which tearing down an isolate gives a warning message. 0 implies no warning.")//
-    public static final RuntimeOptionKey<Long> TearDownWarningSeconds = new RuntimeOptionKey<>(0L, RelevantForCompilationIsolates);
-
     public static long getTearDownWarningNanos() {
-        if (TearDownWarningSeconds.hasBeenSet() && DeprecatedOptions.TearDownWarningNanos.hasBeenSet()) {
-            throw new IllegalArgumentException(DeprecatedOptions.TEAR_DOWN_WARNING_NANOS_ERROR);
-        }
-        if (DeprecatedOptions.TearDownWarningNanos.hasBeenSet()) {
-            return DeprecatedOptions.TearDownWarningNanos.getValue();
+        if (ConcealedOptions.TearDownWarningSeconds.getValue() != 0) {
+            return TimeUtils.secondsToNanos(ConcealedOptions.TearDownWarningSeconds.getValue());
         }
-        return TearDownWarningSeconds.getValue() * TimeUtils.nanosPerSecond;
+        return DeprecatedOptions.TearDownWarningNanos.getValue();
     }
 
     public static long getTearDownFailureNanos() {
-        return TearDownFailureNanos.getValue();
+        if (ConcealedOptions.TearDownFailureSeconds.getValue() != 0) {
+            return TimeUtils.secondsToNanos(ConcealedOptions.TearDownFailureSeconds.getValue());
+        }
+        return DeprecatedOptions.TearDownFailureNanos.getValue();
     }
 
     @Option(help = "Define the maximum number of stores for which the loop that zeroes out objects is unrolled.")//
@@ -1264,6 +1253,15 @@ protected void onValueUpdate(EconomicMap<OptionKey<?>, Object> values, Integer o
         @Option(help = "Avoid linker relocations for code and instead emit address computations.", type = OptionType.Expert) //
         @LayerVerifiedOption(severity = Severity.Error, kind = Kind.Changed, positional = false) //
         public static final HostedOptionKey<Boolean> RelativeCodePointers = new HostedOptionKey<>(false, SubstrateOptions::validateRelativeCodePointers);
+
+        /** Use {@link SubstrateOptions#getTearDownWarningNanos()} instead. */
+        @Option(help = "The number of seconds that the isolate teardown can take before warnings are printed. Disabled if less or equal to 0.")//
+        public static final RuntimeOptionKey<Long> TearDownWarningSeconds = new RuntimeOptionKey<>(0L, RelevantForCompilationIsolates);
+
+        /** Use {@link SubstrateOptions#getTearDownFailureNanos()} instead. */
+        @Option(help = "The number of seconds that the isolate teardown can take before a fatal error is thrown. Disabled if less or equal to 0.")//
+        public static final RuntimeOptionKey<Long> TearDownFailureSeconds = new RuntimeOptionKey<>(0L, RelevantForCompilationIsolates);
+
     }
 
     @Option(help = "Overwrites the available number of processors provided by the OS. Any value <= 0 means using the processor count from the OS.")//

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/graal/snippets/CEntryPointSnippets.java

@@ -671,9 +671,7 @@ public static int tearDownIsolateSnippet() {
     private static int tearDownIsolate() {
         try {
             /* Execute interruptible code. */
-            if (!initiateTearDownIsolateInterruptibly()) {
-                return CEntryPointErrors.UNSPECIFIED;
-            }
+            initiateTearDownIsolateInterruptibly();
 
             /* After threadExit(), only uninterruptible code may be executed. */
             RecurringCallbackSupport.suspendCallbackTimer("Execution of arbitrary code is prohibited during the last teardown steps.");
@@ -722,13 +720,10 @@ private static int tearDownIsolate() {
         }
     }
 
-    @Uninterruptible(reason = "Tear-down in progress - still safe to execute interruptible Java code.", calleeMustBe = false)
-    private static boolean initiateTearDownIsolateInterruptibly() {
+    @Uninterruptible(reason = "Tear-down in progress - still safe to execute interruptible Java code.", callerMustBe = true, calleeMustBe = false)
+    private static void initiateTearDownIsolateInterruptibly() {
         RuntimeSupport.executeTearDownHooks();
-        if (!PlatformThreads.tearDownOtherThreads()) {
-            return false;
-        }
-
+        PlatformThreads.tearDownOtherThreads();
         /*
          * At this point, only the current thread, the VM operation thread, and the reference
          * handler thread are still running.
@@ -739,7 +734,6 @@ private static boolean initiateTearDownIsolateInterruptibly() {
 
         VMThreads.singleton().threadExit();
         /* After threadExit(), only uninterruptible code may be executed. */
-        return true;
     }
 
     @Snippet(allowMissingProbabilities = true)

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/thread/PlatformThreads.java

@@ -44,7 +44,6 @@
 import java.util.concurrent.ForkJoinWorkerThread;
 import java.util.concurrent.ScheduledThreadPoolExecutor;
 import java.util.concurrent.ThreadPoolExecutor;
-import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 
 import org.graalvm.nativeimage.CurrentIsolate;
@@ -550,8 +549,8 @@ public void closeOSThreadHandle(OSThreadHandle threadHandle) {
      * teardown logic (see {@link #isVMInternalThread(IsolateThread)}). Waits until the interrupted
      * threads detach.
      */
-    public static boolean tearDownOtherThreads() {
-        final Log trace = Log.noopLog().string("[PlatformThreads.tearDownPlatformThreads:").newline().flush();
+    public static void tearDownOtherThreads() {
+        Log trace = Log.noopLog().string("[PlatformThreads.tearDownPlatformThreads:").newline().flush();
 
         /*
          * Set tear-down flag for new Java threads that have already been started on an OS level,
@@ -626,46 +625,36 @@ public static boolean tearDownOtherThreads() {
             trace.string("  shutdown initiated: ").object(pool).newline().flush();
         }
 
-        final boolean result = waitForTearDown();
-        trace.string("  returns: ").bool(result).string("]").newline().flush();
-        return result;
+        waitForTearDown();
     }
 
     /** Wait (im)patiently for the thread list to drain. */
-    private static boolean waitForTearDown() {
+    private static void waitForTearDown() {
         assert !isVMInternalThread(CurrentIsolate.getCurrentThread()) : "we count the threads until only the current one remains";
 
-        final Log trace = Log.noopLog().string("[PlatformThreads.waitForTearDown:").newline();
-        final long warningNanos = SubstrateOptions.getTearDownWarningNanos();
-        final String warningMessage = "PlatformThreads.waitForTearDown is taking too long.";
-        final long failureNanos = SubstrateOptions.getTearDownFailureNanos();
-        final String failureMessage = "PlatformThreads.waitForTearDown took too long.";
-        final long startNanos = System.nanoTime();
-        long loopNanos = startNanos;
-        final AtomicBoolean printLaggards = new AtomicBoolean(false);
-        final Log counterLog = ((warningNanos == 0) ? trace : Log.log());
-        final CheckReadyForTearDownOperation operation = new CheckReadyForTearDownOperation(counterLog, printLaggards);
-
-        for (; /* return */;) {
-            final long previousLoopNanos = loopNanos;
+        CheckReadyForTearDownOperation operation = new CheckReadyForTearDownOperation();
+        long warningConfiguredNanos = SubstrateOptions.getTearDownWarningNanos();
+        long failureConfiguredNanos = SubstrateOptions.getTearDownFailureNanos();
+        long startNanos = System.nanoTime();
+        long previousReportNanos = startNanos;
+
+        while (true) {
             operation.enqueue();
             if (operation.isReadyForTearDown()) {
-                trace.string("  returns true]").newline();
-                return true;
+                return;
             }
-            loopNanos = TimeUtils.doNotLoopTooLong(startNanos, loopNanos, warningNanos, warningMessage);
-            final boolean fatallyTooLong = TimeUtils.maybeFatallyTooLong(startNanos, failureNanos, failureMessage);
-            if (fatallyTooLong) {
-                trace.string("Took too long to tear down the VM.").newline();
-                /*
-                 * Debugging tip: Insert a `BreakpointNode.breakpoint()` here to stop in gdb or get
-                 * a core file with the thread stacks. Be careful about believing the stack traces,
-                 * though.
-                 */
-                return false;
+
+            long sinceStartNanos = TimeUtils.nanoSecondsSince(startNanos);
+            if (failureConfiguredNanos > 0 && TimeUtils.nanoTimeLessThan(failureConfiguredNanos, sinceStartNanos)) {
+                throw VMError.shouldNotReachHere("Took too long to tear down the VM.");
+            }
+
+            long sinceReportNanos = TimeUtils.nanoSecondsSince(previousReportNanos);
+            if (warningConfiguredNanos > 0 && TimeUtils.nanoTimeLessThan(warningConfiguredNanos, sinceReportNanos)) {
+                operation.enablePrintLaggards();
+                previousReportNanos += sinceReportNanos;
             }
-            /* If I took too long, print the laggards next time around. */
-            printLaggards.set(previousLoopNanos != loopNanos);
+
             /* Loop impatiently waiting for threads to exit. */
             Thread.yield();
         }
@@ -1175,14 +1164,15 @@ public void operate() {
      * holding the {@link VMThreads#THREAD_MUTEX}.
      */
     private static class CheckReadyForTearDownOperation extends JavaVMOperation {
-        private final Log trace;
-        private final AtomicBoolean printLaggards;
+        private boolean printLaggards;
         private boolean readyForTearDown;
 
-        CheckReadyForTearDownOperation(Log trace, AtomicBoolean printLaggards) {
+        CheckReadyForTearDownOperation() {
             super(VMOperationInfos.get(CheckReadyForTearDownOperation.class, "Check ready for teardown", SystemEffect.NONE));
-            this.trace = trace;
-            this.printLaggards = printLaggards;
+        }
+
+        void enablePrintLaggards() {
+            printLaggards = true;
         }
 
         boolean isReadyForTearDown() {
@@ -1191,47 +1181,82 @@ boolean isReadyForTearDown() {
 
         @Override
         public void operate() {
-            int attachedCount = 0;
-            int unattachedStartedCount;
             VMMutex lock = VMThreads.THREAD_MUTEX.lock();
             try {
-                for (IsolateThread isolateThread = VMThreads.firstThread(); isolateThread.isNonNull(); isolateThread = VMThreads.nextThread(isolateThread)) {
-                    if (isVMInternalThread(isolateThread)) {
-                        continue;
-                    }
+                readyForTearDown = isReadyForTeardown();
+            } finally {
+                lock.unlock();
+            }
+        }
 
-                    attachedCount++;
-                    if (printLaggards.get() && trace.isEnabled() && isolateThread != queuingThread) {
-                        trace.string("  laggard isolateThread: ").hex(isolateThread);
-                        final Thread thread = PlatformThreads.fromVMThread(isolateThread);
-                        if (thread != null) {
-                            final String name = thread.getName();
-                            final Thread.State status = thread.getState();
-                            final boolean interruptedStatus = JavaThreads.isInterrupted(thread);
-                            trace.string("  thread.getName(): ").string(name)
-                                            .string("  interruptedStatus: ").bool(interruptedStatus)
-                                            .string("  getState(): ").string(status.name()).newline();
-                            for (StackTraceElement e : thread.getStackTrace()) {
-                                trace.string(e.toString()).newline();
-                            }
-                        }
-                        trace.newline().flush();
+        private boolean isReadyForTeardown() {
+            int attachedCount = 0;
+            boolean printed = false;
+
+            for (IsolateThread thread = VMThreads.firstThread(); thread.isNonNull(); thread = VMThreads.nextThread(thread)) {
+                if (isVMInternalThread(thread)) {
+                    continue;
+                }
+
+                attachedCount++;
+
+                /* Print some information about slow threads. */
+                if (printLaggards && thread != queuingThread) {
+                    if (!printed) {
+                        printed = true;
+                        Log.log().string("Teardown is taking too long").redent(true);
                     }
+
+                    printThreadInfo(Log.log(), thread);
                 }
+            }
 
-                /*
-                 * Note: our counter for unattached started threads is not guarded by the threads
-                 * mutex and its count could change or have changed within this block. Still, it is
-                 * important that we hold the threads mutex when querying the counter value: a
-                 * thread might start another thread and exit immediately after. By holding the
-                 * threads lock, we prevent the exiting thread from detaching, and/or the starting
-                 * thread from attaching, so we will never consider being ready for tear-down.
-                 */
-                unattachedStartedCount = singleton().unattachedStartedThreads.get();
-            } finally {
-                lock.unlock();
+            if (printed) {
+                Log.log().indent(false);
+            }
+
+            /*
+             * Note: our counter for unattached started threads is not guarded by the threads mutex
+             * and its count could change or have changed within this block. Still, it is important
+             * that we hold the threads mutex when querying the counter value: a thread might start
+             * another thread and exit immediately after. By holding the threads lock, we prevent
+             * the exiting thread from detaching, and/or the starting thread from attaching, so we
+             * will never consider being ready for tear-down.
+             */
+            int unattachedStartedCount = singleton().unattachedStartedThreads.get();
+
+            printLaggards = false;
+            return (attachedCount == 1 && unattachedStartedCount == 0);
+        }
+
+        private static void printThreadInfo(Log log, IsolateThread thread) {
+            log.newline().zhex(thread).spaces(1).string(StatusSupport.getStatusString(thread));
+
+            int safepointBehavior = VMThreads.SafepointBehavior.getSafepointBehaviorVolatile(thread);
+            log.string(" (").string(VMThreads.SafepointBehavior.toString(safepointBehavior)).string(")");
+
+            Thread threadObj = PlatformThreads.fromVMThread(thread);
+            if (threadObj == null) {
+                log.string(" null");
+            } else {
+                log.string(" \"").string(threadObj.getName()).string("\" - ").zhex(Word.objectToUntrackedPointer(threadObj));
+
+                Thread.State status = threadObj.getState();
+                log.string(" (").string(status.name()).string(")");
+
+                if (threadObj.isDaemon()) {
+                    log.string(", daemon");
+                }
+                if (JavaThreads.isInterrupted(threadObj)) {
+                    log.string(", interrupted");
+                }
+            }
+
+            log.indent(true);
+            for (StackTraceElement e : threadObj.getStackTrace()) {
+                log.string(e.toString()).newline();
             }
-            readyForTearDown = (attachedCount == 1 && unattachedStartedCount == 0);
+            log.redent(false);
         }
     }