From ebf2ef65e219b1109e5b70eec6aa6f934c4fdecb Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Wed, 27 Apr 2022 10:30:30 -0400 Subject: [PATCH] Add log section for the last thread dump during a possible deadlock. --- .../logsubmit/LogSectionBlockedThreads.java | 37 -------------- .../logsubmit/LogSectionThreadDump.java | 51 +++++++++++++++++++ .../logsubmit/SubmitDebugLogRepository.java | 2 +- .../core/util/concurrent/DeadlockDetector.kt | 20 ++++++-- 4 files changed, 69 insertions(+), 41 deletions(-) delete mode 100644 app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBlockedThreads.java create mode 100644 app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionThreadDump.java diff --git a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBlockedThreads.java b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBlockedThreads.java deleted file mode 100644 index d2860a987..000000000 --- a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBlockedThreads.java +++ /dev/null @@ -1,37 +0,0 @@ -package org.thoughtcrime.securesms.logsubmit; - -import android.content.Context; - -import androidx.annotation.NonNull; - -import java.util.Map; - -public class LogSectionBlockedThreads implements LogSection { - - @Override - public @NonNull String getTitle() { - return "BLOCKED THREADS"; - } - - @Override - public @NonNull CharSequence getContent(@NonNull Context context) { - Map traces = Thread.getAllStackTraces(); - StringBuilder out = new StringBuilder(); - - for (Map.Entry entry : traces.entrySet()) { - if (entry.getKey().getState() == Thread.State.BLOCKED) { - Thread thread = entry.getKey(); - out.append("-- [").append(thread.getId()).append("] ") - .append(thread.getName()).append(" (").append(thread.getState().toString()).append(")\n"); - - for (StackTraceElement element : entry.getValue()) { - out.append(element.toString()).append("\n"); - } - - out.append("\n"); - } - } - - return out.length() == 0 ? "None" : out; - } -} diff --git a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionThreadDump.java b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionThreadDump.java new file mode 100644 index 000000000..b4137e417 --- /dev/null +++ b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionThreadDump.java @@ -0,0 +1,51 @@ +package org.thoughtcrime.securesms.logsubmit; + +import android.content.Context; + +import androidx.annotation.NonNull; + +import org.signal.core.util.concurrent.DeadlockDetector; +import org.thoughtcrime.securesms.dependencies.ApplicationDependencies; + +import java.text.SimpleDateFormat; +import java.util.Date; +import java.util.Locale; +import java.util.Map; + +public class LogSectionThreadDump implements LogSection { + + private static final SimpleDateFormat DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS zzz", Locale.US); + + @Override + public @NonNull String getTitle() { + return "LAST THREAD DUMP"; + } + + @Override + public @NonNull CharSequence getContent(@NonNull Context context) { + Map traces = ApplicationDependencies.getDeadlockDetector().getLastThreadDump(); + long time = ApplicationDependencies.getDeadlockDetector().getLastThreadDumpTime(); + + if (traces == null) { + return "None"; + } + + StringBuilder out = new StringBuilder(); + + out.append("Time: ").append(DATE_FORMAT.format(new Date(time))).append(" (").append(time).append(")\n\n"); + + for (Map.Entry entry : traces.entrySet()) { + Thread thread = entry.getKey(); + out.append("-- [").append(thread.getId()).append("] ") + .append(thread.getName()).append(" (").append(thread.getState()).append(")\n"); + + for (StackTraceElement element : entry.getValue()) { + out.append(element.toString()).append("\n"); + } + + out.append("\n"); + } + + return out; + } +} diff --git a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java index f5f1ed217..d98ddaeff 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java +++ b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java @@ -83,7 +83,7 @@ public class SubmitDebugLogRepository { add(new LogSectionPermissions()); add(new LogSectionTrace()); add(new LogSectionThreads()); - add(new LogSectionBlockedThreads()); + add(new LogSectionThreadDump()); if (FeatureFlags.internalUser()) { add(new LogSectionSenderKey()); } 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 2a3dc6209..a9f381d2e 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 @@ -12,6 +12,13 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval private var running = false private val previouslyBlocked: MutableSet = mutableSetOf() + private val waitingStates: Set = setOf(Thread.State.WAITING, Thread.State.TIMED_WAITING) + + @Volatile + var lastThreadDump: Map>? = null + + @Volatile + var lastThreadDumpTime: Long = -1 fun start() { Log.d(TAG, "Beginning deadlock monitoring."); @@ -26,21 +33,24 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval } private fun poll() { + val time: Long = System.currentTimeMillis() val threads: Map> = Thread.getAllStackTraces() val blocked: Map> = threads .filter { entry -> val thread: Thread = entry.key val stack: Array = entry.value - thread.state == Thread.State.BLOCKED || (thread.state == Thread.State.WAITING && stack.any { it.methodName.startsWith("lock") }) + thread.state == Thread.State.BLOCKED || (waitingStates.contains(thread.state) && stack.any { it.methodName.startsWith("lock") || it.methodName.startsWith("waitForConnection") }) } - .filter { entry -> !BLOCK_BLACKLIST.contains(entry.key.name) } + .filter { entry -> !BLOCK_BLOCKLIST.contains(entry.key.name) } val blockedIds: Set = blocked.keys.map(Thread::getId).toSet() val stillBlocked: Set = blockedIds.intersect(previouslyBlocked) if (blocked.size > 1) { Log.w(TAG, buildLogString("Found multiple blocked threads! Possible deadlock.", blocked)) + lastThreadDump = threads + lastThreadDumpTime = time } else if (stillBlocked.isNotEmpty()) { val stillBlockedMap: Map> = stillBlocked .map { blockedId -> @@ -51,6 +61,8 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval .toMap() Log.w(TAG, buildLogString("Found a long block! Blocked for at least $pollingInterval ms.", stillBlockedMap)) + lastThreadDump = threads + lastThreadDumpTime = time } val fullExecutors: List = CHECK_FULLNESS_EXECUTORS.filter { isExecutorFull(it.executor) } @@ -64,6 +76,8 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval 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)) } + lastThreadDump = threads + lastThreadDumpTime = time } previouslyBlocked.clear() @@ -89,7 +103,7 @@ class DeadlockDetector(private val handler: Handler, private val pollingInterval private const val CONCERNING_QUEUE_THRESHOLD = 4 - private val BLOCK_BLACKLIST = setOf("HeapTaskDaemon") + private val BLOCK_BLOCKLIST = setOf("HeapTaskDaemon") private fun buildLogString(description: String, blocked: Map>): String { val stringBuilder = StringBuilder()