Add internal slow database transaction logging and alerting.

This commit is contained in:
Cody Henthorne
2026-05-28 13:05:22 -04:00
committed by Michelle Tang
parent a54d62c09d
commit de2a5ea440
4 changed files with 152 additions and 4 deletions
@@ -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);
}
}
@@ -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<Long> TRANSACTION_HOLD_START_NS = new ThreadLocal<>();
private static final ThreadLocal<Set<Runnable>> PENDING_POST_SUCCESSFUL_TRANSACTION_TASKS;
private static final ThreadLocal<Set<Runnable>> 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<Runnable> 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;
@@ -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)
}
}
@@ -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)
}