From 8af8468f4d9c6220595a6a813d9d27926ec10b87 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Wed, 3 Nov 2021 14:22:53 -0400 Subject: [PATCH] Show inferred stack traces when logging blocked threads. --- .../org/signal/core/util/ExceptionUtil.java | 15 ++++--- .../core/util/concurrent/DeadlockDetector.kt | 27 ++++++------ .../core/util/concurrent/TracedThreads.kt | 12 ++++++ .../core/util/concurrent/TracingExecutor.kt | 14 +++++-- .../util/concurrent/TracingExecutorService.kt | 41 +++++++++++++++++-- 5 files changed, 83 insertions(+), 26 deletions(-) create mode 100644 core-util/src/main/java/org/signal/core/util/concurrent/TracedThreads.kt diff --git a/core-util/src/main/java/org/signal/core/util/ExceptionUtil.java b/core-util/src/main/java/org/signal/core/util/ExceptionUtil.java index d759ec28d9..2bdd70721f 100644 --- a/core-util/src/main/java/org/signal/core/util/ExceptionUtil.java +++ b/core-util/src/main/java/org/signal/core/util/ExceptionUtil.java @@ -29,8 +29,15 @@ public final class ExceptionUtil { * @return The provided original exception, for convenience. */ public static E joinStackTrace(@NonNull E original, @NonNull Throwable inferred) { - StackTraceElement[] originalTrace = original.getStackTrace(); - StackTraceElement[] inferredTrace = inferred.getStackTrace(); + StackTraceElement[] combinedTrace = joinStackTrace(original.getStackTrace(), inferred.getStackTrace()); + original.setStackTrace(combinedTrace); + return original; + } + + /** + * See {@link #joinStackTrace(Throwable, Throwable)} + */ + public static StackTraceElement[] joinStackTrace(@NonNull StackTraceElement[] originalTrace, @NonNull StackTraceElement[] inferredTrace) { StackTraceElement[] combinedTrace = new StackTraceElement[originalTrace.length + inferredTrace.length + 2]; System.arraycopy(originalTrace, 0, combinedTrace, 0, originalTrace.length); @@ -40,9 +47,7 @@ public final class ExceptionUtil { System.arraycopy(inferredTrace, 0, combinedTrace, originalTrace.length + 2, inferredTrace.length); - original.setStackTrace(combinedTrace); - - return original; + return combinedTrace; } public static @NonNull String convertThrowableToString(@NonNull Throwable throwable) { diff --git a/core-util/src/main/java/org/signal/core/util/concurrent/DeadlockDetector.kt b/core-util/src/main/java/org/signal/core/util/concurrent/DeadlockDetector.kt index 2921a9b997..2a3dc6209a 100644 --- a/core-util/src/main/java/org/signal/core/util/concurrent/DeadlockDetector.kt +++ b/core-util/src/main/java/org/signal/core/util/concurrent/DeadlockDetector.kt @@ -1,9 +1,9 @@ package org.signal.core.util.concurrent import android.os.Handler +import org.signal.core.util.ExceptionUtil import org.signal.core.util.logging.Log import java.util.concurrent.ExecutorService -import java.util.concurrent.ThreadPoolExecutor /** * A class that polls active threads at a set interval and logs when multiple threads are BLOCKED. @@ -53,7 +53,7 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval Log.w(TAG, buildLogString("Found a long block! Blocked for at least $pollingInterval ms.", stillBlockedMap)) } - val fullExecutors: List = EXECUTORS.filter { isExecutorFull(it.executor) } + val fullExecutors: List = CHECK_FULLNESS_EXECUTORS.filter { isExecutorFull(it.executor) } if (fullExecutors.isNotEmpty()) { fullExecutors.forEach { executorInfo -> @@ -61,15 +61,8 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval .filter { it.key.name.startsWith(executorInfo.namePrefix) } .toMap() - val executor: ThreadPoolExecutor = executorInfo.executor as ThreadPoolExecutor + val executor: TracingExecutorService = executorInfo.executor as TracingExecutorService Log.w(TAG, buildLogString("Found a full executor! ${executor.activeCount}/${executor.maximumPoolSize} threads active with ${executor.queue.size} tasks queued.", fullMap)) - - val runnableStringBuilder = StringBuilder() - executor.queue.forEach { runnable -> - runnableStringBuilder.append(runnable.toString()).append("\n") - } - - Log.w(TAG, "Queue:\n${runnableStringBuilder}") } } @@ -89,7 +82,7 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval companion object { private val TAG = Log.tag(DeadlockDetector::class.java) - private val EXECUTORS: Set = setOf( + private val CHECK_FULLNESS_EXECUTORS: Set = setOf( ExecutorInfo(SignalExecutors.BOUNDED, "signal-bounded-"), ExecutorInfo(SignalExecutors.BOUNDED_IO, "signal-io-bounded") ) @@ -105,7 +98,15 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval for (entry in blocked) { stringBuilder.append("-- [${entry.key.id}] ${entry.key.name} | ${entry.key.state}\n") - for (element in entry.value) { + + val callerThrowable: Throwable? = TracedThreads.callerStackTraces[entry.key.id] + val stackTrace: Array = if (callerThrowable != null) { + ExceptionUtil.joinStackTrace(entry.value, callerThrowable.stackTrace) + } else { + entry.value + } + + for (element in stackTrace) { stringBuilder.append("$element\n") } @@ -116,7 +117,7 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval } private fun isExecutorFull(executor: ExecutorService): Boolean { - return if (executor is ThreadPoolExecutor) { + return if (executor is TracingExecutorService) { executor.queue.size > CONCERNING_QUEUE_THRESHOLD } else { false diff --git a/core-util/src/main/java/org/signal/core/util/concurrent/TracedThreads.kt b/core-util/src/main/java/org/signal/core/util/concurrent/TracedThreads.kt new file mode 100644 index 0000000000..8306d960bd --- /dev/null +++ b/core-util/src/main/java/org/signal/core/util/concurrent/TracedThreads.kt @@ -0,0 +1,12 @@ +package org.signal.core.util.concurrent + +import java.util.concurrent.ConcurrentHashMap + +/** + * A container for keeping track of the caller stack traces of the threads we care about. + * + * Note: This should only be used for debugging. To keep overhead minimal, not much effort has been put into ensuring this map is 100% accurate. + */ +internal object TracedThreads { + val callerStackTraces: MutableMap = ConcurrentHashMap() +} diff --git a/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutor.kt b/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutor.kt index 324001b538..1675888e0c 100644 --- a/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutor.kt +++ b/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutor.kt @@ -11,12 +11,18 @@ internal class TracingExecutor(val wrapped: Executor) : Executor by wrapped { val callerStackTrace = Throwable() wrapped.execute { - val currentHandler: Thread.UncaughtExceptionHandler? = Thread.currentThread().uncaughtExceptionHandler + val currentThread: Thread = Thread.currentThread() + val currentHandler: Thread.UncaughtExceptionHandler? = currentThread.uncaughtExceptionHandler val originalHandler: Thread.UncaughtExceptionHandler? = if (currentHandler is TracingUncaughtExceptionHandler) currentHandler.originalHandler else currentHandler - Thread.currentThread().uncaughtExceptionHandler = TracingUncaughtExceptionHandler(originalHandler, callerStackTrace) + currentThread.uncaughtExceptionHandler = TracingUncaughtExceptionHandler(originalHandler, callerStackTrace) - command?.run() + TracedThreads.callerStackTraces.put(currentThread.id, callerStackTrace) + try { + command?.run() + } finally { + TracedThreads.callerStackTraces.remove(currentThread.id) + } } } -} \ No newline at end of file +} diff --git a/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutorService.kt b/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutorService.kt index 44c6ebfde0..b4ed4e9f03 100644 --- a/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutorService.kt +++ b/core-util/src/main/java/org/signal/core/util/concurrent/TracingExecutorService.kt @@ -1,6 +1,9 @@ package org.signal.core.util.concurrent +import java.util.Queue import java.util.concurrent.ExecutorService +import java.util.concurrent.LinkedBlockingQueue +import java.util.concurrent.ThreadPoolExecutor /** * An executor that will keep track of the stack trace at the time of calling [execute] and use that to build a more useful stack trace in the event of a crash. @@ -11,12 +14,42 @@ internal class TracingExecutorService(val wrapped: ExecutorService) : ExecutorSe val callerStackTrace = Throwable() wrapped.execute { - val currentHandler: Thread.UncaughtExceptionHandler? = Thread.currentThread().uncaughtExceptionHandler + val currentThread: Thread = Thread.currentThread() + val currentHandler: Thread.UncaughtExceptionHandler? = currentThread.uncaughtExceptionHandler val originalHandler: Thread.UncaughtExceptionHandler? = if (currentHandler is TracingUncaughtExceptionHandler) currentHandler.originalHandler else currentHandler - Thread.currentThread().uncaughtExceptionHandler = TracingUncaughtExceptionHandler(originalHandler, callerStackTrace) + currentThread.uncaughtExceptionHandler = TracingUncaughtExceptionHandler(originalHandler, callerStackTrace) - command?.run() + TracedThreads.callerStackTraces.put(currentThread.id, callerStackTrace) + try { + command?.run() + } finally { + TracedThreads.callerStackTraces.remove(currentThread.id) + } } } -} \ No newline at end of file + + val queue: Queue + get() { + return if (wrapped is ThreadPoolExecutor) + wrapped.queue + else + LinkedBlockingQueue() + } + + val activeCount: Int + get() { + return if (wrapped is ThreadPoolExecutor) + wrapped.activeCount + else + 0 + } + + val maximumPoolSize: Int + get() { + return if (wrapped is ThreadPoolExecutor) + wrapped.maximumPoolSize + else + 0 + } +}