diff --git a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java index 130d2b1b36..6ac02397c1 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java +++ b/app/src/main/java/org/thoughtcrime/securesms/ApplicationContext.java @@ -114,6 +114,7 @@ import org.thoughtcrime.securesms.service.webrtc.ActiveCallManager; import org.thoughtcrime.securesms.service.webrtc.AndroidTelecomUtil; import org.thoughtcrime.securesms.storage.StorageSyncHelper; import org.thoughtcrime.securesms.util.AppStartup; +import org.thoughtcrime.securesms.util.BatterySnapshotTracker; import org.thoughtcrime.securesms.util.DeviceProperties; import org.thoughtcrime.securesms.util.DynamicTheme; import org.thoughtcrime.securesms.util.Environment; @@ -259,6 +260,8 @@ public class ApplicationContext extends Application implements AppForegroundObse long startTime = System.currentTimeMillis(); Log.i(TAG, "App is now visible. Battery: " + DeviceProperties.getBatteryLevel(this) + "% (charging: " + DeviceProperties.isCharging(this) + ")"); + BatterySnapshotTracker.emit(this, "foreground"); + AppDependencies.getFrameRateTracker().start(); AppDependencies.getMegaphoneRepository().onAppForegrounded(); AppDependencies.getDeadlockDetector().start(); @@ -299,6 +302,7 @@ public class ApplicationContext extends Application implements AppForegroundObse @Override public void onBackground() { Log.i(TAG, "App is no longer visible."); + BatterySnapshotTracker.emit(this, "background"); KeyCachingService.onAppBackgrounded(this); AppDependencies.getMessageNotifier().clearVisibleThread(); AppDependencies.getFrameRateTracker().stop(); diff --git a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBattery.kt b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBattery.kt new file mode 100644 index 0000000000..00cbe65ae2 --- /dev/null +++ b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionBattery.kt @@ -0,0 +1,75 @@ +package org.thoughtcrime.securesms.logsubmit + +import android.app.usage.UsageStatsManager +import android.content.Context +import android.net.TrafficStats +import android.os.Build +import android.os.PowerManager +import android.os.Process +import android.os.SystemClock +import org.signal.core.util.bytes +import org.thoughtcrime.securesms.util.BucketInfo +import org.thoughtcrime.securesms.util.DeviceProperties +import org.thoughtcrime.securesms.util.WakeLockUtil +import java.util.Locale +import java.util.concurrent.TimeUnit +import kotlin.time.Duration.Companion.milliseconds + +/** + * A point-in-time summary of process resource usage relevant to battery consumption. The detailed + * time series lives in the regular logs (emitted by [org.thoughtcrime.securesms.util.BatterySnapshotTracker]); + * this section gives an at-a-glance summary accumulated since process start. + */ +class LogSectionBattery : LogSection { + override fun getTitle(): String { + return "BATTERY" + } + + override fun getContent(context: Context): CharSequence { + val cpuMs = Process.getElapsedCpuTime() + val wakeLockMs = WakeLockUtil.getCumulativeHeldMs() + val rxBytes = TrafficStats.getUidRxBytes(Process.myUid()) + val txBytes = TrafficStats.getUidTxBytes(Process.myUid()) + + val builder = StringBuilder() + + if (Build.VERSION.SDK_INT >= 24) { + val uptimeMs = SystemClock.elapsedRealtime() - Process.getStartElapsedRealtime() + builder.append("Process uptime : ").append(uptimeMs.milliseconds.toString()).append("\n") + builder.append("CPU time : ").append(cpuMs).append("ms (").append(percent(cpuMs, uptimeMs)).append(" of uptime)\n") + builder.append("Wakelock time : ").append(wakeLockMs).append("ms (").append(percent(wakeLockMs, uptimeMs)).append(" of uptime)\n") + } else { + builder.append("CPU time : ").append(cpuMs).append("ms\n") + builder.append("Wakelock time : ").append(wakeLockMs).append("ms\n") + } + + builder.append("Active wakelocks: ").append(WakeLockUtil.getActiveLockCount()).append("\n") + builder.append("Network rx/tx : ").append(rxBytes.bytes.toUnitString()).append(" / ").append(txBytes.bytes.toUnitString()).append("\n") + builder.append("Battery level : ").append(DeviceProperties.getBatteryLevel(context)).append("%\n") + builder.append("Charge counter : ").append(DeviceProperties.getBatteryChargeCounter(context)).append("µAh\n") + builder.append("Charging : ").append(DeviceProperties.isCharging(context)).append("\n") + + val powerManager = context.getSystemService(Context.POWER_SERVICE) as? PowerManager + if (powerManager != null) { + builder.append("Power save mode : ").append(powerManager.isPowerSaveMode).append("\n") + builder.append("Device idle : ").append(powerManager.isDeviceIdleMode).append("\n") + builder.append("Interactive : ").append(powerManager.isInteractive).append("\n") + } + + if (Build.VERSION.SDK_INT >= 28) { + val usageStatsManager = context.getSystemService(Context.USAGE_STATS_SERVICE) as? UsageStatsManager + if (usageStatsManager != null) { + builder.append("Standby bucket : ").append(BucketInfo.bucketToString(usageStatsManager.appStandbyBucket)).append("\n") + } + } + + return builder + } + + private fun percent(part: Long, whole: Long): String { + if (whole <= 0) { + return "n/a" + } + return String.format(Locale.US, "%.1f%%", 100.0 * part / whole) + } +} 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 0263ae44d2..dd309cad62 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java +++ b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/SubmitDebugLogRepository.java @@ -85,6 +85,7 @@ public class SubmitDebugLogRepository { if (Build.VERSION.SDK_INT >= 28) { add(new LogSectionPower()); } + add(new LogSectionBattery()); add(new LogSectionNotifications()); add(new LogSectionNotificationProfiles()); add(new LogSectionExoPlayerPool()); diff --git a/app/src/main/java/org/thoughtcrime/securesms/messageprocessingalarm/RoutineMessageFetchReceiver.java b/app/src/main/java/org/thoughtcrime/securesms/messageprocessingalarm/RoutineMessageFetchReceiver.java index f0a1d4103e..fc550f9a25 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/messageprocessingalarm/RoutineMessageFetchReceiver.java +++ b/app/src/main/java/org/thoughtcrime/securesms/messageprocessingalarm/RoutineMessageFetchReceiver.java @@ -19,6 +19,7 @@ import org.thoughtcrime.securesms.dependencies.AppDependencies; import org.thoughtcrime.securesms.jobmanager.JobTracker; import org.thoughtcrime.securesms.jobs.MessageFetchJob; import org.signal.core.util.AppForegroundObserver; +import org.thoughtcrime.securesms.util.BatterySnapshotTracker; import org.thoughtcrime.securesms.util.RemoteConfig; import java.util.Locale; @@ -49,6 +50,8 @@ public final class RoutineMessageFetchReceiver extends BroadcastReceiver { return; } + BatterySnapshotTracker.emit(context, "routine"); + long foregroundDelayMs = RemoteConfig.getBackgroundMessageProcessForegroundDelay(); long jobTimeout = foregroundDelayMs + 200; diff --git a/app/src/main/java/org/thoughtcrime/securesms/util/BatterySnapshotTracker.kt b/app/src/main/java/org/thoughtcrime/securesms/util/BatterySnapshotTracker.kt new file mode 100644 index 0000000000..140d6372c6 --- /dev/null +++ b/app/src/main/java/org/thoughtcrime/securesms/util/BatterySnapshotTracker.kt @@ -0,0 +1,121 @@ +package org.thoughtcrime.securesms.util + +import android.app.usage.UsageStatsManager +import android.content.Context +import android.net.TrafficStats +import android.os.Build +import android.os.PowerManager +import android.os.Process +import android.os.SystemClock +import org.signal.core.util.bytes +import org.signal.core.util.logging.Log +import java.util.Locale + +/** + * Records lightweight, delta-based snapshots of process resource usage that correlate with battery + * drain (CPU time, held wakelocks, network bytes, and consumed charge), along with the power-related + * device state at the time of sampling. + * + * Every value read here is a cheap, in-process syscall, so this is intended to be sampled only when + * the app is already awake for another reason (e.g. a routine background fetch or a foreground + * transition). It deliberately never schedules its own wakeups, which would themselves drain battery. + */ +object BatterySnapshotTracker { + + private val TAG = Log.tag(BatterySnapshotTracker::class.java) + + private var lastSample: Sample? = null + + @JvmStatic + @Synchronized + fun emit(context: Context, trigger: String) { + val sample = Sample( + elapsedRealtimeMs = SystemClock.elapsedRealtime(), + cpuMs = Process.getElapsedCpuTime(), + rxBytes = TrafficStats.getUidRxBytes(Process.myUid()), + txBytes = TrafficStats.getUidTxBytes(Process.myUid()), + wakeLockMs = WakeLockUtil.getCumulativeHeldMs(), + chargeCounterUah = DeviceProperties.getBatteryChargeCounter(context) + ) + + val previous = lastSample + lastSample = sample + + val state = describeState(context) + + if (previous == null) { + Log.i(TAG, "[$trigger] Baseline established. $state") + return + } + + val wallMs = sample.elapsedRealtimeMs - previous.elapsedRealtimeMs + if (wallMs <= 0) { + Log.w(TAG, "[$trigger] Non-positive interval ($wallMs ms). Skipping.") + return + } + + val cpuDeltaMs = sample.cpuMs - previous.cpuMs + val wakeDeltaMs = sample.wakeLockMs - previous.wakeLockMs + + Log.i( + TAG, + String.format( + Locale.US, + "[%s] Δ=%.1fm | cpu=+%dms(%.1f%%) | wakelock=+%dms(%.1f%%) | net=%s | chargeΔ=%s | %s", + trigger, + wallMs / 60000.0, + cpuDeltaMs, + 100.0 * cpuDeltaMs / wallMs, + wakeDeltaMs, + 100.0 * wakeDeltaMs / wallMs, + formatNet(previous, sample), + formatCharge(previous, sample), + state + ) + ) + } + + private fun formatNet(previous: Sample, sample: Sample): String { + if (sample.rxBytes < 0 || sample.txBytes < 0 || previous.rxBytes < 0 || previous.txBytes < 0) { + return "unsupported" + } + val rx = sample.rxBytes - previous.rxBytes + val tx = sample.txBytes - previous.txBytes + return "+${(rx + tx).bytes.toUnitString()} (rx ${rx.bytes.toUnitString()} / tx ${tx.bytes.toUnitString()})" + } + + private fun formatCharge(previous: Sample, sample: Sample): String { + if (sample.chargeCounterUah < 0 || previous.chargeCounterUah < 0) { + return "unsupported" + } + return "${sample.chargeCounterUah - previous.chargeCounterUah}µAh" + } + + private fun describeState(context: Context): String { + val level = DeviceProperties.getBatteryLevel(context) + val charging = DeviceProperties.isCharging(context) + + val powerManager = context.getSystemService(Context.POWER_SERVICE) as? PowerManager + val powerSave = powerManager?.isPowerSaveMode ?: false + val doze = powerManager?.isDeviceIdleMode ?: false + val interactive = powerManager?.isInteractive ?: false + + val bucket = if (Build.VERSION.SDK_INT >= 28) { + val usageStatsManager = context.getSystemService(Context.USAGE_STATS_SERVICE) as? UsageStatsManager + usageStatsManager?.let { BucketInfo.bucketToString(it.appStandbyBucket) } ?: "unknown" + } else { + "n/a" + } + + return "battery=$level% charging=$charging powerSave=$powerSave doze=$doze interactive=$interactive bucket=$bucket" + } + + private data class Sample( + val elapsedRealtimeMs: Long, + val cpuMs: Long, + val rxBytes: Long, + val txBytes: Long, + val wakeLockMs: Long, + val chargeCounterUah: Int + ) +} diff --git a/app/src/main/java/org/thoughtcrime/securesms/util/DeviceProperties.java b/app/src/main/java/org/thoughtcrime/securesms/util/DeviceProperties.java index 60968efd78..50af2a50ba 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/util/DeviceProperties.java +++ b/app/src/main/java/org/thoughtcrime/securesms/util/DeviceProperties.java @@ -98,6 +98,20 @@ public final class DeviceProperties { return -1; } + /** + * Returns the remaining battery charge in microampere-hours (µAh), or -1 if unavailable. Unlike + * the battery level percentage, this has fine granularity and is well-suited to measuring drain + * between two points in time. + */ + public static int getBatteryChargeCounter(@NonNull Context context) { + BatteryManager batteryManager = (BatteryManager) context.getSystemService(Context.BATTERY_SERVICE); + if (batteryManager != null) { + int value = batteryManager.getIntProperty(BatteryManager.BATTERY_PROPERTY_CHARGE_COUNTER); + return value > 0 ? value : -1; + } + return -1; + } + /** * Returns whether the device is currently charging. */ diff --git a/app/src/main/java/org/thoughtcrime/securesms/util/WakeLockUtil.java b/app/src/main/java/org/thoughtcrime/securesms/util/WakeLockUtil.java index 3a5f19bfbe..6bb819aa93 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/util/WakeLockUtil.java +++ b/app/src/main/java/org/thoughtcrime/securesms/util/WakeLockUtil.java @@ -3,6 +3,7 @@ package org.thoughtcrime.securesms.util; import android.content.Context; import android.os.PowerManager; import android.os.PowerManager.WakeLock; +import android.os.SystemClock; import androidx.annotation.NonNull; import androidx.annotation.Nullable; @@ -10,10 +11,17 @@ import androidx.annotation.Nullable; import org.signal.core.util.logging.Log; import org.signal.core.util.ServiceUtil; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicLong; + public class WakeLockUtil { private static final String TAG = Log.tag(WakeLockUtil.class); + private static final Map activeAcquisitions = new ConcurrentHashMap<>(); + private static final AtomicLong cumulativeHeldMs = new AtomicLong(0); + /** * Run a runnable with a wake lock. Ensures that the lock is safely acquired and released. * @@ -42,6 +50,8 @@ public class WakeLockUtil { wakeLock.acquire(timeout); + activeAcquisitions.put(wakeLock, new Acquisition(SystemClock.elapsedRealtime(), timeout)); + return wakeLock; } catch (Exception e) { Log.w(TAG, "Failed to acquire wakelock with tag: " + tag, e); @@ -54,6 +64,11 @@ public class WakeLockUtil { */ public static void release(@Nullable WakeLock wakeLock, @NonNull String tag) { tag = prefixTag(tag); + + if (wakeLock != null) { + recordHeldTime(wakeLock); + } + try { if (wakeLock == null) { Log.d(TAG, "Wakelock was null. Skipping. Tag: " + tag); @@ -67,7 +82,51 @@ public class WakeLockUtil { } } + /** + * The cumulative time, in milliseconds, that wakelocks acquired through this class have been held + * since process start. Includes the in-progress duration of any currently-held locks. + */ + public static long getCumulativeHeldMs() { + long total = cumulativeHeldMs.get(); + long now = SystemClock.elapsedRealtime(); + + for (Acquisition acquisition : activeAcquisitions.values()) { + total += acquisition.heldMs(now); + } + + return total; + } + + /** + * The number of wakelocks acquired through this class that are currently being tracked as held. + */ + public static int getActiveLockCount() { + return activeAcquisitions.size(); + } + + private static void recordHeldTime(@NonNull WakeLock wakeLock) { + Acquisition acquisition = activeAcquisitions.remove(wakeLock); + if (acquisition != null) { + cumulativeHeldMs.addAndGet(acquisition.heldMs(SystemClock.elapsedRealtime())); + } + } + private static String prefixTag(@NonNull String tag) { return tag.startsWith("signal:") ? tag : "signal:" + tag; } + + private static final class Acquisition { + private final long acquiredAtMs; + private final long timeoutMs; + + Acquisition(long acquiredAtMs, long timeoutMs) { + this.acquiredAtMs = acquiredAtMs; + this.timeoutMs = timeoutMs; + } + + long heldMs(long now) { + long elapsed = Math.max(0, now - acquiredAtMs); + return timeoutMs > 0 ? Math.min(elapsed, timeoutMs) : elapsed; + } + } }