From d636ef8ec9e821966906afa1d2343ffeefd82188 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Fri, 15 Aug 2025 16:05:53 -0400 Subject: [PATCH] Add debug logging for attachment restore speeds. --- .../securesms/backup/ArchiveUploadProgress.kt | 18 ++-- .../backup/v2/ArchiveRestoreProgress.kt | 87 +++++++++++++++++++ .../securesms/jobs/BackupRestoreMediaJob.kt | 3 + .../jobs/CheckRestoreMediaLeftJob.kt | 14 +-- .../securesms/jobs/RestoreAttachmentJob.kt | 7 ++ .../securesms/util/SignalLocalMetrics.java | 17 ++++ 6 files changed, 133 insertions(+), 13 deletions(-) create mode 100644 app/src/main/java/org/thoughtcrime/securesms/backup/v2/ArchiveRestoreProgress.kt diff --git a/app/src/main/java/org/thoughtcrime/securesms/backup/ArchiveUploadProgress.kt b/app/src/main/java/org/thoughtcrime/securesms/backup/ArchiveUploadProgress.kt index b8fe2d3ec7..2af3b4ceef 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/backup/ArchiveUploadProgress.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/backup/ArchiveUploadProgress.kt @@ -32,6 +32,8 @@ import org.thoughtcrime.securesms.keyvalue.protos.ArchiveUploadProgressState import org.thoughtcrime.securesms.util.SignalLocalMetrics import org.whispersystems.signalservice.api.messages.AttachmentTransferProgress import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicLong import kotlin.math.max import kotlin.time.Duration.Companion.milliseconds import kotlin.time.Duration.Companion.seconds @@ -55,8 +57,8 @@ object ArchiveUploadProgress { private val attachmentProgress: MutableMap = ConcurrentHashMap() private var debugAttachmentStartTime: Long = 0 - private var debugTotalAttachments: Int = 0 - private var debugTotalBytes: Long = 0 + private val debugTotalAttachments: AtomicInteger = AtomicInteger(0) + private val debugTotalBytes: AtomicLong = AtomicLong(0) /** * Observe this to get updates on the current upload progress. @@ -80,7 +82,7 @@ object ArchiveUploadProgress { val pendingMediaUploadBytes = SignalDatabase.attachments.getPendingArchiveUploadBytes() - attachmentProgress.values.sumOf { it.bytesUploaded } if (pendingMediaUploadBytes <= 0) { Log.i(TAG, "No more pending bytes. Done!") - Log.d(TAG, buildDebugStats(debugAttachmentStartTime, debugTotalAttachments, debugTotalBytes)) + Log.d(TAG, "Upload finished! " + buildDebugStats(debugAttachmentStartTime, debugTotalAttachments.get(), debugTotalBytes.get())) return@map PROGRESS_NONE } @@ -188,13 +190,13 @@ object ArchiveUploadProgress { fun onAttachmentFinished(attachmentId: AttachmentId) { SignalLocalMetrics.ArchiveAttachmentUpload.end(attachmentId) - debugTotalAttachments++ + debugTotalAttachments.incrementAndGet() attachmentProgress[attachmentId]?.let { if (BuildConfig.DEBUG) { - Log.d(TAG, "Attachment finished: $it") + Log.d(TAG, "Attachment uploaded: $it") } - debugTotalBytes += it.totalBytes + debugTotalBytes.addAndGet(it.totalBytes) } attachmentProgress.remove(attachmentId) _progress.tryEmit(Unit) @@ -292,7 +294,7 @@ object ArchiveUploadProgress { } private fun buildDebugStats(startTimeMs: Long, totalAttachments: Int, totalBytes: Long): String { - if (debugAttachmentStartTime <= 0 || debugTotalAttachments <= 0 || debugTotalBytes <= 0) { + if (startTimeMs <= 0 || totalAttachments <= 0 || totalBytes <= 0) { return "Insufficient data to print debug stats." } @@ -313,7 +315,7 @@ object ArchiveUploadProgress { } val seconds: Double = (System.currentTimeMillis() - startTimeMs).milliseconds.toDouble(DurationUnit.SECONDS) - val bytesPerSecond: Long = (bytesUploaded / seconds).toLong() + val bytesPerSecond: Long = (totalBytes / seconds).toLong() return "Duration=${System.currentTimeMillis() - startTimeMs}ms, TotalBytes=$totalBytes (${totalBytes.bytes.toUnitString()}), Rate=$bytesPerSecond bytes/sec (${bytesPerSecond.bytes.toUnitString()}/sec)" } diff --git a/app/src/main/java/org/thoughtcrime/securesms/backup/v2/ArchiveRestoreProgress.kt b/app/src/main/java/org/thoughtcrime/securesms/backup/v2/ArchiveRestoreProgress.kt new file mode 100644 index 0000000000..2c0048c7ed --- /dev/null +++ b/app/src/main/java/org/thoughtcrime/securesms/backup/v2/ArchiveRestoreProgress.kt @@ -0,0 +1,87 @@ +/* + * Copyright 2025 Signal Messenger, LLC + * SPDX-License-Identifier: AGPL-3.0-only + */ + +package org.thoughtcrime.securesms.backup.v2 + +import org.signal.core.util.bytes +import org.signal.core.util.logging.Log +import org.thoughtcrime.securesms.BuildConfig +import org.thoughtcrime.securesms.attachments.AttachmentId +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicLong +import kotlin.time.Duration.Companion.milliseconds +import kotlin.time.DurationUnit + +/** + * A class for tracking restore progress, largely just for debugging purposes. It keeps no state on disk, and is therefore only useful for testing. + */ +object ArchiveRestoreProgress { + private val TAG = Log.tag(ArchiveRestoreProgress::class.java) + + private var debugAttachmentStartTime: Long = 0 + private val debugTotalAttachments: AtomicInteger = AtomicInteger(0) + private val debugTotalBytes: AtomicLong = AtomicLong(0) + + private val attachmentProgress: MutableMap = ConcurrentHashMap() + + fun onProcessStart() { + debugAttachmentStartTime = System.currentTimeMillis() + } + + fun onDownloadStart(attachmentId: AttachmentId) { + attachmentProgress[attachmentId] = AttachmentProgressDetails(startTimeMs = System.currentTimeMillis()) + } + + fun onDownloadEnd(attachmentId: AttachmentId, totalBytes: Long) { + val details = attachmentProgress[attachmentId] ?: return + details.networkFinishTime = System.currentTimeMillis() + details.totalBytes = totalBytes + } + + fun onWriteToDiskEnd(attachmentId: AttachmentId) { + val details = attachmentProgress[attachmentId] ?: return + attachmentProgress.remove(attachmentId) + + debugTotalAttachments.incrementAndGet() + debugTotalBytes.addAndGet(details.totalBytes) + + if (BuildConfig.DEBUG) { + Log.d(TAG, "Attachment restored: $details") + } + } + + fun onProcessEnd() { + if (debugAttachmentStartTime <= 0 || debugTotalAttachments.get() <= 0 || debugTotalBytes.get() <= 0) { + Log.w(TAG, "Insufficient data to print debug stats.") + return + } + + val seconds: Double = (System.currentTimeMillis() - debugAttachmentStartTime).milliseconds.toDouble(DurationUnit.SECONDS) + val bytesPerSecond: Long = (debugTotalBytes.get() / seconds).toLong() + + Log.w(TAG, "Restore Finished! TotalAttachments=$debugTotalAttachments, TotalBytes=$debugTotalBytes (${debugTotalBytes.get().bytes.toUnitString()}), Rate=$bytesPerSecond bytes/sec (${bytesPerSecond.bytes.toUnitString()}/sec)") + } + + private class AttachmentProgressDetails( + val startTimeMs: Long = 0, + var networkFinishTime: Long = 0, + var totalBytes: Long = 0 + ) { + override fun toString(): String { + if (startTimeMs == 0L || totalBytes == 0L) { + return "N/A" + } + + val networkSeconds: Double = (networkFinishTime - startTimeMs).milliseconds.toDouble(DurationUnit.SECONDS) + val networkBytesPerSecond: Long = (totalBytes / networkSeconds).toLong() + + val diskSeconds: Double = (System.currentTimeMillis() - networkFinishTime).milliseconds.toDouble(DurationUnit.SECONDS) + val diskBytesPerSecond: Long = (totalBytes / diskSeconds).toLong() + + return "Duration=${System.currentTimeMillis() - startTimeMs}ms, TotalBytes=$totalBytes (${totalBytes.bytes.toUnitString()}), NetworkRate=$networkBytesPerSecond bytes/sec (${networkBytesPerSecond.bytes.toUnitString()}/sec), DiskRate=$diskBytesPerSecond bytes/sec (${diskBytesPerSecond.bytes.toUnitString()}/sec)" + } + } +} diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/BackupRestoreMediaJob.kt b/app/src/main/java/org/thoughtcrime/securesms/jobs/BackupRestoreMediaJob.kt index 7bf68b8053..f25fdbf6ad 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/BackupRestoreMediaJob.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/BackupRestoreMediaJob.kt @@ -8,6 +8,7 @@ package org.thoughtcrime.securesms.jobs import org.signal.core.util.logging.Log import org.signal.core.util.withinTransaction import org.thoughtcrime.securesms.attachments.AttachmentId +import org.thoughtcrime.securesms.backup.v2.ArchiveRestoreProgress import org.thoughtcrime.securesms.database.AttachmentTable import org.thoughtcrime.securesms.database.SignalDatabase import org.thoughtcrime.securesms.database.model.MmsMessageRecord @@ -109,6 +110,8 @@ class BackupRestoreMediaJob private constructor(parameters: Parameters) : BaseJo SignalDatabase.attachments.setRestoreTransferState(restoreThumbnailOnlyAttachmentsIds, AttachmentTable.TRANSFER_RESTORE_OFFLOADED) } + ArchiveRestoreProgress.onProcessStart() + // Intentionally enqueues one at a time for safer attachment transfer state management restoreThumbnailJobs.forEach { jobManager.add(it) } restoreFullAttachmentJobs.forEach { jobManager.add(it) } diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/CheckRestoreMediaLeftJob.kt b/app/src/main/java/org/thoughtcrime/securesms/jobs/CheckRestoreMediaLeftJob.kt index b46636e36c..80e7aec593 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/CheckRestoreMediaLeftJob.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/CheckRestoreMediaLeftJob.kt @@ -8,6 +8,7 @@ package org.thoughtcrime.securesms.jobs import org.signal.core.util.logging.Log import org.thoughtcrime.securesms.backup.DeletionState import org.thoughtcrime.securesms.backup.RestoreState +import org.thoughtcrime.securesms.backup.v2.ArchiveRestoreProgress import org.thoughtcrime.securesms.database.SignalDatabase import org.thoughtcrime.securesms.jobmanager.Job import org.thoughtcrime.securesms.keyvalue.SignalStore @@ -43,12 +44,15 @@ class CheckRestoreMediaLeftJob private constructor(parameters: Parameters) : Job val remainingAttachmentSize = SignalDatabase.attachments.getRemainingRestorableAttachmentSize() if (remainingAttachmentSize == 0L) { - Log.d(TAG, "Media restore complete: there are no remaining restorable attachments.") - SignalStore.backup.totalRestorableAttachmentSize = 0 - SignalStore.backup.restoreState = RestoreState.NONE + if (SignalStore.backup.restoreState != RestoreState.NONE) { + Log.d(TAG, "Media restore complete: there are no remaining restorable attachments.") + SignalStore.backup.totalRestorableAttachmentSize = 0 + SignalStore.backup.restoreState = RestoreState.NONE + ArchiveRestoreProgress.onProcessEnd() - if (SignalStore.backup.deletionState == DeletionState.AWAITING_MEDIA_DOWNLOAD) { - SignalStore.backup.deletionState = DeletionState.MEDIA_DOWNLOAD_FINISHED + if (SignalStore.backup.deletionState == DeletionState.AWAITING_MEDIA_DOWNLOAD) { + SignalStore.backup.deletionState = DeletionState.MEDIA_DOWNLOAD_FINISHED + } } } else if (runAttempt == 0) { Log.w(TAG, "Still have remaining data to restore, will retry before checking job queues, queue: ${parameters.queue} estimated remaining: $remainingAttachmentSize") diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/RestoreAttachmentJob.kt b/app/src/main/java/org/thoughtcrime/securesms/jobs/RestoreAttachmentJob.kt index 9699e5e5e0..8048b60450 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/RestoreAttachmentJob.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/RestoreAttachmentJob.kt @@ -20,6 +20,7 @@ import org.thoughtcrime.securesms.R import org.thoughtcrime.securesms.attachments.AttachmentId import org.thoughtcrime.securesms.attachments.DatabaseAttachment import org.thoughtcrime.securesms.attachments.InvalidAttachmentException +import org.thoughtcrime.securesms.backup.v2.ArchiveRestoreProgress import org.thoughtcrime.securesms.backup.v2.BackupRepository import org.thoughtcrime.securesms.backup.v2.createArchiveAttachmentPointer import org.thoughtcrime.securesms.backup.v2.requireMediaName @@ -41,6 +42,7 @@ import org.thoughtcrime.securesms.notifications.NotificationChannels import org.thoughtcrime.securesms.notifications.NotificationIds import org.thoughtcrime.securesms.transport.RetryLaterException import org.thoughtcrime.securesms.util.RemoteConfig +import org.thoughtcrime.securesms.util.SignalLocalMetrics import org.whispersystems.signalservice.api.crypto.AttachmentCipherInputStream.IntegrityCheck import org.whispersystems.signalservice.api.messages.AttachmentTransferProgress import org.whispersystems.signalservice.api.messages.SignalServiceAttachment @@ -218,7 +220,9 @@ class RestoreAttachmentJob private constructor( return } + SignalLocalMetrics.ArchiveAttachmentRestore.start(attachmentId) retrieveAttachment(messageId, attachmentId, attachment) + SignalLocalMetrics.ArchiveAttachmentRestore.end(attachmentId) } override fun onFailure() { @@ -300,6 +304,7 @@ class RestoreAttachmentJob private constructor( } } + ArchiveRestoreProgress.onDownloadStart(attachmentId) val decryptingStream = if (useArchiveCdn) { val cdnCredentials = BackupRepository.getCdnReadCredentials(BackupRepository.CredentialType.MEDIA, attachment.archiveCdn ?: RemoteConfig.backupFallbackArchiveCdn).successOrThrow().headers @@ -323,10 +328,12 @@ class RestoreAttachmentJob private constructor( progressListener ) } + ArchiveRestoreProgress.onDownloadEnd(attachmentId, attachmentFile.length()) decryptingStream.use { input -> SignalDatabase.attachments.finalizeAttachmentAfterDownload(messageId, attachmentId, input, if (manual) System.currentTimeMillis().milliseconds else null) } + ArchiveRestoreProgress.onWriteToDiskEnd(attachmentId) } catch (e: RangeException) { Log.w(TAG, "[$attachmentId] Range exception, file size " + attachmentFile.length(), e) if (attachmentFile.delete()) { diff --git a/app/src/main/java/org/thoughtcrime/securesms/util/SignalLocalMetrics.java b/app/src/main/java/org/thoughtcrime/securesms/util/SignalLocalMetrics.java index b9bcf0669d..d354da9e3e 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/util/SignalLocalMetrics.java +++ b/app/src/main/java/org/thoughtcrime/securesms/util/SignalLocalMetrics.java @@ -516,4 +516,21 @@ public final class SignalLocalMetrics { LocalMetrics.getInstance().end(NAME + id); } } + + /** + * Tracks how long it took to restore an attachment. + */ + public static final class ArchiveAttachmentRestore { + private static final String NAME = "archive-attachment-restore"; + + /** When the attachment begins uploading. */ + public static void start(AttachmentId id) { + LocalMetrics.getInstance().start(NAME, NAME + id); + } + + /** When the attachment finishes uploading. */ + public static void end(AttachmentId id) { + LocalMetrics.getInstance().end(NAME + id); + } + } }