From de2a5ea44036444dffddddd821677ff35c1aa873 Mon Sep 17 00:00:00 2001 From: Cody Henthorne Date: Thu, 28 May 2026 13:05:22 -0400 Subject: [PATCH] Add internal slow database transaction logging and alerting. --- .../securesms/ApplicationContext.java | 9 ++- .../securesms/database/SQLiteDatabase.java | 72 ++++++++++++++++++ .../SlowTransactionInternalNotifier.kt | 74 +++++++++++++++++++ .../securesms/util/Environment.kt | 1 + 4 files changed, 152 insertions(+), 4 deletions(-) create mode 100644 app/src/main/java/org/thoughtcrime/securesms/database/SlowTransactionInternalNotifier.kt diff --git a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java index a0c82c1e27..38c3b45189 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java +++ b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java @@ -33,8 +33,10 @@ import net.zetetic.database.Logger; import org.conscrypt.ConscryptSignal; import org.greenrobot.eventbus.EventBus; import org.signal.aesgcmprovider.AesGcmProvider; +import org.signal.core.util.AppForegroundObserver; import org.signal.core.util.DiskUtil; import org.signal.core.util.MemoryTracker; +import org.signal.core.util.Util; import org.signal.core.util.concurrent.AnrDetector; import org.signal.core.util.concurrent.SignalExecutors; import org.signal.core.util.logging.AndroidLogger; @@ -51,6 +53,7 @@ import org.thoughtcrime.securesms.backup.v2.BackupRepository; import org.thoughtcrime.securesms.crypto.AttachmentSecretProvider; import org.thoughtcrime.securesms.crypto.DatabaseSecretProvider; import org.thoughtcrime.securesms.database.LogDatabase; +import org.thoughtcrime.securesms.database.SQLiteDatabase; import org.thoughtcrime.securesms.database.SignalDatabase; import org.thoughtcrime.securesms.database.SqlCipherLibraryLoader; import org.thoughtcrime.securesms.dependencies.AppDependencies; @@ -59,6 +62,7 @@ import org.thoughtcrime.securesms.emoji.EmojiSource; import org.thoughtcrime.securesms.emoji.JumboEmoji; import org.thoughtcrime.securesms.gcm.FcmFetchManager; import org.thoughtcrime.securesms.glide.SignalGlideComponents; +import org.thoughtcrime.securesms.jobmanager.impl.SealedSenderConstraint; import org.thoughtcrime.securesms.jobs.AccountConsistencyWorkerJob; import org.thoughtcrime.securesms.jobs.BackupRefreshJob; import org.thoughtcrime.securesms.jobs.BackupSubscriptionCheckJob; @@ -83,7 +87,6 @@ import org.thoughtcrime.securesms.jobs.RefreshSvrCredentialsJob; import org.thoughtcrime.securesms.jobs.RestoreOptimizedMediaJob; import org.thoughtcrime.securesms.jobs.RetrieveProfileJob; import org.thoughtcrime.securesms.jobs.RetrieveRemoteAnnouncementsJob; -import org.thoughtcrime.securesms.jobmanager.impl.SealedSenderConstraint; import org.thoughtcrime.securesms.jobs.StoryOnboardingDownloadJob; import org.thoughtcrime.securesms.keyvalue.KeepMessagesDuration; import org.thoughtcrime.securesms.keyvalue.SignalStore; @@ -107,10 +110,8 @@ import org.thoughtcrime.securesms.service.MessageBackupListener; import org.thoughtcrime.securesms.service.RotateSenderCertificateListener; import org.thoughtcrime.securesms.service.RotateSignedPreKeyListener; import org.thoughtcrime.securesms.service.webrtc.ActiveCallManager; -import org.thoughtcrime.securesms.service.webrtc.CallingAssets; import org.thoughtcrime.securesms.service.webrtc.AndroidTelecomUtil; import org.thoughtcrime.securesms.storage.StorageSyncHelper; -import org.signal.core.util.AppForegroundObserver; import org.thoughtcrime.securesms.util.AppStartup; import org.thoughtcrime.securesms.util.DeviceProperties; import org.thoughtcrime.securesms.util.DynamicTheme; @@ -121,7 +122,6 @@ import org.thoughtcrime.securesms.util.SignalLocalMetrics; import org.thoughtcrime.securesms.util.SignalUncaughtExceptionHandler; import org.thoughtcrime.securesms.util.SqlCipherLogTarget; import org.thoughtcrime.securesms.util.TextSecurePreferences; -import org.signal.core.util.Util; import org.thoughtcrime.securesms.util.VersionTracker; import org.thoughtcrime.securesms.util.dynamiclanguage.DynamicLanguageContextWrapper; import org.whispersystems.signalservice.api.websocket.SignalWebSocket; @@ -510,6 +510,7 @@ public class ApplicationContext extends Application implements AppForegroundObse private void initializeTracer() { if (RemoteConfig.internalUser()) { Tracer.getInstance().setMaxBufferSize(35_000); + SQLiteDatabase.setSlowWriteLoggingEnabled(true); } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/database/SQLiteDatabase.java b/app/src/main/java/org/thoughtcrime/securesms/database/SQLiteDatabase.java index e5ffdfef40..811affd8ea 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/database/SQLiteDatabase.java +++ b/app/src/main/java/org/thoughtcrime/securesms/database/SQLiteDatabase.java @@ -14,6 +14,7 @@ import androidx.sqlite.db.SupportSQLiteQuery; import net.zetetic.database.sqlcipher.SQLiteStatement; import net.zetetic.database.sqlcipher.SQLiteTransactionListener; +import org.signal.core.util.logging.Log; import org.signal.core.util.tracing.Tracer; import java.io.IOException; @@ -25,6 +26,7 @@ import java.util.Locale; import java.util.Map; import java.util.Objects; import java.util.Set; +import java.util.concurrent.TimeUnit; /** * This is a wrapper around {@link net.zetetic.database.sqlcipher.SQLiteDatabase}. There's difficulties @@ -33,6 +35,13 @@ import java.util.Set; */ public class SQLiteDatabase implements SupportSQLiteDatabase { + private static final String TAG = Log.tag(SQLiteDatabase.class); + + private static final long SLOW_WRITE_LOCK_WAIT_MS = TimeUnit.SECONDS.toMillis(3); + private static final long SLOW_TRANSACTION_HOLD_MS = 750; + private static final long SLOW_DIRECT_WRITE_MS = 250; + private static final long SLOW_QUERY_MS = TimeUnit.SECONDS.toMillis(1); + public static final int CONFLICT_ROLLBACK = 1; public static final int CONFLICT_ABORT = 2; public static final int CONFLICT_FAIL = 3; @@ -48,6 +57,9 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { private final net.zetetic.database.sqlcipher.SQLiteDatabase wrapped; private final Tracer tracer; + private static volatile boolean slowWriteLoggingEnabled = false; + + private static final ThreadLocal TRANSACTION_HOLD_START_NS = new ThreadLocal<>(); private static final ThreadLocal> PENDING_POST_SUCCESSFUL_TRANSACTION_TASKS; private static final ThreadLocal> POST_SUCCESSFUL_TRANSACTION_TASKS; @@ -58,6 +70,10 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { PENDING_POST_SUCCESSFUL_TRANSACTION_TASKS.set(new LinkedHashSet<>()); } + public static void setSlowWriteLoggingEnabled(boolean enabled) { + slowWriteLoggingEnabled = enabled; + } + public SQLiteDatabase(net.zetetic.database.sqlcipher.SQLiteDatabase wrapped) { this.wrapped = wrapped; this.tracer = Tracer.getInstance(); @@ -83,7 +99,11 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { } tracer.start(methodName, KEY_QUERY, query); + long startNs = slowWriteLoggingEnabled && locked ? System.nanoTime() : 0L; returnable.run(); + if (slowWriteLoggingEnabled && locked) { + warnIfSlowDirectWrite(methodName, null, query, startNs); + } tracer.end(methodName); if (locked) { @@ -109,11 +129,19 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { } tracer.start(methodName, params); + long startNs = slowWriteLoggingEnabled ? System.nanoTime() : 0L; E result = returnable.run(); if (result instanceof Cursor) { // Triggers filling the window (which is about to be done anyway), but lets us capture that time inside the trace ((Cursor) result).getCount(); } + if (slowWriteLoggingEnabled) { + if (locked) { + warnIfSlowDirectWrite(methodName, table, query, startNs); + } else { + warnIfSlowQuery(methodName, table, query, startNs); + } + } tracer.end(methodName); if (locked) { @@ -292,6 +320,7 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { trace("beginTransaction()", wrapped::beginTransaction); } else { trace("beginTransaction()", () -> { + long waitStartNs = slowWriteLoggingEnabled ? System.nanoTime() : 0L; wrapped.beginTransactionWithListener(new SQLiteTransactionListener() { @Override public void onBegin() { } @@ -310,13 +339,31 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { getPendingPostSuccessfulTransactionTasks().clear(); } }); + if (slowWriteLoggingEnabled) { + long waitMs = (System.nanoTime() - waitStartNs) / 1_000_000L; + if (waitMs >= SLOW_WRITE_LOCK_WAIT_MS) { + Log.w(TAG, "Slow write-lock acquire: waited " + waitMs + "ms to BEGIN", new Throwable()); + } + TRANSACTION_HOLD_START_NS.set(System.nanoTime()); + } }); } } public void endTransaction() { + Long holdStartNs = slowWriteLoggingEnabled ? TRANSACTION_HOLD_START_NS.get() : null; trace("endTransaction()", wrapped::endTransaction); traceLockEnd(); + if (holdStartNs != null && !wrapped.inTransaction()) { + TRANSACTION_HOLD_START_NS.remove(); + if (slowWriteLoggingEnabled) { + long holdMs = (System.nanoTime() - holdStartNs) / 1_000_000L; + if (holdMs >= SLOW_TRANSACTION_HOLD_MS) { + Log.w(TAG, "Slow transaction: held write lock for " + holdMs + "ms", new Throwable()); + SlowTransactionInternalNotifier.onSlowEvent(); + } + } + } Set tasks = getPostSuccessfulTransactionTasks(); for (Runnable r : new HashSet<>(tasks)) { r.run(); @@ -519,6 +566,31 @@ public class SQLiteDatabase implements SupportSQLiteDatabase { wrapped.setLocale(locale); } + private void warnIfSlowDirectWrite(String methodName, String table, String query, long startNs) { + if (!slowWriteLoggingEnabled || wrapped.inTransaction()) { + return; + } + + long elapsedMs = (System.nanoTime() - startNs) / 1_000_000L; + + if (elapsedMs >= SLOW_DIRECT_WRITE_MS) { + Log.w(TAG, "Slow direct write: " + methodName + " on " + table + " took " + elapsedMs + "ms (query=" + query + ")", new Throwable()); + } + } + + private void warnIfSlowQuery(String methodName, String table, String query, long startNs) { + if (!slowWriteLoggingEnabled) { + return; + } + + long elapsedMs = (System.nanoTime() - startNs) / 1_000_000L; + + if (elapsedMs >= SLOW_QUERY_MS) { + Log.w(TAG, "Slow query: " + methodName + " on " + table + " took " + elapsedMs + "ms (query=" + query + ")", new Throwable()); + SlowTransactionInternalNotifier.onSlowEvent(); + } + } + private static class ConvertedTransactionListener implements SQLiteTransactionListener { private final android.database.sqlite.SQLiteTransactionListener listener; diff --git a/app/src/main/java/org/thoughtcrime/securesms/database/SlowTransactionInternalNotifier.kt b/app/src/main/java/org/thoughtcrime/securesms/database/SlowTransactionInternalNotifier.kt new file mode 100644 index 0000000000..bb70dbce7c --- /dev/null +++ b/app/src/main/java/org/thoughtcrime/securesms/database/SlowTransactionInternalNotifier.kt @@ -0,0 +1,74 @@ +/* + * Copyright 2026 Signal Messenger, LLC + * SPDX-License-Identifier: AGPL-3.0-only + */ + +package org.thoughtcrime.securesms.database + +import android.Manifest +import android.app.Notification +import android.app.PendingIntent +import android.content.Intent +import android.content.pm.PackageManager +import androidx.core.app.NotificationCompat +import androidx.core.app.NotificationManagerCompat +import androidx.core.content.ContextCompat +import org.signal.core.util.PendingIntentFlags +import org.thoughtcrime.securesms.R +import org.thoughtcrime.securesms.dependencies.AppDependencies +import org.thoughtcrime.securesms.logsubmit.SubmitDebugLogActivity +import org.thoughtcrime.securesms.notifications.NotificationChannels +import org.thoughtcrime.securesms.notifications.NotificationIds +import org.thoughtcrime.securesms.util.RemoteConfig +import java.util.concurrent.atomic.AtomicInteger +import kotlin.time.Duration +import kotlin.time.Duration.Companion.milliseconds +import kotlin.time.Duration.Companion.minutes + +/** + * Internal-user-only notifier that surfaces SQLite write-lock contention. + */ +object SlowTransactionInternalNotifier { + + private const val THRESHOLD = 5 + + private val NOTIFY_INTERVAL = 30.minutes + + private val count = AtomicInteger(0) + + @Volatile + private var lastNotify: Duration = 0.milliseconds + + @JvmStatic + fun onSlowEvent() { + if (!RemoteConfig.internalUser) { + return + } + + if (count.incrementAndGet() < THRESHOLD) { + return + } + + val now = System.currentTimeMillis().milliseconds + if (lastNotify + NOTIFY_INTERVAL > now) { + return + } + + val context = AppDependencies.application + if (ContextCompat.checkSelfPermission(context, Manifest.permission.POST_NOTIFICATIONS) != PackageManager.PERMISSION_GRANTED) { + return + } + + val observed = count.getAndSet(0) + lastNotify = now + + val notification: Notification = NotificationCompat.Builder(context, NotificationChannels.getInstance().FAILURES) + .setSmallIcon(R.drawable.ic_notification) + .setContentTitle("[Internal-only] Slow database activity") + .setContentText("$observed slow database operations (transactions/queries) observed. Please tap to get a debug log.") + .setContentIntent(PendingIntent.getActivity(context, 0, Intent(context, SubmitDebugLogActivity::class.java), PendingIntentFlags.mutable())) + .build() + + NotificationManagerCompat.from(context).notify(NotificationIds.INTERNAL_ERROR, notification) + } +} diff --git a/app/src/main/java/org/thoughtcrime/securesms/util/Environment.kt b/app/src/main/java/org/thoughtcrime/securesms/util/Environment.kt index 2356210df5..14dca0ce35 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/util/Environment.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/util/Environment.kt @@ -17,6 +17,7 @@ object Environment { @JvmField var IS_INSTRUMENTATION: Boolean = IS_BENCHMARK + @JvmStatic fun isInternal(): Boolean { return !IS_INSTRUMENTATION && (BuildConfig.DEBUG || IS_NIGHTLY || IS_PERF || IS_STAGING) }