Repository: reef Updated Branches: refs/heads/master 17ef67734 -> 1a7c6d1d3
[REEF-1656] Implement proper logging of threads still running at the end of the REEF process This work is towards proper job shutdown for "REEF as a library" [REEF-1561](https://issues.apache.org/jira/browse/REEF-1561) project * Use `ThreadLogger` for all thread logging and remove duplicate code * sort threads in log by name and thread group * Print thread group, status, activity, and other info * minor fixes in logging JIRA: [REEF-1656](https://issues.apache.org/jira/browse/REEF-1656) Pull Request: This closes #1171 Project: http://git-wip-us.apache.org/repos/asf/reef/repo Commit: http://git-wip-us.apache.org/repos/asf/reef/commit/1a7c6d1d Tree: http://git-wip-us.apache.org/repos/asf/reef/tree/1a7c6d1d Diff: http://git-wip-us.apache.org/repos/asf/reef/diff/1a7c6d1d Branch: refs/heads/master Commit: 1a7c6d1d3caeabd34cac8f9ba430a8990f574f4e Parents: 17ef677 Author: Sergiy Matusevych <[email protected]> Authored: Thu Oct 27 16:02:57 2016 -0700 Committer: Markus Weimer <[email protected]> Committed: Fri Oct 28 15:28:20 2016 -0700 ---------------------------------------------------------------------- .../reef/runtime/common/REEFEnvironment.java | 9 ++++-- .../reef/runtime/common/REEFLauncher.java | 8 +----- .../java/org/apache/reef/util/ThreadLogger.java | 30 +++++++++++++++++--- .../reef/wake/time/runtime/RuntimeClock.java | 22 +------------- 4 files changed, 35 insertions(+), 34 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/reef/blob/1a7c6d1d/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFEnvironment.java ---------------------------------------------------------------------- diff --git a/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFEnvironment.java b/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFEnvironment.java index b997347..ceeb4d1 100644 --- a/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFEnvironment.java +++ b/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFEnvironment.java @@ -31,6 +31,7 @@ import org.apache.reef.tang.annotations.NamedParameter; import org.apache.reef.tang.exceptions.InjectionException; import org.apache.reef.util.EnvironmentUtils; import org.apache.reef.util.REEFVersion; +import org.apache.reef.util.ThreadLogger; import org.apache.reef.wake.profiler.WakeProfiler; import org.apache.reef.wake.time.Clock; @@ -53,6 +54,8 @@ public final class REEFEnvironment implements Runnable, AutoCloseable { private static final Logger LOG = Logger.getLogger(REEFEnvironment.class.getName()); + private static final String CLASS_NAME = REEFEnvironment.class.getCanonicalName(); + private static final Tang TANG = Tang.Factory.getTang(); /** Main event loop of current REEF component (Driver or Evaluator). */ @@ -131,7 +134,7 @@ public final class REEFEnvironment implements Runnable, AutoCloseable { @SuppressWarnings("checkstyle:illegalcatch") // Catch throwable to feed it to error handler public void close() { - LOG.log(Level.FINER, "Closing REEF Environment - start"); + LOG.entering(CLASS_NAME, "close"); try { this.clock.close(); @@ -150,7 +153,9 @@ public final class REEFEnvironment implements Runnable, AutoCloseable { } } - LOG.log(Level.FINER, "Closing REEF Environment - end"); + ThreadLogger.logThreads(LOG, Level.FINEST, "Threads running after REEFEnvironment.close():"); + + LOG.exiting(CLASS_NAME, "close"); } /** http://git-wip-us.apache.org/repos/asf/reef/blob/1a7c6d1d/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFLauncher.java ---------------------------------------------------------------------- diff --git a/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFLauncher.java b/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFLauncher.java index 74de099..0b542e3 100644 --- a/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFLauncher.java +++ b/lang/java/reef-common/src/main/java/org/apache/reef/runtime/common/REEFLauncher.java @@ -185,15 +185,9 @@ public final class REEFLauncher { LOG.log(Level.INFO, "Exiting REEFLauncher.main()"); - if (LOG.isLoggable(Level.FINEST)) { - LOG.log(Level.FINEST, ThreadLogger.getFormattedThreadList("Threads running after REEFLauncher.close():")); - } - System.exit(0); - if (LOG.isLoggable(Level.FINEST)) { - LOG.log(Level.FINEST, ThreadLogger.getFormattedThreadList("Threads running after System.exit():")); - } + ThreadLogger.logThreads(LOG, Level.FINEST, "Threads running after System.exit():"); } /** http://git-wip-us.apache.org/repos/asf/reef/blob/1a7c6d1d/lang/java/reef-common/src/main/java/org/apache/reef/util/ThreadLogger.java ---------------------------------------------------------------------- diff --git a/lang/java/reef-common/src/main/java/org/apache/reef/util/ThreadLogger.java b/lang/java/reef-common/src/main/java/org/apache/reef/util/ThreadLogger.java index 104b468..1e4a790 100644 --- a/lang/java/reef-common/src/main/java/org/apache/reef/util/ThreadLogger.java +++ b/lang/java/reef-common/src/main/java/org/apache/reef/util/ThreadLogger.java @@ -22,6 +22,7 @@ import java.lang.management.LockInfo; import java.lang.management.MonitorInfo; import java.lang.management.ThreadInfo; import java.util.Map; +import java.util.TreeMap; import java.util.logging.Level; import java.util.logging.Logger; @@ -56,7 +57,10 @@ public final class ThreadLogger { public static void logThreads( final Logger logger, final Level level, final String prefix, final String threadPrefix, final String stackElementPrefix) { - logger.log(level, getFormattedThreadList(prefix, threadPrefix, stackElementPrefix)); + + if (logger.isLoggable(level)) { + logger.log(level, getFormattedThreadList(prefix, threadPrefix, stackElementPrefix)); + } } /** @@ -69,13 +73,31 @@ public final class ThreadLogger { */ public static String getFormattedThreadList( final String prefix, final String threadPrefix, final String stackElementPrefix) { - final StringBuilder message = new StringBuilder(prefix); + + // Sort by thread name + final TreeMap<String, StackTraceElement[]> threadNames = new TreeMap<>(); for (final Map.Entry<Thread, StackTraceElement[]> entry : Thread.getAllStackTraces().entrySet()) { - message.append(threadPrefix).append("Thread '").append(entry.getKey().getName()).append("':"); + + final Thread t = entry.getKey(); + final String tg = t.getThreadGroup() == null ? null : t.getThreadGroup().getName(); + + if (!"system".equals(tg)) { + threadNames.put(String.format("TG %s THREAD %s :: %s, %s, %s, %s", + tg, t.getName(), t.getState(), + t.isAlive() ? "Alive" : "NOT alive", + t.isInterrupted() ? "Interrupted" : "NOT interrupted", + t.isDaemon() ? "Daemon" : "NOT daemon"), entry.getValue()); + } + } + + final StringBuilder message = new StringBuilder(prefix); + for (final Map.Entry<String, StackTraceElement[]> entry : threadNames.entrySet()) { + message.append(threadPrefix).append(entry.getKey()); for (final StackTraceElement element : entry.getValue()) { - message.append(stackElementPrefix).append(element.toString()); + message.append(stackElementPrefix).append(element); } } + return message.toString(); } http://git-wip-us.apache.org/repos/asf/reef/blob/1a7c6d1d/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java ---------------------------------------------------------------------- diff --git a/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java b/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java index 523bce3..238e7bb 100644 --- a/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java +++ b/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java @@ -212,7 +212,7 @@ public final class RuntimeClock implements Clock { synchronized (this.schedule) { if (this.isClosed) { - LOG.log(Level.FINEST, "Clock has already been closed"); + LOG.exiting(CLASS_NAME, "close", "Clock has already been closed"); return; } @@ -270,24 +270,6 @@ public final class RuntimeClock implements Clock { } /** - * Logs the currently running threads. - * @param level Log level used to write the entry. - * @param prefix put before the comma-separated list of threads - */ - private static void logThreads(final Level level, final String prefix) { - - if (LOG.isLoggable(level)) { - - final StringBuilder sb = new StringBuilder(prefix); - for (final Thread t : Thread.getAllStackTraces().keySet()) { - sb.append(t.getName()).append(", "); - } - - LOG.log(level, sb.toString()); - } - } - - /** * Main event loop. * Set up the event handlers, and go into event loop that polls the schedule and process events in it. */ @@ -382,8 +364,6 @@ public final class RuntimeClock implements Clock { this.handlers.onNext(new RuntimeStop(this.timer.getCurrent(), e)); } finally { - - logThreads(Level.FINE, "Threads running after exiting the clock main loop: "); LOG.log(Level.FINE, "Runtime clock exit"); }
