Add debug logging for attachment restore speeds.

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<AttachmentId, AttachmentProgressDetails> = 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)"
     }

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<AttachmentId, AttachmentProgressDetails> = 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)"
+    }
+  }
+}

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) }

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")

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()) {

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);
+    }
+  }
 }