From 96b980676a82a6036f654eae59c7b44f214c9110 Mon Sep 17 00:00:00 2001 From: Jing Ji Date: Fri, 1 Apr 2022 13:42:05 -0700 Subject: [PATCH] Improve the dumpsys output of the app battery tracker Also turn on the logging in debug builds. Bug: 203105544 Test: atest FrameworksMockingServicesTests:BackgroundRestrictionTest Test: dumpsys activity -a Change-Id: I08df65278e228d75dc45c995326cf9cef91de59a --- .../android/server/am/AppBatteryTracker.java | 144 +++++++++++++----- 1 file changed, 106 insertions(+), 38 deletions(-) diff --git a/services/core/java/com/android/server/am/AppBatteryTracker.java b/services/core/java/com/android/server/am/AppBatteryTracker.java index 9c2a38c97a92..bfb42675a1e7 100644 --- a/services/core/java/com/android/server/am/AppBatteryTracker.java +++ b/services/core/java/com/android/server/am/AppBatteryTracker.java @@ -55,6 +55,7 @@ import android.os.BatteryConsumer.Dimensions; import android.os.BatteryStatsInternal; import android.os.BatteryUsageStats; import android.os.BatteryUsageStatsQuery; +import android.os.Build; import android.os.PowerExemptionManager; import android.os.PowerExemptionManager.ReasonCode; import android.os.SystemClock; @@ -62,6 +63,7 @@ import android.os.UidBatteryConsumer; import android.os.UserHandle; import android.provider.DeviceConfig; import android.util.ArraySet; +import android.util.Pair; import android.util.Slog; import android.util.SparseArray; import android.util.SparseBooleanArray; @@ -80,6 +82,7 @@ import java.io.PrintWriter; import java.lang.reflect.Constructor; import java.util.Arrays; import java.util.List; +import java.util.concurrent.CountDownLatch; /** * The battery usage tracker for apps, currently we are focusing on background + FGS battery here. @@ -90,6 +93,9 @@ final class AppBatteryTracker extends BaseAppStateTracker static final boolean DEBUG_BACKGROUND_BATTERY_TRACKER = false; + static final boolean DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE = + DEBUG_BACKGROUND_BATTERY_TRACKER | Build.IS_DEBUGGABLE; + // As we don't support realtime per-UID battery usage stats yet, we're polling the stats // in a regular time basis. private final long mBatteryUsageStatsPollingIntervalMs; @@ -169,7 +175,7 @@ final class AppBatteryTracker extends BaseAppStateTracker private long mLastUidBatteryUsageStartTs; // For debug only. - private final SparseArray mDebugUidPercentages = new SparseArray<>(); + private final SparseArray mDebugUidPercentages = new SparseArray<>(); AppBatteryTracker(Context context, AppRestrictionController controller) { this(context, controller, null, null); @@ -331,10 +337,12 @@ final class AppBatteryTracker extends BaseAppStateTracker bgPolicy.mBgCurrentDrainExemptedTypes); // It's possible the exemptedUsage could be larger than actualUsage, // as the former one is an approximate value. - final BatteryUsage bgUsage = actualUsage.mutate() + final ImmutableBatteryUsage bgUsage = actualUsage.mutate() .subtract(exemptedUsage) - .calcPercentage(uid, bgPolicy); - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + .calcPercentage(uid, bgPolicy) + .unmutate(); + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE + && !BATTERY_USAGE_NONE.equals(actualUsage)) { Slog.i(TAG, String.format( "UID %d: %s (%s) | %s | %s over the past %s", uid, @@ -414,7 +422,7 @@ final class AppBatteryTracker extends BaseAppStateTracker } } - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE) { Slog.i(TAG, "updateBatteryUsageStatsOnce"); } @@ -471,14 +479,17 @@ final class AppBatteryTracker extends BaseAppStateTracker final BatteryUsage lastUsage = mLastUidBatteryUsage.get(uid, BATTERY_USAGE_NONE); final BatteryUsage curUsage = buf.valueAt(i); final BatteryUsage before; + final BatteryUsage totalUsage; if (index >= 0) { - before = mUidBatteryUsage.valueAt(index); - before.subtract(lastUsage).add(curUsage); + totalUsage = mUidBatteryUsage.valueAt(index); + before = DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE + ? new BatteryUsage(totalUsage) : BATTERY_USAGE_NONE; + totalUsage.subtract(lastUsage).add(curUsage); } else { - before = BATTERY_USAGE_NONE; + before = totalUsage = BATTERY_USAGE_NONE; mUidBatteryUsage.put(uid, curUsage); } - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE) { final BatteryUsage actualDelta = new BatteryUsage(curUsage).subtract(lastUsage); String msg = "Updating mUidBatteryUsage uid=" + uid + ", before=" + before + ", after=" + mUidBatteryUsage.get(uid, BATTERY_USAGE_NONE) @@ -490,7 +501,7 @@ final class AppBatteryTracker extends BaseAppStateTracker if (!actualDelta.isValid()) { // Something is wrong, the battery usage shouldn't be negative. Slog.e(TAG, msg); - } else { + } else if (!BATTERY_USAGE_NONE.equals(actualDelta)) { Slog.i(TAG, msg); } } @@ -513,11 +524,16 @@ final class AppBatteryTracker extends BaseAppStateTracker copyUidBatteryUsage(buf, mUidBatteryUsageInWindow); } } - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE) { synchronized (mLock) { for (int i = 0, size = mUidBatteryUsageInWindow.size(); i < size; i++) { + final ImmutableBatteryUsage usage = mUidBatteryUsageInWindow.valueAt(i); + if (BATTERY_USAGE_NONE.equals(usage)) { + // Skip the logging to avoid spamming. + continue; + } Slog.i(TAG, "mUidBatteryUsageInWindow uid=" + mUidBatteryUsageInWindow.keyAt(i) - + " usage=" + mUidBatteryUsageInWindow.valueAt(i)); + + " usage=" + usage); } } } @@ -568,7 +584,8 @@ final class AppBatteryTracker extends BaseAppStateTracker final BatteryUsage before = buf.valueAt(index); before.add(bgUsage); } - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE + && !BATTERY_USAGE_NONE.equals(bgUsage)) { Slog.i(TAG, "updateBatteryUsageStatsOnceInternal uid=" + rawUid + ", bgUsage=" + bgUsage + (rawUid == uid ? "" @@ -625,7 +642,8 @@ final class AppBatteryTracker extends BaseAppStateTracker void setDebugUidPercentage(int[] uids, double[][] percentages) { mDebugUidPercentages.clear(); for (int i = 0; i < uids.length; i++) { - mDebugUidPercentages.put(uids[i], new BatteryUsage().setPercentage(percentages[i])); + mDebugUidPercentages.put(uids[i], + new BatteryUsage().setPercentage(percentages[i]).unmutate()); } scheduleBgBatteryUsageStatsCheck(); } @@ -651,7 +669,20 @@ final class AppBatteryTracker extends BaseAppStateTracker void dump(PrintWriter pw, String prefix) { pw.print(prefix); pw.println("APP BATTERY STATE TRACKER:"); + // Force an update. updateBatteryUsageStatsIfNecessary(mInjector.currentTimeMillis(), true); + // Force a check. + scheduleBgBatteryUsageStatsCheck(); + // Wait for its completion (as it runs in handler thread for the sake of thread safe) + final CountDownLatch latch = new CountDownLatch(1); + mBgHandler.getLooper().getQueue().addIdleHandler(() -> { + latch.countDown(); + return false; + }); + try { + latch.await(); + } catch (InterruptedException e) { + } synchronized (mLock) { final SparseArray uidConsumers = mUidBatteryUsageInWindow; pw.print(" " + prefix); @@ -816,8 +847,12 @@ final class AppBatteryTracker extends BaseAppStateTracker } private BatteryUsage setToInternal(@NonNull BatteryUsage other) { - for (int i = 0; i < other.mUsage.length; i++) { - mUsage[i] = other.mUsage[i]; + System.arraycopy(other.mUsage, 0, mUsage, 0, other.mUsage.length); + if (other.mPercentage != null) { + mPercentage = new double[other.mPercentage.length]; + System.arraycopy(other.mPercentage, 0, mPercentage, 0, other.mPercentage.length); + } else { + mPercentage = null; } return this; } @@ -1297,11 +1332,12 @@ final class AppBatteryTracker extends BaseAppStateTracker /** * List of the packages with significant background battery usage, key is the UID of - * the package and value is an array of the timestamps when the UID is found guilty and - * should be moved to the next level of restriction. + * the package and value is the pair of {timestamp[], battery usage snapshot[]} + * when the UID is found guilty and should be moved to the next level of restriction. */ @GuardedBy("mLock") - private final SparseArray mHighBgBatteryPackages = new SparseArray<>(); + private final SparseArray> mHighBgBatteryPackages = + new SparseArray<>(); @NonNull private final Object mLock; @@ -1531,8 +1567,9 @@ final class AppBatteryTracker extends BaseAppStateTracker return RESTRICTION_LEVEL_UNKNOWN; } synchronized (mLock) { - final long[] ts = mHighBgBatteryPackages.get(uid); - if (ts != null) { + final Pair pair = mHighBgBatteryPackages.get(uid); + if (pair != null) { + final long[] ts = pair.first; final int restrictedLevel = ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET] > 0 ? RESTRICTION_LEVEL_RESTRICTED_BUCKET : RESTRICTION_LEVEL_ADAPTIVE_BUCKET; @@ -1601,10 +1638,10 @@ final class AppBatteryTracker extends BaseAppStateTracker return sb.toString(); } - void handleUidBatteryUsage(final int uid, final BatteryUsage usage) { + void handleUidBatteryUsage(final int uid, final ImmutableBatteryUsage usage) { final @ReasonCode int reason = shouldExemptUid(uid); if (reason != REASON_DENIED) { - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE && !BATTERY_USAGE_NONE.equals(usage)) { Slog.i(TAG, "Exempting battery usage in " + UserHandle.formatUid(uid) + " " + PowerExemptionManager.reasonCodeToString(reason)); } @@ -1612,6 +1649,7 @@ final class AppBatteryTracker extends BaseAppStateTracker } boolean notifyController = false; boolean excessive = false; + int index = 0; final double rbPercentage = sumPercentageOfTypes(usage.getPercentage(), mBgCurrentDrainRestrictedBucketTypes); final double brPercentage = sumPercentageOfTypes(usage.getPercentage(), @@ -1625,33 +1663,41 @@ final class AppBatteryTracker extends BaseAppStateTracker final long now = SystemClock.elapsedRealtime(); final int thresholdIndex = getCurrentDrainThresholdIndex(uid, now, mBgCurrentDrainWindowMs); - final int index = mHighBgBatteryPackages.indexOfKey(uid); + index = mHighBgBatteryPackages.indexOfKey(uid); final boolean decoupleThresholds = mBgCurrentDrainDecoupleThresholds; final double rbThreshold = mBgCurrentDrainRestrictedBucketThreshold[thresholdIndex]; final double brThreshold = mBgCurrentDrainBgRestrictedThreshold[thresholdIndex]; if (index < 0) { long[] ts = null; + ImmutableBatteryUsage[] usages = null; if (rbPercentage >= rbThreshold) { // New findings to us, track it and let the controller know. ts = new long[TIME_STAMP_INDEX_LAST]; ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = now; - mHighBgBatteryPackages.put(uid, ts); + usages = new ImmutableBatteryUsage[TIME_STAMP_INDEX_LAST]; + usages[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = usage; + mHighBgBatteryPackages.put(uid, Pair.create(ts, usages)); notifyController = excessive = true; } if (decoupleThresholds && brPercentage >= brThreshold) { if (ts == null) { ts = new long[TIME_STAMP_INDEX_LAST]; - mHighBgBatteryPackages.put(uid, ts); + usages = new ImmutableBatteryUsage[TIME_STAMP_INDEX_LAST]; + mHighBgBatteryPackages.put(uid, Pair.create(ts, usages)); } ts[TIME_STAMP_INDEX_BG_RESTRICTED] = now; + usages[TIME_STAMP_INDEX_BG_RESTRICTED] = usage; notifyController = excessive = true; } } else { - final long[] ts = mHighBgBatteryPackages.valueAt(index); + final Pair pair = + mHighBgBatteryPackages.valueAt(index); + final long[] ts = pair.first; final long lastRestrictBucketTs = ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET]; if (rbPercentage >= rbThreshold) { if (lastRestrictBucketTs == 0) { ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = now; + pair.second[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = usage; } notifyController = excessive = true; } else { @@ -1670,6 +1716,7 @@ final class AppBatteryTracker extends BaseAppStateTracker && (now > lastRestrictBucketTs + mBgCurrentDrainWindowMs)); if (notifyController) { ts[TIME_STAMP_INDEX_BG_RESTRICTED] = now; + pair.second[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = usage; } excessive = true; } else { @@ -1677,13 +1724,14 @@ final class AppBatteryTracker extends BaseAppStateTracker // user consent to unrestrict it; or if it's in restricted bucket level, // resetting this won't lift it from that level. ts[TIME_STAMP_INDEX_BG_RESTRICTED] = 0; + pair.second[TIME_STAMP_INDEX_RESTRICTED_BUCKET] = null; // Now need to notify the controller. } } } if (excessive) { - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE) { Slog.i(TAG, "Excessive background current drain " + uid + " " + usage + " (" + usage.percentageToString() + " ) over " + TimeUtils.formatDuration(mBgCurrentDrainWindowMs)); @@ -1694,7 +1742,7 @@ final class AppBatteryTracker extends BaseAppStateTracker REASON_SUB_FORCED_SYSTEM_FLAG_ABUSE, true); } } else { - if (DEBUG_BACKGROUND_BATTERY_TRACKER) { + if (DEBUG_BACKGROUND_BATTERY_TRACKER_VERBOSE && index >= 0) { Slog.i(TAG, "Background current drain backs to normal " + uid + " " + usage + " (" + usage.percentageToString() + " ) over " + TimeUtils.formatDuration(mBgCurrentDrainWindowMs)); @@ -1764,9 +1812,10 @@ final class AppBatteryTracker extends BaseAppStateTracker synchronized (mLock) { // User has explicitly removed it from background restricted level, // clear the timestamp of the background-restricted - final long[] ts = mHighBgBatteryPackages.get(uid); - if (ts != null) { - ts[TIME_STAMP_INDEX_BG_RESTRICTED] = 0; + final Pair pair = mHighBgBatteryPackages.get(uid); + if (pair != null) { + pair.first[TIME_STAMP_INDEX_BG_RESTRICTED] = 0; + pair.second[TIME_STAMP_INDEX_BG_RESTRICTED] = null; } } } @@ -1841,6 +1890,10 @@ final class AppBatteryTracker extends BaseAppStateTracker pw.print(KEY_BG_CURRENT_DRAIN_HIGH_THRESHOLD_BY_BG_LOCATION); pw.print('='); pw.println(mBgCurrentDrainHighThresholdByBgLocation); + pw.print(prefix); + pw.print("Full charge capacity="); + pw.print(mBatteryFullChargeMah); + pw.println(" mAh"); pw.print(prefix); pw.println("Excessive current drain detected:"); @@ -1851,18 +1904,24 @@ final class AppBatteryTracker extends BaseAppStateTracker final long now = SystemClock.elapsedRealtime(); for (int i = 0; i < size; i++) { final int uid = mHighBgBatteryPackages.keyAt(i); - final long[] ts = mHighBgBatteryPackages.valueAt(i); + final Pair pair = + mHighBgBatteryPackages.valueAt(i); + final long[] ts = pair.first; + final ImmutableBatteryUsage[] usages = pair.second; final int thresholdIndex = getCurrentDrainThresholdIndex(uid, now, mBgCurrentDrainWindowMs); - pw.format("%s%s: (threshold=%4.2f%%/%4.2f%%) %s/%s\n", + pw.format("%s%s: (threshold=%4.2f%%/%4.2f%%) %s / %s\n", prefix, UserHandle.formatUid(uid), mBgCurrentDrainRestrictedBucketThreshold[thresholdIndex], mBgCurrentDrainBgRestrictedThreshold[thresholdIndex], - ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET] == 0 ? "0" - : formatTime(ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET], now), - ts[TIME_STAMP_INDEX_BG_RESTRICTED] == 0 ? "0" - : formatTime(ts[TIME_STAMP_INDEX_BG_RESTRICTED], now)); + formatHighBgBatteryRecord( + ts[TIME_STAMP_INDEX_RESTRICTED_BUCKET], now, + usages[TIME_STAMP_INDEX_RESTRICTED_BUCKET]), + formatHighBgBatteryRecord( + ts[TIME_STAMP_INDEX_BG_RESTRICTED], now, + usages[TIME_STAMP_INDEX_BG_RESTRICTED]) + ); } } else { pw.print(prefix); @@ -1871,5 +1930,14 @@ final class AppBatteryTracker extends BaseAppStateTracker } } } + + private String formatHighBgBatteryRecord(long ts, long now, ImmutableBatteryUsage usage) { + if (ts > 0 && usage != null) { + return String.format("%s %s (%s)", + formatTime(ts, now), usage.toString(), usage.percentageToString()); + } else { + return "0"; + } + } } }