Show inferred stack traces when logging blocked threads.

This commit is contained in:
Greyson Parrelli 2021-11-03 14:22:53 -04:00
parent 49270e677e
commit 8af8468f4d
5 changed files with 83 additions and 26 deletions

View file

@ -29,8 +29,15 @@ public final class ExceptionUtil {
* @return The provided original exception, for convenience. * @return The provided original exception, for convenience.
*/ */
public static <E extends Throwable> E joinStackTrace(@NonNull E original, @NonNull Throwable inferred) { public static <E extends Throwable> E joinStackTrace(@NonNull E original, @NonNull Throwable inferred) {
StackTraceElement[] originalTrace = original.getStackTrace(); StackTraceElement[] combinedTrace = joinStackTrace(original.getStackTrace(), inferred.getStackTrace());
StackTraceElement[] inferredTrace = 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]; StackTraceElement[] combinedTrace = new StackTraceElement[originalTrace.length + inferredTrace.length + 2];
System.arraycopy(originalTrace, 0, combinedTrace, 0, originalTrace.length); 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); System.arraycopy(inferredTrace, 0, combinedTrace, originalTrace.length + 2, inferredTrace.length);
original.setStackTrace(combinedTrace); return combinedTrace;
return original;
} }
public static @NonNull String convertThrowableToString(@NonNull Throwable throwable) { public static @NonNull String convertThrowableToString(@NonNull Throwable throwable) {

View file

@ -1,9 +1,9 @@
package org.signal.core.util.concurrent package org.signal.core.util.concurrent
import android.os.Handler import android.os.Handler
import org.signal.core.util.ExceptionUtil
import org.signal.core.util.logging.Log import org.signal.core.util.logging.Log
import java.util.concurrent.ExecutorService 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. * 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)) Log.w(TAG, buildLogString("Found a long block! Blocked for at least $pollingInterval ms.", stillBlockedMap))
} }
val fullExecutors: List<ExecutorInfo> = EXECUTORS.filter { isExecutorFull(it.executor) } val fullExecutors: List<ExecutorInfo> = CHECK_FULLNESS_EXECUTORS.filter { isExecutorFull(it.executor) }
if (fullExecutors.isNotEmpty()) { if (fullExecutors.isNotEmpty()) {
fullExecutors.forEach { executorInfo -> fullExecutors.forEach { executorInfo ->
@ -61,15 +61,8 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval
.filter { it.key.name.startsWith(executorInfo.namePrefix) } .filter { it.key.name.startsWith(executorInfo.namePrefix) }
.toMap() .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)) 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 { companion object {
private val TAG = Log.tag(DeadlockDetector::class.java) private val TAG = Log.tag(DeadlockDetector::class.java)
private val EXECUTORS: Set<ExecutorInfo> = setOf( private val CHECK_FULLNESS_EXECUTORS: Set<ExecutorInfo> = setOf(
ExecutorInfo(SignalExecutors.BOUNDED, "signal-bounded-"), ExecutorInfo(SignalExecutors.BOUNDED, "signal-bounded-"),
ExecutorInfo(SignalExecutors.BOUNDED_IO, "signal-io-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) { for (entry in blocked) {
stringBuilder.append("-- [${entry.key.id}] ${entry.key.name} | ${entry.key.state}\n") 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<StackTraceElement> = if (callerThrowable != null) {
ExceptionUtil.joinStackTrace(entry.value, callerThrowable.stackTrace)
} else {
entry.value
}
for (element in stackTrace) {
stringBuilder.append("$element\n") stringBuilder.append("$element\n")
} }
@ -116,7 +117,7 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval
} }
private fun isExecutorFull(executor: ExecutorService): Boolean { private fun isExecutorFull(executor: ExecutorService): Boolean {
return if (executor is ThreadPoolExecutor) { return if (executor is TracingExecutorService) {
executor.queue.size > CONCERNING_QUEUE_THRESHOLD executor.queue.size > CONCERNING_QUEUE_THRESHOLD
} else { } else {
false false

View file

@ -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<Long, Throwable> = ConcurrentHashMap()
}

View file

@ -11,12 +11,18 @@ internal class TracingExecutor(val wrapped: Executor) : Executor by wrapped {
val callerStackTrace = Throwable() val callerStackTrace = Throwable()
wrapped.execute { 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 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)
}
} }
} }
} }

View file

@ -1,6 +1,9 @@
package org.signal.core.util.concurrent package org.signal.core.util.concurrent
import java.util.Queue
import java.util.concurrent.ExecutorService 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. * 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() val callerStackTrace = Throwable()
wrapped.execute { 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 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)
}
} }
} }
val queue: Queue<Runnable>
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
}
} }