From 234d1828ca4a706676ad6f3fa0629959c74297c7 Mon Sep 17 00:00:00 2001 From: Mike Ma Date: Tue, 13 Mar 2018 18:53:21 -0700 Subject: [PATCH] Resolve STATSD and batterystats race condition Both STATSD and batterystats need to read uid cpu info. However, uid cpu stats needs to be cleared from time to time to conserve memory. To resolve this race condition, only batterystats will remove uid stats, both from readers and from the kernel, also with a delay, so that STATSD can access such info before it is removed. Refactored readers to reuse some common code. Also removed string reader from KernelUidCpuFreqTimeReader completely since binary reader has been working fine for a while. Change-Id: I209bdcec642e1a29a44b566ce98ebbfaaacb4e6a Fixes: 72172569 Test: BatteryStatsCpuTimesTest Test: KernelUidCpuActiveTimeReaderTest Test: KernelUidCpuClusterTimeReaderTest Test: KernelUidCpuFreqTimeReaderTest --- .../android/internal/os/BatteryStatsImpl.java | 201 +++++++++--- .../os/KernelUidCpuActiveTimeReader.java | 97 +++--- .../os/KernelUidCpuClusterTimeReader.java | 124 ++++---- .../os/KernelUidCpuFreqTimeReader.java | 288 +++++++----------- .../internal/os/BatteryStatsCpuTimesTest.java | 134 ++++++++ .../internal/os/BatteryStatsNoteTest.java | 9 +- .../os/KernelUidCpuActiveTimeReaderTest.java | 6 +- .../os/KernelUidCpuFreqTimeReaderTest.java | 187 +----------- .../internal/os/MockBatteryStatsImpl.java | 5 + .../server/am/BatteryExternalStatsWorker.java | 1 + .../server/am/BatteryStatsService.java | 10 + .../server/stats/StatsCompanionService.java | 1 - 12 files changed, 555 insertions(+), 508 deletions(-) diff --git a/core/java/com/android/internal/os/BatteryStatsImpl.java b/core/java/com/android/internal/os/BatteryStatsImpl.java index 4ab2fecbe9645..89f8ae6b01bfc 100644 --- a/core/java/com/android/internal/os/BatteryStatsImpl.java +++ b/core/java/com/android/internal/os/BatteryStatsImpl.java @@ -33,9 +33,6 @@ import android.net.wifi.WifiManager; import android.os.BatteryManager; import android.os.BatteryStats; import android.os.Build; -import android.os.connectivity.CellularBatteryStats; -import android.os.connectivity.WifiBatteryStats; -import android.os.connectivity.GpsBatteryStats; import android.os.FileUtils; import android.os.Handler; import android.os.IBatteryPropertiesRegistrar; @@ -53,6 +50,9 @@ import android.os.SystemClock; import android.os.UserHandle; import android.os.WorkSource; import android.os.WorkSource.WorkChain; +import android.os.connectivity.CellularBatteryStats; +import android.os.connectivity.GpsBatteryStats; +import android.os.connectivity.WifiBatteryStats; import android.provider.Settings; import android.telephony.DataConnectionRealTimeInfo; import android.telephony.ModemActivityInfo; @@ -90,8 +90,8 @@ import com.android.internal.util.FastXmlSerializer; import com.android.internal.util.JournaledFile; import com.android.internal.util.XmlUtils; -import java.util.List; import libcore.util.EmptyArray; + import org.xmlpull.v1.XmlPullParser; import org.xmlpull.v1.XmlPullParserException; import org.xmlpull.v1.XmlSerializer; @@ -109,11 +109,11 @@ import java.util.Arrays; import java.util.Calendar; import java.util.HashMap; import java.util.Iterator; +import java.util.LinkedList; +import java.util.List; import java.util.Map; -import java.util.concurrent.ExecutorService; -import java.util.concurrent.Executors; +import java.util.Queue; import java.util.concurrent.Future; -import java.util.concurrent.ThreadFactory; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.locks.ReentrantLock; @@ -234,11 +234,15 @@ public class BatteryStatsImpl extends BatteryStats { protected final SparseIntArray mPendingUids = new SparseIntArray(); @GuardedBy("this") - private long mNumCpuTimeReads; + private long mNumSingleUidCpuTimeReads; @GuardedBy("this") - private long mNumBatchedCpuTimeReads; + private long mNumBatchedSingleUidCpuTimeReads; @GuardedBy("this") private long mCpuTimeReadsTrackingStartTime = SystemClock.uptimeMillis(); + @GuardedBy("this") + private int mNumUidsRemoved; + @GuardedBy("this") + private int mNumAllUidCpuTimeReads; /** Container for Resource Power Manager stats. Updated by updateRpmStatsLocked. */ private final RpmStats mTmpRpmStats = new RpmStats(); @@ -246,6 +250,67 @@ public class BatteryStatsImpl extends BatteryStats { private static final long RPM_STATS_UPDATE_FREQ_MS = 1000; /** Last time that RPM stats were updated by updateRpmStatsLocked. */ private long mLastRpmStatsUpdateTimeMs = -RPM_STATS_UPDATE_FREQ_MS; + /** + * Use a queue to delay removing UIDs from {@link KernelUidCpuTimeReader}, + * {@link KernelUidCpuActiveTimeReader}, {@link KernelUidCpuClusterTimeReader}, + * {@link KernelUidCpuFreqTimeReader} and from the Kernel. + * + * Isolated and invalid UID info must be removed to conserve memory. However, STATSD and + * Batterystats both need to access UID cpu time. To resolve this race condition, only + * Batterystats shall remove UIDs, and a delay {@link Constants#UID_REMOVE_DELAY_MS} is + * implemented so that STATSD can capture those UID times before they are deleted. + */ + @GuardedBy("this") + @VisibleForTesting(visibility = VisibleForTesting.Visibility.PACKAGE) + protected Queue mPendingRemovedUids = new LinkedList<>(); + + @VisibleForTesting + public final class UidToRemove { + int startUid; + int endUid; + long timeAddedInQueue; + + /** Remove just one UID */ + public UidToRemove(int uid, long timestamp) { + this(uid, uid, timestamp); + } + + /** Remove a range of UIDs, startUid must be smaller than endUid. */ + public UidToRemove(int startUid, int endUid, long timestamp) { + this.startUid = startUid; + this.endUid = endUid; + timeAddedInQueue = timestamp; + } + + void remove() { + if (startUid == endUid) { + mKernelUidCpuTimeReader.removeUid(startUid); + mKernelUidCpuFreqTimeReader.removeUid(startUid); + if (mConstants.TRACK_CPU_ACTIVE_CLUSTER_TIME) { + mKernelUidCpuActiveTimeReader.removeUid(startUid); + mKernelUidCpuClusterTimeReader.removeUid(startUid); + } + if (mKernelSingleUidTimeReader != null) { + mKernelSingleUidTimeReader.removeUid(startUid); + } + mNumUidsRemoved++; + } else if (startUid < endUid) { + mKernelUidCpuFreqTimeReader.removeUidsInRange(startUid, endUid); + mKernelUidCpuTimeReader.removeUidsInRange(startUid, endUid); + if (mConstants.TRACK_CPU_ACTIVE_CLUSTER_TIME) { + mKernelUidCpuActiveTimeReader.removeUidsInRange(startUid, endUid); + mKernelUidCpuClusterTimeReader.removeUidsInRange(startUid, endUid); + } + if (mKernelSingleUidTimeReader != null) { + mKernelSingleUidTimeReader.removeUidsInRange(startUid, endUid); + } + // Treat as one. We don't know how many uids there are in between. + mNumUidsRemoved++; + } else { + Slog.w(TAG, "End UID " + endUid + " is smaller than start UID " + startUid); + } + } + } public interface BatteryCallback { public void batteryNeedsCpuUpdate(); @@ -376,6 +441,14 @@ public class BatteryStatsImpl extends BatteryStats { } } + public void clearPendingRemovedUids() { + long cutOffTime = mClocks.elapsedRealtime() - mConstants.UID_REMOVE_DELAY_MS; + while (!mPendingRemovedUids.isEmpty() + && mPendingRemovedUids.peek().timeAddedInQueue < cutOffTime) { + mPendingRemovedUids.poll().remove(); + } + } + public void copyFromAllUidsCpuTimes() { synchronized (BatteryStatsImpl.this) { copyFromAllUidsCpuTimes( @@ -3961,12 +4034,7 @@ public class BatteryStatsImpl extends BatteryStats { u.removeIsolatedUid(isolatedUid); mIsolatedUids.removeAt(idx); } - mKernelUidCpuTimeReader.removeUid(isolatedUid); - mKernelUidCpuFreqTimeReader.removeUid(isolatedUid); - if (mConstants.TRACK_CPU_ACTIVE_CLUSTER_TIME) { - mKernelUidCpuActiveTimeReader.removeUid(isolatedUid); - mKernelUidCpuClusterTimeReader.removeUid(isolatedUid); - } + mPendingRemovedUids.add(new UidToRemove(isolatedUid, mClocks.elapsedRealtime())); } public int mapUid(int uid) { @@ -9860,9 +9928,9 @@ public class BatteryStatsImpl extends BatteryStats { mBsi.mOnBatteryTimeBase.isRunning(), mBsi.mOnBatteryScreenOffTimeBase.isRunning(), mBsi.mConstants.PROC_STATE_CPU_TIMES_READ_DELAY_MS); - mBsi.mNumCpuTimeReads++; + mBsi.mNumSingleUidCpuTimeReads++; } else { - mBsi.mNumBatchedCpuTimeReads++; + mBsi.mNumBatchedSingleUidCpuTimeReads++; } if (mBsi.mPendingUids.indexOfKey(mUid) < 0 || ArrayUtils.contains(CRITICAL_PROC_STATES, mProcessState)) { @@ -11024,6 +11092,9 @@ public class BatteryStatsImpl extends BatteryStats { mLastStepStatSoftIrqTime = mCurStepStatSoftIrqTime = 0; mLastStepStatIdleTime = mCurStepStatIdleTime = 0; + mNumAllUidCpuTimeReads = 0; + mNumUidsRemoved = 0; + initDischarge(); clearHistoryLocked(); @@ -12009,9 +12080,11 @@ public class BatteryStatsImpl extends BatteryStats { if (!onBattery) { mKernelUidCpuTimeReader.readDelta(null); mKernelUidCpuFreqTimeReader.readDelta(null); + mNumAllUidCpuTimeReads += 2; if (mConstants.TRACK_CPU_ACTIVE_CLUSTER_TIME) { mKernelUidCpuActiveTimeReader.readDelta(null); mKernelUidCpuClusterTimeReader.readDelta(null); + mNumAllUidCpuTimeReads += 2; } for (int cluster = mKernelCpuSpeedReaders.length - 1; cluster >= 0; --cluster) { mKernelCpuSpeedReaders[cluster].readDelta(); @@ -12029,9 +12102,11 @@ public class BatteryStatsImpl extends BatteryStats { updateClusterSpeedTimes(updatedUids, onBattery); } readKernelUidCpuFreqTimesLocked(partialTimersToConsider, onBattery, onBatteryScreenOff); + mNumAllUidCpuTimeReads += 2; if (mConstants.TRACK_CPU_ACTIVE_CLUSTER_TIME) { readKernelUidCpuActiveTimesLocked(onBattery); readKernelUidCpuClusterTimesLocked(onBattery); + mNumAllUidCpuTimeReads += 2; } } @@ -13256,11 +13331,8 @@ public class BatteryStatsImpl extends BatteryStats { public void onCleanupUserLocked(int userId) { final int firstUidForUser = UserHandle.getUid(userId, 0); final int lastUidForUser = UserHandle.getUid(userId, UserHandle.PER_USER_RANGE - 1); - mKernelUidCpuFreqTimeReader.removeUidsInRange(firstUidForUser, lastUidForUser); - mKernelUidCpuTimeReader.removeUidsInRange(firstUidForUser, lastUidForUser); - if (mKernelSingleUidTimeReader != null) { - mKernelSingleUidTimeReader.removeUidsInRange(firstUidForUser, lastUidForUser); - } + mPendingRemovedUids.add( + new UidToRemove(firstUidForUser, lastUidForUser, mClocks.elapsedRealtime())); } public void onUserRemovedLocked(int userId) { @@ -13277,12 +13349,8 @@ public class BatteryStatsImpl extends BatteryStats { * Remove the statistics object for a particular uid. */ public void removeUidStatsLocked(int uid) { - mKernelUidCpuTimeReader.removeUid(uid); - mKernelUidCpuFreqTimeReader.removeUid(uid); - if (mKernelSingleUidTimeReader != null) { - mKernelSingleUidTimeReader.removeUid(uid); - } mUidStats.remove(uid); + mPendingRemovedUids.add(new UidToRemove(uid, mClocks.elapsedRealtime())); } /** @@ -13335,24 +13403,24 @@ public class BatteryStatsImpl extends BatteryStats { = "track_cpu_times_by_proc_state"; public static final String KEY_TRACK_CPU_ACTIVE_CLUSTER_TIME = "track_cpu_active_cluster_time"; - public static final String KEY_READ_BINARY_CPU_TIME - = "read_binary_cpu_time"; public static final String KEY_PROC_STATE_CPU_TIMES_READ_DELAY_MS = "proc_state_cpu_times_read_delay_ms"; public static final String KEY_KERNEL_UID_READERS_THROTTLE_TIME = "kernel_uid_readers_throttle_time"; + public static final String KEY_UID_REMOVE_DELAY_MS + = "uid_remove_delay_ms"; private static final boolean DEFAULT_TRACK_CPU_TIMES_BY_PROC_STATE = true; private static final boolean DEFAULT_TRACK_CPU_ACTIVE_CLUSTER_TIME = true; - private static final boolean DEFAULT_READ_BINARY_CPU_TIME = true; private static final long DEFAULT_PROC_STATE_CPU_TIMES_READ_DELAY_MS = 5_000; private static final long DEFAULT_KERNEL_UID_READERS_THROTTLE_TIME = 10_000; + private static final long DEFAULT_UID_REMOVE_DELAY_MS = 5L * 60L * 1000L; public boolean TRACK_CPU_TIMES_BY_PROC_STATE = DEFAULT_TRACK_CPU_TIMES_BY_PROC_STATE; public boolean TRACK_CPU_ACTIVE_CLUSTER_TIME = DEFAULT_TRACK_CPU_ACTIVE_CLUSTER_TIME; - public boolean READ_BINARY_CPU_TIME = DEFAULT_READ_BINARY_CPU_TIME; public long PROC_STATE_CPU_TIMES_READ_DELAY_MS = DEFAULT_PROC_STATE_CPU_TIMES_READ_DELAY_MS; public long KERNEL_UID_READERS_THROTTLE_TIME = DEFAULT_KERNEL_UID_READERS_THROTTLE_TIME; + public long UID_REMOVE_DELAY_MS = DEFAULT_UID_REMOVE_DELAY_MS; private ContentResolver mResolver; private final KeyValueListParser mParser = new KeyValueListParser(','); @@ -13390,14 +13458,14 @@ public class BatteryStatsImpl extends BatteryStats { DEFAULT_TRACK_CPU_TIMES_BY_PROC_STATE)); TRACK_CPU_ACTIVE_CLUSTER_TIME = mParser.getBoolean( KEY_TRACK_CPU_ACTIVE_CLUSTER_TIME, DEFAULT_TRACK_CPU_ACTIVE_CLUSTER_TIME); - updateReadBinaryCpuTime(READ_BINARY_CPU_TIME, - mParser.getBoolean(KEY_READ_BINARY_CPU_TIME, DEFAULT_READ_BINARY_CPU_TIME)); updateProcStateCpuTimesReadDelayMs(PROC_STATE_CPU_TIMES_READ_DELAY_MS, mParser.getLong(KEY_PROC_STATE_CPU_TIMES_READ_DELAY_MS, DEFAULT_PROC_STATE_CPU_TIMES_READ_DELAY_MS)); updateKernelUidReadersThrottleTime(KERNEL_UID_READERS_THROTTLE_TIME, mParser.getLong(KEY_KERNEL_UID_READERS_THROTTLE_TIME, DEFAULT_KERNEL_UID_READERS_THROTTLE_TIME)); + updateUidRemoveDelay( + mParser.getLong(KEY_UID_REMOVE_DELAY_MS, DEFAULT_UID_REMOVE_DELAY_MS)); } } @@ -13407,24 +13475,17 @@ public class BatteryStatsImpl extends BatteryStats { mKernelSingleUidTimeReader.markDataAsStale(true); mExternalSync.scheduleCpuSyncDueToSettingChange(); - mNumCpuTimeReads = 0; - mNumBatchedCpuTimeReads = 0; + mNumSingleUidCpuTimeReads = 0; + mNumBatchedSingleUidCpuTimeReads = 0; mCpuTimeReadsTrackingStartTime = mClocks.uptimeMillis(); } } - private void updateReadBinaryCpuTime(boolean oldEnabled, boolean isEnabled) { - READ_BINARY_CPU_TIME = isEnabled; - if (oldEnabled != isEnabled) { - mKernelUidCpuFreqTimeReader.setReadBinary(isEnabled); - } - } - private void updateProcStateCpuTimesReadDelayMs(long oldDelayMillis, long newDelayMillis) { PROC_STATE_CPU_TIMES_READ_DELAY_MS = newDelayMillis; if (oldDelayMillis != newDelayMillis) { - mNumCpuTimeReads = 0; - mNumBatchedCpuTimeReads = 0; + mNumSingleUidCpuTimeReads = 0; + mNumBatchedSingleUidCpuTimeReads = 0; mCpuTimeReadsTrackingStartTime = mClocks.uptimeMillis(); } } @@ -13440,13 +13501,16 @@ public class BatteryStatsImpl extends BatteryStats { } } + private void updateUidRemoveDelay(long newTimeMs) { + UID_REMOVE_DELAY_MS = newTimeMs; + clearPendingRemovedUids(); + } + public void dumpLocked(PrintWriter pw) { pw.print(KEY_TRACK_CPU_TIMES_BY_PROC_STATE); pw.print("="); pw.println(TRACK_CPU_TIMES_BY_PROC_STATE); pw.print(KEY_TRACK_CPU_ACTIVE_CLUSTER_TIME); pw.print("="); pw.println(TRACK_CPU_ACTIVE_CLUSTER_TIME); - pw.print(KEY_READ_BINARY_CPU_TIME); pw.print("="); - pw.println(READ_BINARY_CPU_TIME); pw.print(KEY_PROC_STATE_CPU_TIMES_READ_DELAY_MS); pw.print("="); pw.println(PROC_STATE_CPU_TIMES_READ_DELAY_MS); pw.print(KEY_KERNEL_UID_READERS_THROTTLE_TIME); pw.print("="); @@ -13459,6 +13523,43 @@ public class BatteryStatsImpl extends BatteryStats { mConstants.dumpLocked(pw); } + @GuardedBy("this") + public void dumpCpuStatsLocked(PrintWriter pw) { + int size = mUidStats.size(); + pw.println("Per UID CPU user & system time in ms:"); + for (int i = 0; i < size; i++) { + int u = mUidStats.keyAt(i); + Uid uid = mUidStats.get(u); + pw.print(" "); pw.print(u); pw.print(": "); + pw.print(uid.getUserCpuTimeUs(STATS_SINCE_CHARGED) / 1000); pw.print(" "); + pw.println(uid.getSystemCpuTimeUs(STATS_SINCE_CHARGED) / 1000); + } + pw.println("Per UID CPU active time in ms:"); + for (int i = 0; i < size; i++) { + int u = mUidStats.keyAt(i); + Uid uid = mUidStats.get(u); + if (uid.getCpuActiveTime() > 0) { + pw.print(" "); pw.print(u); pw.print(": "); pw.println(uid.getCpuActiveTime()); + } + } + pw.println("Per UID CPU cluster time in ms:"); + for (int i = 0; i < size; i++) { + int u = mUidStats.keyAt(i); + long[] times = mUidStats.get(u).getCpuClusterTimes(); + if (times != null) { + pw.print(" "); pw.print(u); pw.print(": "); pw.println(Arrays.toString(times)); + } + } + pw.println("Per UID CPU frequency time in ms:"); + for (int i = 0; i < size; i++) { + int u = mUidStats.keyAt(i); + long[] times = mUidStats.get(u).getCpuFreqTimes(STATS_SINCE_CHARGED); + if (times != null) { + pw.print(" "); pw.print(u); pw.print(": "); pw.println(Arrays.toString(times)); + } + } + } + Parcel mPendingWrite = null; final ReentrantLock mWriteLock = new ReentrantLock(); @@ -15183,10 +15284,14 @@ public class BatteryStatsImpl extends BatteryStats { } super.dumpLocked(context, pw, flags, reqUid, histStart); pw.print("Total cpu time reads: "); - pw.println(mNumCpuTimeReads); + pw.println(mNumSingleUidCpuTimeReads); pw.print("Batched cpu time reads: "); - pw.println(mNumBatchedCpuTimeReads); + pw.println(mNumBatchedSingleUidCpuTimeReads); pw.print("Batching Duration (min): "); pw.println((mClocks.uptimeMillis() - mCpuTimeReadsTrackingStartTime) / (60 * 1000)); + pw.print("All UID cpu time reads since the later of device start or stats reset: "); + pw.println(mNumAllUidCpuTimeReads); + pw.print("UIDs removed since the later of device start or stats reset: "); + pw.println(mNumUidsRemoved); } } diff --git a/core/java/com/android/internal/os/KernelUidCpuActiveTimeReader.java b/core/java/com/android/internal/os/KernelUidCpuActiveTimeReader.java index e790e08520cbc..bd8a67a8bd0ef 100644 --- a/core/java/com/android/internal/os/KernelUidCpuActiveTimeReader.java +++ b/core/java/com/android/internal/os/KernelUidCpuActiveTimeReader.java @@ -24,6 +24,7 @@ import com.android.internal.annotations.VisibleForTesting; import java.nio.ByteBuffer; import java.nio.IntBuffer; +import java.util.function.Consumer; /** * Reads binary proc file /proc/uid_cpupower/concurrent_active_time and reports CPU active time to @@ -54,6 +55,7 @@ public class KernelUidCpuActiveTimeReader extends private final KernelCpuProcReader mProcReader; private SparseArray mLastUidCpuActiveTimeMs = new SparseArray<>(); + private int mCores; public interface Callback extends KernelUidCpuTimeReaderBase.Callback { /** @@ -75,7 +77,60 @@ public class KernelUidCpuActiveTimeReader extends } @Override - protected void readDeltaImpl(@Nullable Callback cb) { + protected void readDeltaImpl(@Nullable Callback callback) { + readImpl((buf) -> { + int uid = buf.get(); + double activeTime = sumActiveTime(buf); + if (activeTime > 0) { + double delta = activeTime - mLastUidCpuActiveTimeMs.get(uid, 0.0); + if (delta > 0) { + mLastUidCpuActiveTimeMs.put(uid, activeTime); + if (callback != null) { + callback.onUidCpuActiveTime(uid, (long) delta); + } + } else if (delta < 0) { + Slog.e(TAG, "Negative delta from active time proc: " + delta); + } + } + }); + } + + public void readAbsolute(Callback callback) { + readImpl((buf) -> { + int uid = buf.get(); + double activeTime = sumActiveTime(buf); + if (activeTime > 0) { + callback.onUidCpuActiveTime(uid, (long) activeTime); + } + }); + } + + private double sumActiveTime(IntBuffer buffer) { + double sum = 0; + boolean corrupted = false; + for (int j = 1; j <= mCores; j++) { + int time = buffer.get(); + if (time < 0) { + // Even if error happens, we still need to continue reading. + // Buffer cannot be skipped. + Slog.e(TAG, "Negative time from active time proc: " + time); + corrupted = true; + } else { + sum += (double) time * 10 / j; // Unit is 10ms. + } + } + return corrupted ? -1 : sum; + } + + /** + * readImpl accepts a callback to process the uid entry. readDeltaImpl needs to store the last + * seen results while processing the buffer, while readAbsolute returns the absolute value read + * from the buffer without storing. So readImpl contains the common logic of the two, leaving + * the difference to a processUid function. + * + * @param processUid the callback function to process the uid entry in the buffer. + */ + private void readImpl(Consumer processUid) { synchronized (mProcReader) { final ByteBuffer bytes = mProcReader.readBytes(); if (bytes == null || bytes.remaining() <= 4) { @@ -89,6 +144,11 @@ public class KernelUidCpuActiveTimeReader extends } final IntBuffer buf = bytes.asIntBuffer(); final int cores = buf.get(); + if (mCores != 0 && cores != mCores) { + Slog.wtf(TAG, "Cpu active time wrong # cores: " + cores); + return; + } + mCores = cores; if (cores <= 0 || buf.remaining() % (cores + 1) != 0) { Slog.wtf(TAG, "Cpu active time format error: " + buf.remaining() + " / " + (cores @@ -97,25 +157,7 @@ public class KernelUidCpuActiveTimeReader extends } int numUids = buf.remaining() / (cores + 1); for (int i = 0; i < numUids; i++) { - int uid = buf.get(); - boolean corrupted = false; - double curTime = 0; - for (int j = 1; j <= cores; j++) { - int time = buf.get(); - if (time < 0) { - Slog.e(TAG, "Corrupted data from active time proc: " + time); - corrupted = true; - } else { - curTime += (double) time * 10 / j; // Unit is 10ms. - } - } - double delta = curTime - mLastUidCpuActiveTimeMs.get(uid, 0.0); - if (delta > 0 && !corrupted) { - mLastUidCpuActiveTimeMs.put(uid, curTime); - if (cb != null) { - cb.onUidCpuActiveTime(uid, (long) delta); - } - } + processUid.accept(buf); } if (DEBUG) { Slog.d(TAG, "Read uids: " + numUids); @@ -123,26 +165,11 @@ public class KernelUidCpuActiveTimeReader extends } } - public void readAbsolute(Callback cb) { - synchronized (mProcReader) { - readDelta(null); - int total = mLastUidCpuActiveTimeMs.size(); - for (int i = 0; i < total; i ++){ - int uid = mLastUidCpuActiveTimeMs.keyAt(i); - cb.onUidCpuActiveTime(uid, mLastUidCpuActiveTimeMs.get(uid).longValue()); - } - } - } - public void removeUid(int uid) { mLastUidCpuActiveTimeMs.delete(uid); } public void removeUidsInRange(int startUid, int endUid) { - if (endUid < startUid) { - Slog.w(TAG, "End UID " + endUid + " is smaller than start UID " + startUid); - return; - } mLastUidCpuActiveTimeMs.put(startUid, null); mLastUidCpuActiveTimeMs.put(endUid, null); final int firstIndex = mLastUidCpuActiveTimeMs.indexOfKey(startUid); diff --git a/core/java/com/android/internal/os/KernelUidCpuClusterTimeReader.java b/core/java/com/android/internal/os/KernelUidCpuClusterTimeReader.java index bf5b5203eb3f7..3cbfaead47796 100644 --- a/core/java/com/android/internal/os/KernelUidCpuClusterTimeReader.java +++ b/core/java/com/android/internal/os/KernelUidCpuClusterTimeReader.java @@ -24,6 +24,7 @@ import com.android.internal.annotations.VisibleForTesting; import java.nio.ByteBuffer; import java.nio.IntBuffer; +import java.util.function.Consumer; /** * Reads binary proc file /proc/uid_cpupower/concurrent_policy_time and reports CPU cluster times @@ -89,6 +90,72 @@ public class KernelUidCpuClusterTimeReader extends @Override protected void readDeltaImpl(@Nullable Callback cb) { + readImpl((buf) -> { + int uid = buf.get(); + double[] lastTimes = mLastUidPolicyTimeMs.get(uid); + if (lastTimes == null) { + lastTimes = new double[mNumClusters]; + mLastUidPolicyTimeMs.put(uid, lastTimes); + } + if (!sumClusterTime(buf, mCurTime)) { + return; + } + boolean valid = true; + boolean notify = false; + for (int i = 0; i < mNumClusters; i++) { + mDeltaTime[i] = (long) (mCurTime[i] - lastTimes[i]); + if (mDeltaTime[i] < 0) { + Slog.e(TAG, "Negative delta from cluster time proc: " + mDeltaTime[i]); + valid = false; + } + notify |= mDeltaTime[i] > 0; + } + if (notify && valid) { + System.arraycopy(mCurTime, 0, lastTimes, 0, mNumClusters); + if (cb != null) { + cb.onUidCpuPolicyTime(uid, mDeltaTime); + } + } + }); + } + + public void readAbsolute(Callback callback) { + readImpl((buf) -> { + int uid = buf.get(); + if (sumClusterTime(buf, mCurTime)) { + for (int i = 0; i < mNumClusters; i++) { + mCurTimeRounded[i] = (long) mCurTime[i]; + } + callback.onUidCpuPolicyTime(uid, mCurTimeRounded); + } + }); + } + + private boolean sumClusterTime(IntBuffer buffer, double[] clusterTime) { + boolean valid = true; + for (int i = 0; i < mNumClusters; i++) { + clusterTime[i] = 0; + for (int j = 1; j <= mNumCoresOnCluster[i]; j++) { + int time = buffer.get(); + if (time < 0) { + Slog.e(TAG, "Negative time from cluster time proc: " + time); + valid = false; + } + clusterTime[i] += (double) time * 10 / j; // Unit is 10ms. + } + } + return valid; + } + + /** + * readImpl accepts a callback to process the uid entry. readDeltaImpl needs to store the last + * seen results while processing the buffer, while readAbsolute returns the absolute value read + * from the buffer without storing. So readImpl contains the common logic of the two, leaving + * the difference to a processUid function. + * + * @param processUid the callback function to process the uid entry in the buffer. + */ + private void readImpl(Consumer processUid) { synchronized (mProcReader) { ByteBuffer bytes = mProcReader.readBytes(); if (bytes == null || bytes.remaining() <= 4) { @@ -130,7 +197,7 @@ public class KernelUidCpuClusterTimeReader extends int numUids = buf.remaining() / (mNumCores + 1); for (int i = 0; i < numUids; i++) { - processUid(buf, cb); + processUid.accept(buf); } if (DEBUG) { Slog.d(TAG, "Read uids: " + numUids); @@ -138,57 +205,6 @@ public class KernelUidCpuClusterTimeReader extends } } - public void readAbsolute(Callback cb) { - synchronized (mProcReader) { - readDelta(null); - int total = mLastUidPolicyTimeMs.size(); - for (int i = 0; i < total; i ++){ - int uid = mLastUidPolicyTimeMs.keyAt(i); - double[] lastTimes = mLastUidPolicyTimeMs.get(uid); - for (int j = 0; j < mNumClusters; j++) { - mCurTimeRounded[j] = (long) lastTimes[j]; - } - cb.onUidCpuPolicyTime(uid, mCurTimeRounded); - } - } - } - - private void processUid(IntBuffer buf, @Nullable Callback cb) { - int uid = buf.get(); - double[] lastTimes = mLastUidPolicyTimeMs.get(uid); - if (lastTimes == null) { - lastTimes = new double[mNumClusters]; - mLastUidPolicyTimeMs.put(uid, lastTimes); - } - - boolean notify = false; - boolean corrupted = false; - - for (int j = 0; j < mNumClusters; j++) { - mCurTime[j] = 0; - for (int k = 1; k <= mNumCoresOnCluster[j]; k++) { - int time = buf.get(); - if (time < 0) { - Slog.e(TAG, "Corrupted data from cluster time proc uid: " + uid); - corrupted = true; - } - mCurTime[j] += (double) time * 10 / k; // Unit is 10ms. - } - mDeltaTime[j] = (long) (mCurTime[j] - lastTimes[j]); - if (mDeltaTime[j] < 0) { - Slog.e(TAG, "Unexpected delta from cluster time proc uid: " + uid); - corrupted = true; - } - notify |= mDeltaTime[j] > 0; - } - if (notify && !corrupted) { - System.arraycopy(mCurTime, 0, lastTimes, 0, mNumClusters); - if (cb != null) { - cb.onUidCpuPolicyTime(uid, mDeltaTime); - } - } - } - // Returns if it has read valid info. private boolean readCoreInfo(IntBuffer buf, int numClusters) { int numCores = 0; @@ -214,10 +230,6 @@ public class KernelUidCpuClusterTimeReader extends } public void removeUidsInRange(int startUid, int endUid) { - if (endUid < startUid) { - Slog.w(TAG, "End UID " + endUid + " is smaller than start UID " + startUid); - return; - } mLastUidPolicyTimeMs.put(startUid, null); mLastUidPolicyTimeMs.put(endUid, null); final int firstIndex = mLastUidPolicyTimeMs.indexOfKey(startUid); diff --git a/core/java/com/android/internal/os/KernelUidCpuFreqTimeReader.java b/core/java/com/android/internal/os/KernelUidCpuFreqTimeReader.java index f65074f65d874..5b46d0f29c20a 100644 --- a/core/java/com/android/internal/os/KernelUidCpuFreqTimeReader.java +++ b/core/java/com/android/internal/os/KernelUidCpuFreqTimeReader.java @@ -21,11 +21,9 @@ import static com.android.internal.util.Preconditions.checkNotNull; import android.annotation.NonNull; import android.annotation.Nullable; import android.os.StrictMode; -import android.os.SystemClock; import android.util.IntArray; import android.util.Slog; import android.util.SparseArray; -import android.util.TimeUtils; import com.android.internal.annotations.VisibleForTesting; @@ -34,6 +32,7 @@ import java.io.FileReader; import java.io.IOException; import java.nio.ByteBuffer; import java.nio.IntBuffer; +import java.util.function.Consumer; /** * Reads /proc/uid_time_in_state which has the format: @@ -75,9 +74,6 @@ public class KernelUidCpuFreqTimeReader extends private long[] mCurTimes; // Reuse to prevent GC. private long[] mDeltaTimes; // Reuse to prevent GC. private int mCpuFreqsCount; - private long mLastTimeReadMs = Long.MIN_VALUE; - private long mNowTimeMs; - private boolean mReadBinary = true; private final KernelCpuProcReader mProcReader; private SparseArray mLastUidCpuFreqTimeMs = new SparseArray<>(); @@ -140,180 +136,6 @@ public class KernelUidCpuFreqTimeReader extends if (line == null) { return null; } - return readCpuFreqs(line, powerProfile); - } - - public void setReadBinary(boolean readBinary) { - mReadBinary = readBinary; - } - - @Override - protected void readDeltaImpl(@Nullable Callback callback) { - if (mCpuFreqs == null) { - return; - } - if (mReadBinary) { - readDeltaBinary(callback); - } else { - readDeltaString(callback); - } - } - - private void readDeltaString(@Nullable Callback callback) { - mNowTimeMs = SystemClock.elapsedRealtime(); - final int oldMask = StrictMode.allowThreadDiskReadsMask(); - try (BufferedReader reader = new BufferedReader(new FileReader(UID_TIMES_PROC_FILE))) { - readDelta(reader, callback); - } catch (IOException e) { - Slog.e(TAG, "Failed to read " + UID_TIMES_PROC_FILE + ": " + e); - } finally { - StrictMode.setThreadPolicyMask(oldMask); - } - mLastTimeReadMs = mNowTimeMs; - } - - @VisibleForTesting - public void readDeltaBinary(@Nullable Callback callback) { - synchronized (mProcReader) { - ByteBuffer bytes = mProcReader.readBytes(); - if (bytes == null || bytes.remaining() <= 4) { - // Error already logged in mProcReader. - return; - } - if ((bytes.remaining() & 3) != 0) { - Slog.wtf(TAG, "Cannot parse cluster time proc bytes to int: " + bytes.remaining()); - return; - } - IntBuffer buf = bytes.asIntBuffer(); - final int freqs = buf.get(); - if (freqs != mCpuFreqsCount) { - Slog.wtf(TAG, "Cpu freqs expect " + mCpuFreqsCount + " , got " + freqs); - return; - } - if (buf.remaining() % (freqs + 1) != 0) { - Slog.wtf(TAG, "Freq time format error: " + buf.remaining() + " / " + (freqs + 1)); - return; - } - int numUids = buf.remaining() / (freqs + 1); - for (int i = 0; i < numUids; i++) { - int uid = buf.get(); - long[] lastTimes = mLastUidCpuFreqTimeMs.get(uid); - if (lastTimes == null) { - lastTimes = new long[mCpuFreqsCount]; - mLastUidCpuFreqTimeMs.put(uid, lastTimes); - } - boolean notify = false; - boolean corrupted = false; - for (int j = 0; j < freqs; j++) { - mCurTimes[j] = (long) buf.get() * 10; // Unit is 10ms. - mDeltaTimes[j] = mCurTimes[j] - lastTimes[j]; - if (mCurTimes[j] < 0 || mDeltaTimes[j] < 0) { - Slog.e(TAG, "Unexpected data from freq time proc: " + mCurTimes[j]); - corrupted = true; - } - notify |= mDeltaTimes[j] > 0; - } - if (notify && !corrupted) { - System.arraycopy(mCurTimes, 0, lastTimes, 0, freqs); - if (callback != null) { - callback.onUidCpuFreqTime(uid, mDeltaTimes); - } - } - } - if (DEBUG) { - Slog.d(TAG, "Read uids: " + numUids); - } - } - } - - public void readAbsolute(Callback cb) { - synchronized (mProcReader) { - readDelta(null); - int total = mLastUidCpuFreqTimeMs.size(); - for (int i = 0; i < total; i ++){ - int uid = mLastUidCpuFreqTimeMs.keyAt(i); - cb.onUidCpuFreqTime(uid, mLastUidCpuFreqTimeMs.get(uid)); - } - } - } - - public void removeUid(int uid) { - mLastUidCpuFreqTimeMs.delete(uid); - } - - public void removeUidsInRange(int startUid, int endUid) { - if (endUid < startUid) { - return; - } - mLastUidCpuFreqTimeMs.put(startUid, null); - mLastUidCpuFreqTimeMs.put(endUid, null); - final int firstIndex = mLastUidCpuFreqTimeMs.indexOfKey(startUid); - final int lastIndex = mLastUidCpuFreqTimeMs.indexOfKey(endUid); - mLastUidCpuFreqTimeMs.removeAtRange(firstIndex, lastIndex - firstIndex + 1); - } - - @VisibleForTesting - public void readDelta(BufferedReader reader, @Nullable Callback callback) throws IOException { - String line = reader.readLine(); - if (line == null) { - return; - } - while ((line = reader.readLine()) != null) { - final int index = line.indexOf(' '); - final int uid = Integer.parseInt(line.substring(0, index - 1), 10); - readTimesForUid(uid, line.substring(index + 1, line.length()), callback); - } - } - - private void readTimesForUid(int uid, String line, Callback callback) { - long[] uidTimeMs = mLastUidCpuFreqTimeMs.get(uid); - if (uidTimeMs == null) { - uidTimeMs = new long[mCpuFreqsCount]; - mLastUidCpuFreqTimeMs.put(uid, uidTimeMs); - } - final String[] timesStr = line.split(" "); - final int size = timesStr.length; - if (size != uidTimeMs.length) { - Slog.e(TAG, "No. of readings don't match cpu freqs, readings: " + size - + " cpuFreqsCount: " + uidTimeMs.length); - return; - } - final long[] deltaUidTimeMs = new long[size]; - final long[] curUidTimeMs = new long[size]; - boolean notify = false; - for (int i = 0; i < size; ++i) { - // Times read will be in units of 10ms - final long totalTimeMs = Long.parseLong(timesStr[i], 10) * 10; - deltaUidTimeMs[i] = totalTimeMs - uidTimeMs[i]; - // If there is malformed data for any uid, then we just log about it and ignore - // the data for that uid. - if (deltaUidTimeMs[i] < 0 || totalTimeMs < 0) { - if (DEBUG) { - final StringBuilder sb = new StringBuilder("Malformed cpu freq data for UID=") - .append(uid).append("\n"); - sb.append("data=").append("(").append(uidTimeMs[i]).append(",") - .append(totalTimeMs).append(")").append("\n"); - sb.append("times=").append("("); - TimeUtils.formatDuration(mLastTimeReadMs, sb); - sb.append(","); - TimeUtils.formatDuration(mNowTimeMs, sb); - sb.append(")"); - Slog.e(TAG, sb.toString()); - } - return; - } - curUidTimeMs[i] = totalTimeMs; - notify = notify || (deltaUidTimeMs[i] > 0); - } - if (notify) { - System.arraycopy(curUidTimeMs, 0, uidTimeMs, 0, size); - if (callback != null) { - callback.onUidCpuFreqTime(uid, deltaUidTimeMs); - } - } - } - - private long[] readCpuFreqs(String line, PowerProfile powerProfile) { final String[] freqStr = line.split(" "); // First item would be "uid: " which needs to be ignored. mCpuFreqsCount = freqStr.length - 1; @@ -339,10 +161,116 @@ public class KernelUidCpuFreqTimeReader extends mPerClusterTimesAvailable = false; } Slog.i(TAG, "mPerClusterTimesAvailable=" + mPerClusterTimesAvailable); - return mCpuFreqs; } + @Override + @VisibleForTesting + public void readDeltaImpl(@Nullable Callback callback) { + if (mCpuFreqs == null) { + return; + } + readImpl((buf) -> { + int uid = buf.get(); + long[] lastTimes = mLastUidCpuFreqTimeMs.get(uid); + if (lastTimes == null) { + lastTimes = new long[mCpuFreqsCount]; + mLastUidCpuFreqTimeMs.put(uid, lastTimes); + } + if (!getFreqTimeForUid(buf, mCurTimes)) { + return; + } + boolean notify = false; + boolean valid = true; + for (int i = 0; i < mCpuFreqsCount; i++) { + mDeltaTimes[i] = mCurTimes[i] - lastTimes[i]; + if (mDeltaTimes[i] < 0) { + Slog.e(TAG, "Negative delta from freq time proc: " + mDeltaTimes[i]); + valid = false; + } + notify |= mDeltaTimes[i] > 0; + } + if (notify && valid) { + System.arraycopy(mCurTimes, 0, lastTimes, 0, mCpuFreqsCount); + if (callback != null) { + callback.onUidCpuFreqTime(uid, mDeltaTimes); + } + } + }); + } + + public void readAbsolute(Callback callback) { + readImpl((buf) -> { + int uid = buf.get(); + if (getFreqTimeForUid(buf, mCurTimes)) { + callback.onUidCpuFreqTime(uid, mCurTimes); + } + }); + } + + private boolean getFreqTimeForUid(IntBuffer buffer, long[] freqTime) { + boolean valid = true; + for (int i = 0; i < mCpuFreqsCount; i++) { + freqTime[i] = (long) buffer.get() * 10; // Unit is 10ms. + if (freqTime[i] < 0) { + Slog.e(TAG, "Negative time from freq time proc: " + freqTime[i]); + valid = false; + } + } + return valid; + } + + /** + * readImpl accepts a callback to process the uid entry. readDeltaImpl needs to store the last + * seen results while processing the buffer, while readAbsolute returns the absolute value read + * from the buffer without storing. So readImpl contains the common logic of the two, leaving + * the difference to a processUid function. + * + * @param processUid the callback function to process the uid entry in the buffer. + */ + private void readImpl(Consumer processUid) { + synchronized (mProcReader) { + ByteBuffer bytes = mProcReader.readBytes(); + if (bytes == null || bytes.remaining() <= 4) { + // Error already logged in mProcReader. + return; + } + if ((bytes.remaining() & 3) != 0) { + Slog.wtf(TAG, "Cannot parse freq time proc bytes to int: " + bytes.remaining()); + return; + } + IntBuffer buf = bytes.asIntBuffer(); + final int freqs = buf.get(); + if (freqs != mCpuFreqsCount) { + Slog.wtf(TAG, "Cpu freqs expect " + mCpuFreqsCount + " , got " + freqs); + return; + } + if (buf.remaining() % (freqs + 1) != 0) { + Slog.wtf(TAG, "Freq time format error: " + buf.remaining() + " / " + (freqs + 1)); + return; + } + int numUids = buf.remaining() / (freqs + 1); + for (int i = 0; i < numUids; i++) { + processUid.accept(buf); + } + if (DEBUG) { + Slog.d(TAG, "Read uids: #" + numUids); + } + } + } + + public void removeUid(int uid) { + mLastUidCpuFreqTimeMs.delete(uid); + } + + public void removeUidsInRange(int startUid, int endUid) { + mLastUidCpuFreqTimeMs.put(startUid, null); + mLastUidCpuFreqTimeMs.put(endUid, null); + final int firstIndex = mLastUidCpuFreqTimeMs.indexOfKey(startUid); + final int lastIndex = mLastUidCpuFreqTimeMs.indexOfKey(endUid); + mLastUidCpuFreqTimeMs.removeAtRange(firstIndex, lastIndex - firstIndex + 1); + } + /** * Extracts no. of cpu clusters and no. of freqs in each of these clusters from the freqs * read from the proc file. diff --git a/core/tests/coretests/src/com/android/internal/os/BatteryStatsCpuTimesTest.java b/core/tests/coretests/src/com/android/internal/os/BatteryStatsCpuTimesTest.java index cb049b780fa83..ee8d5081b0b33 100644 --- a/core/tests/coretests/src/com/android/internal/os/BatteryStatsCpuTimesTest.java +++ b/core/tests/coretests/src/com/android/internal/os/BatteryStatsCpuTimesTest.java @@ -1084,6 +1084,49 @@ public class BatteryStatsCpuTimesTest { } } + @Test + public void testReadKernelUidCpuActiveTimesLocked_invalidUid() { + // PRECONDITIONS + updateTimeBasesLocked(true, Display.STATE_ON, 0, 0); + + final int testUserId = 11; + final int invalidUserId = 15; + final int invalidUid = UserHandle.getUid(invalidUserId, FIRST_APPLICATION_UID + 99); + when(mUserInfoProvider.exists(testUserId)).thenReturn(true); + when(mUserInfoProvider.exists(invalidUserId)).thenReturn(false); + final int[] testUids = getUids(testUserId, new int[]{ + FIRST_APPLICATION_UID + 22, + FIRST_APPLICATION_UID + 27, + FIRST_APPLICATION_UID + 33 + }); + final long[] uidTimesMs = {8000, 25000, 3000, 0, 42000}; + doAnswer(invocation -> { + final KernelUidCpuActiveTimeReader.Callback callback = + (KernelUidCpuActiveTimeReader.Callback) invocation.getArguments()[0]; + for (int i = 0; i < testUids.length; ++i) { + callback.onUidCpuActiveTime(testUids[i], uidTimesMs[i]); + } + // And one for the invalid uid + callback.onUidCpuActiveTime(invalidUid, 1200L); + return null; + }).when(mKernelUidCpuActiveTimeReader).readDelta( + any(KernelUidCpuActiveTimeReader.Callback.class)); + + // RUN + mBatteryStatsImpl.readKernelUidCpuActiveTimesLocked(true); + + // VERIFY + for (int i = 0; i < testUids.length; ++i) { + final BatteryStats.Uid u = mBatteryStatsImpl.getUidStats().get(testUids[i]); + assertNotNull("No entry for uid=" + testUids[i], u); + assertEquals("Unexpected cpu active time for uid=" + testUids[i], uidTimesMs[i], + u.getCpuActiveTime()); + } + assertNull("There shouldn't be an entry for invalid uid=" + invalidUid, + mBatteryStatsImpl.getUidStats().get(invalidUid)); + verify(mKernelUidCpuActiveTimeReader).removeUid(invalidUid); + } + @Test public void testReadKernelUidCpuClusterTimesLocked() { // PRECONDITIONS @@ -1153,6 +1196,97 @@ public class BatteryStatsCpuTimesTest { } } + @Test + public void testReadKernelUidCpuClusterTimesLocked_invalidUid() { + // PRECONDITIONS + updateTimeBasesLocked(true, Display.STATE_ON, 0, 0); + + final int testUserId = 11; + final int invalidUserId = 15; + final int invalidUid = UserHandle.getUid(invalidUserId, FIRST_APPLICATION_UID + 99); + when(mUserInfoProvider.exists(testUserId)).thenReturn(true); + when(mUserInfoProvider.exists(invalidUserId)).thenReturn(false); + final int[] testUids = getUids(testUserId, new int[]{ + FIRST_APPLICATION_UID + 22, + FIRST_APPLICATION_UID + 27, + FIRST_APPLICATION_UID + 33 + }); + final long[][] uidTimesMs = { + {4000, 10000}, + {5000, 1000}, + {8000, 0} + }; + doAnswer(invocation -> { + final KernelUidCpuClusterTimeReader.Callback callback = + (KernelUidCpuClusterTimeReader.Callback) invocation.getArguments()[0]; + for (int i = 0; i < testUids.length; ++i) { + callback.onUidCpuPolicyTime(testUids[i], uidTimesMs[i]); + } + // And one for the invalid uid + callback.onUidCpuPolicyTime(invalidUid, new long[] {400, 1000}); + return null; + }).when(mKernelUidCpuClusterTimeReader).readDelta( + any(KernelUidCpuClusterTimeReader.Callback.class)); + + // RUN + mBatteryStatsImpl.readKernelUidCpuClusterTimesLocked(true); + + // VERIFY + for (int i = 0; i < testUids.length; ++i) { + final BatteryStats.Uid u = mBatteryStatsImpl.getUidStats().get(testUids[i]); + assertNotNull("No entry for uid=" + testUids[i], u); + assertArrayEquals("Unexpected cpu cluster time for uid=" + testUids[i], uidTimesMs[i], + u.getCpuClusterTimes()); + } + assertNull("There shouldn't be an entry for invalid uid=" + invalidUid, + mBatteryStatsImpl.getUidStats().get(invalidUid)); + verify(mKernelUidCpuClusterTimeReader).removeUid(invalidUid); + } + + @Test + public void testRemoveUidCpuTimes() { + mClocks.realtime = mClocks.uptime = 0; + mBatteryStatsImpl.getPendingRemovedUids().add( + mBatteryStatsImpl.new UidToRemove(1, mClocks.elapsedRealtime())); + mBatteryStatsImpl.getPendingRemovedUids().add( + mBatteryStatsImpl.new UidToRemove(5, 10, mClocks.elapsedRealtime())); + mBatteryStatsImpl.clearPendingRemovedUids(); + assertEquals(2, mBatteryStatsImpl.getPendingRemovedUids().size()); + + mClocks.realtime = mClocks.uptime = 100_000; + mBatteryStatsImpl.clearPendingRemovedUids(); + assertEquals(2, mBatteryStatsImpl.getPendingRemovedUids().size()); + + mClocks.realtime = mClocks.uptime = 200_000; + mBatteryStatsImpl.getPendingRemovedUids().add( + mBatteryStatsImpl.new UidToRemove(100, mClocks.elapsedRealtime())); + mBatteryStatsImpl.clearPendingRemovedUids(); + assertEquals(3, mBatteryStatsImpl.getPendingRemovedUids().size()); + + mClocks.realtime = mClocks.uptime = 400_000; + mBatteryStatsImpl.clearPendingRemovedUids(); + assertEquals(1, mBatteryStatsImpl.getPendingRemovedUids().size()); + verify(mKernelUidCpuActiveTimeReader).removeUid(1); + verify(mKernelUidCpuActiveTimeReader).removeUidsInRange(5, 10); + verify(mKernelUidCpuClusterTimeReader).removeUid(1); + verify(mKernelUidCpuClusterTimeReader).removeUidsInRange(5, 10); + verify(mKernelUidCpuFreqTimeReader).removeUid(1); + verify(mKernelUidCpuFreqTimeReader).removeUidsInRange(5, 10); + verify(mKernelUidCpuTimeReader).removeUid(1); + verify(mKernelUidCpuTimeReader).removeUidsInRange(5, 10); + + mClocks.realtime = mClocks.uptime = 800_000; + mBatteryStatsImpl.clearPendingRemovedUids(); + assertEquals(0, mBatteryStatsImpl.getPendingRemovedUids().size()); + verify(mKernelUidCpuActiveTimeReader).removeUid(100); + verify(mKernelUidCpuClusterTimeReader).removeUid(100); + verify(mKernelUidCpuFreqTimeReader).removeUid(100); + verify(mKernelUidCpuTimeReader).removeUid(100); + + verifyNoMoreInteractions(mKernelUidCpuActiveTimeReader, mKernelUidCpuClusterTimeReader, + mKernelUidCpuFreqTimeReader, mKernelUidCpuTimeReader); + } + private void updateTimeBasesLocked(boolean unplugged, int screenState, long upTime, long realTime) { // Set PowerProfile=null before calling updateTimeBasesLocked to avoid execution of diff --git a/core/tests/coretests/src/com/android/internal/os/BatteryStatsNoteTest.java b/core/tests/coretests/src/com/android/internal/os/BatteryStatsNoteTest.java index 01ddc15efb47f..8cbe5d68d5540 100644 --- a/core/tests/coretests/src/com/android/internal/os/BatteryStatsNoteTest.java +++ b/core/tests/coretests/src/com/android/internal/os/BatteryStatsNoteTest.java @@ -244,13 +244,16 @@ public class BatteryStatsNoteTest extends TestCase { assertEquals(bi.getScreenState(), Display.STATE_OFF); } - /** + /* * Test BatteryStatsImpl.noteScreenStateLocked updates timers correctly. * * Unknown and doze should both be subset of off state * - * Timeline 0----100----200----310----400------------1000 Unknown ------- On ------- Off - * ------- ---------------------- Doze ---------------- + * Timeline 0----100----200----310----400------------1000 + * Unknown ------- + * On ------- + * Off ------- ---------------------- + * Doze ---------------- */ @SmallTest public void testNoteScreenStateTimersLocked() throws Exception { diff --git a/core/tests/coretests/src/com/android/internal/os/KernelUidCpuActiveTimeReaderTest.java b/core/tests/coretests/src/com/android/internal/os/KernelUidCpuActiveTimeReaderTest.java index 06f51c9c42a8f..28570e8fa747c 100644 --- a/core/tests/coretests/src/com/android/internal/os/KernelUidCpuActiveTimeReaderTest.java +++ b/core/tests/coretests/src/com/android/internal/os/KernelUidCpuActiveTimeReaderTest.java @@ -57,7 +57,7 @@ public class KernelUidCpuActiveTimeReaderTest { } @Test - public void testReadDelta() throws Exception { + public void testReadDelta() { final int cores = 8; final int[] uids = {1, 22, 333, 4444, 5555}; @@ -104,7 +104,7 @@ public class KernelUidCpuActiveTimeReaderTest { } @Test - public void testReadAbsolute() throws Exception { + public void testReadAbsolute() { final int cores = 8; final int[] uids = {1, 22, 333, 4444, 5555}; @@ -128,7 +128,7 @@ public class KernelUidCpuActiveTimeReaderTest { } @Test - public void testReadDelta_malformedData() throws Exception { + public void testReadDelta_malformedData() { final int cores = 8; final int[] uids = {1, 22, 333, 4444, 5555}; final long[][] times = increaseTime(new long[uids.length][cores]); diff --git a/core/tests/coretests/src/com/android/internal/os/KernelUidCpuFreqTimeReaderTest.java b/core/tests/coretests/src/com/android/internal/os/KernelUidCpuFreqTimeReaderTest.java index a6b99c30315a5..67c4e6161da66 100644 --- a/core/tests/coretests/src/com/android/internal/os/KernelUidCpuFreqTimeReaderTest.java +++ b/core/tests/coretests/src/com/android/internal/os/KernelUidCpuFreqTimeReaderTest.java @@ -21,7 +21,6 @@ import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertTrue; -import static org.mockito.Mockito.verifyNoMoreInteractions; import static org.mockito.Mockito.verifyZeroInteractions; import static org.mockito.Mockito.when; @@ -144,82 +143,6 @@ public class KernelUidCpuFreqTimeReaderTest { } } - @Test - public void testReadDelta() throws Exception { - final long[] freqs = {1, 12, 123, 1234, 12345, 123456}; - final int[] uids = {1, 22, 333, 4444, 5555}; - final long[][] times = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - times[i][j] = uids[i] * freqs[j] * 10; - } - } - when(mBufferedReader.readLine()).thenReturn(getFreqsLine(freqs)); - long[] actualFreqs = mKernelUidCpuFreqTimeReader.readFreqs(mBufferedReader, mPowerProfile); - - assertArrayEquals(freqs, actualFreqs); - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, times)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], times[i]); - } - verifyNoMoreInteractions(mCallback); - - // Verify that a second call will only return deltas. - Mockito.reset(mCallback, mBufferedReader); - final long[][] newTimes1 = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - newTimes1[i][j] = (times[i][j] + uids[i] + freqs[j]) * 10; - } - } - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], subtract(newTimes1[i], times[i])); - } - verifyNoMoreInteractions(mCallback); - - // Verify that there won't be a callback if the proc file values didn't change. - Mockito.reset(mCallback, mBufferedReader); - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - verifyNoMoreInteractions(mCallback); - - // Verify that calling with a null callback doesn't result in any crashes - Mockito.reset(mCallback, mBufferedReader); - final long[][] newTimes2 = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - newTimes2[i][j] = (newTimes1[i][j] + uids[i] * freqs[j]) * 10; - } - } - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes2)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, null); - - // Verify that the readDelta call will only return deltas when - // the previous call had null callback. - Mockito.reset(mCallback, mBufferedReader); - final long[][] newTimes3 = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - newTimes3[i][j] = (newTimes2[i][j] * (uids[i] + freqs[j])) * 10; - } - } - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes3)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], - subtract(newTimes3[i], newTimes2[i])); - } - verifyNoMoreInteractions(mCallback); - } - @Test public void testReadDelta_Binary() throws Exception { VerifiableCallback cb = new VerifiableCallback(); @@ -236,7 +159,7 @@ public class KernelUidCpuFreqTimeReaderTest { assertArrayEquals(freqs, actualFreqs); when(mProcReader.readBytes()).thenReturn(getUidTimesBytes(uids, times)); - mKernelUidCpuFreqTimeReader.readDeltaBinary(cb); + mKernelUidCpuFreqTimeReader.readDeltaImpl(cb); for (int i = 0; i < uids.length; ++i) { cb.verify(uids[i], times[i]); } @@ -252,7 +175,7 @@ public class KernelUidCpuFreqTimeReaderTest { } } when(mProcReader.readBytes()).thenReturn(getUidTimesBytes(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDeltaBinary(cb); + mKernelUidCpuFreqTimeReader.readDeltaImpl(cb); for (int i = 0; i < uids.length; ++i) { cb.verify(uids[i], subtract(newTimes1[i], times[i])); } @@ -262,7 +185,7 @@ public class KernelUidCpuFreqTimeReaderTest { cb.clear(); Mockito.reset(mProcReader); when(mProcReader.readBytes()).thenReturn(getUidTimesBytes(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDeltaBinary(cb); + mKernelUidCpuFreqTimeReader.readDeltaImpl(cb); cb.verifyNoMoreInteractions(); // Verify that calling with a null callback doesn't result in any crashes @@ -275,7 +198,7 @@ public class KernelUidCpuFreqTimeReaderTest { } } when(mProcReader.readBytes()).thenReturn(getUidTimesBytes(uids, newTimes2)); - mKernelUidCpuFreqTimeReader.readDeltaBinary(null); + mKernelUidCpuFreqTimeReader.readDeltaImpl(null); cb.verifyNoMoreInteractions(); // Verify that the readDelta call will only return deltas when @@ -289,7 +212,7 @@ public class KernelUidCpuFreqTimeReaderTest { } } when(mProcReader.readBytes()).thenReturn(getUidTimesBytes(uids, newTimes3)); - mKernelUidCpuFreqTimeReader.readDeltaBinary(cb); + mKernelUidCpuFreqTimeReader.readDeltaImpl(cb); for (int i = 0; i < uids.length; ++i) { cb.verify(uids[i], subtract(newTimes3[i], newTimes2[i])); } @@ -336,91 +259,6 @@ public class KernelUidCpuFreqTimeReaderTest { cb.verifyNoMoreInteractions(); } - @Test - public void testReadDelta_malformedData() throws Exception { - final long[] freqs = {1, 12, 123, 1234, 12345, 123456}; - final int[] uids = {1, 22, 333, 4444, 5555}; - final long[][] times = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - times[i][j] = uids[i] * freqs[j] * 10; - } - } - when(mBufferedReader.readLine()).thenReturn(getFreqsLine(freqs)); - long[] actualFreqs = mKernelUidCpuFreqTimeReader.readFreqs(mBufferedReader, mPowerProfile); - - assertArrayEquals(freqs, actualFreqs); - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, times)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], times[i]); - } - verifyNoMoreInteractions(mCallback); - - // Verify that there is no callback if any value in the proc file is -ve. - Mockito.reset(mCallback, mBufferedReader); - final long[][] newTimes1 = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - newTimes1[i][j] = (times[i][j] + uids[i] + freqs[j]) * 10; - } - } - newTimes1[uids.length - 1][freqs.length - 1] *= -1; - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - if (i == uids.length - 1) { - continue; - } - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], subtract(newTimes1[i], times[i])); - } - verifyNoMoreInteractions(mCallback); - - // Verify that the internal state was not modified when the proc file had -ve value. - Mockito.reset(mCallback, mBufferedReader); - for (int i = 0; i < freqs.length; ++i) { - newTimes1[uids.length - 1][i] = times[uids.length - 1][i]; - } - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes1)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - verifyNoMoreInteractions(mCallback); - - // Verify that there is no callback if the values in the proc file are decreased. - Mockito.reset(mCallback, mBufferedReader); - final long[][] newTimes2 = new long[uids.length][freqs.length]; - for (int i = 0; i < uids.length; ++i) { - for (int j = 0; j < freqs.length; ++j) { - newTimes2[i][j] = (newTimes1[i][j] + uids[i] * freqs[j]) * 10; - } - } - newTimes2[uids.length - 1][freqs.length - 1] = - newTimes1[uids.length - 1][freqs.length - 1] - 222; - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes2)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - for (int i = 0; i < uids.length; ++i) { - if (i == uids.length - 1) { - continue; - } - Mockito.verify(mCallback).onUidCpuFreqTime(uids[i], - subtract(newTimes2[i], newTimes1[i])); - } - verifyNoMoreInteractions(mCallback); - - // Verify that the internal state was not modified when the proc file had decreasing values. - Mockito.reset(mCallback, mBufferedReader); - for (int i = 0; i < freqs.length; ++i) { - newTimes2[uids.length - 1][i] = newTimes1[uids.length - 1][i]; - } - when(mBufferedReader.readLine()) - .thenReturn(getFreqsLine(freqs), getUidTimesLines(uids, newTimes2)); - mKernelUidCpuFreqTimeReader.readDelta(mBufferedReader, mCallback); - verifyNoMoreInteractions(mCallback); - } - private long[] subtract(long[] a1, long[] a2) { long[] val = new long[a1.length]; for (int i = 0; i < val.length; ++i) { @@ -438,21 +276,6 @@ public class KernelUidCpuFreqTimeReaderTest { return sb.toString(); } - private String[] getUidTimesLines(int[] uids, long[][] times) { - final String[] lines = new String[uids.length + 1]; - final StringBuilder sb = new StringBuilder(); - for (int i = 0; i < uids.length; ++i) { - sb.setLength(0); - sb.append(uids[i] + ":"); - for (int j = 0; j < times[i].length; ++j) { - sb.append(" " + times[i][j] / 10); - } - lines[i] = sb.toString(); - } - lines[uids.length] = null; - return lines; - } - private ByteBuffer getUidTimesBytes(int[] uids, long[][] times) { int size = (1 + uids.length + uids.length * times[0].length) * 4; ByteBuffer buf = ByteBuffer.allocate(size); diff --git a/core/tests/coretests/src/com/android/internal/os/MockBatteryStatsImpl.java b/core/tests/coretests/src/com/android/internal/os/MockBatteryStatsImpl.java index 6d5c7e7749e81..36e54adc4ff13 100644 --- a/core/tests/coretests/src/com/android/internal/os/MockBatteryStatsImpl.java +++ b/core/tests/coretests/src/com/android/internal/os/MockBatteryStatsImpl.java @@ -22,6 +22,7 @@ import android.util.SparseIntArray; import com.android.internal.location.gnssmetrics.GnssMetrics; import java.util.ArrayList; +import java.util.Queue; import java.util.concurrent.Future; /** @@ -66,6 +67,10 @@ public class MockBatteryStatsImpl extends BatteryStatsImpl { return mScreenState; } + public Queue getPendingRemovedUids() { + return mPendingRemovedUids; + } + public boolean isOnBattery() { return mForceOnBattery ? true : super.isOnBattery(); } diff --git a/services/core/java/com/android/server/am/BatteryExternalStatsWorker.java b/services/core/java/com/android/server/am/BatteryExternalStatsWorker.java index 1f101814d2940..f5e1a317c89b8 100644 --- a/services/core/java/com/android/server/am/BatteryExternalStatsWorker.java +++ b/services/core/java/com/android/server/am/BatteryExternalStatsWorker.java @@ -306,6 +306,7 @@ class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStatsSync { for (int uid : uidsToRemove) { mStats.removeIsolatedUidLocked(uid); } + mStats.clearPendingRemovedUids(); } } }; diff --git a/services/core/java/com/android/server/am/BatteryStatsService.java b/services/core/java/com/android/server/am/BatteryStatsService.java index 3db1da59b4eaa..3c49eceb48535 100644 --- a/services/core/java/com/android/server/am/BatteryStatsService.java +++ b/services/core/java/com/android/server/am/BatteryStatsService.java @@ -1193,6 +1193,7 @@ public final class BatteryStatsService extends IBatteryStats.Stub pw.println(" --new-daily: immediately create and write new daily stats record."); pw.println(" --read-daily: read-load last written daily stats."); pw.println(" --settings: dump the settings key/values related to batterystats"); + pw.println(" --cpu: dump cpu stats for debugging purpose"); pw.println(" : optional name of package to filter output by."); pw.println(" -h: print this help text."); pw.println("Battery stats (batterystats) commands:"); @@ -1211,6 +1212,12 @@ public final class BatteryStatsService extends IBatteryStats.Stub } } + private void dumpCpuStats(PrintWriter pw) { + synchronized (mStats) { + mStats.dumpCpuStatsLocked(pw); + } + } + private int doEnableOrDisable(PrintWriter pw, int i, String[] args, boolean enable) { i++; if (i >= args.length) { @@ -1324,6 +1331,9 @@ public final class BatteryStatsService extends IBatteryStats.Stub } else if ("--settings".equals(arg)) { dumpSettings(pw); return; + } else if ("--cpu".equals(arg)) { + dumpCpuStats(pw); + return; } else if ("-a".equals(arg)) { flags |= BatteryStats.DUMP_VERBOSE; } else if (arg.length() > 0 && arg.charAt(0) == '-'){ diff --git a/services/core/java/com/android/server/stats/StatsCompanionService.java b/services/core/java/com/android/server/stats/StatsCompanionService.java index afcedcc80de22..74c5ee9c35204 100644 --- a/services/core/java/com/android/server/stats/StatsCompanionService.java +++ b/services/core/java/com/android/server/stats/StatsCompanionService.java @@ -177,7 +177,6 @@ public class StatsCompanionService extends IStatsCompanionService.Stub { // frameworks/base/core/java/com/android/internal/os/KernelCpuProcReader mKernelUidCpuFreqTimeReader.setThrottleInterval(0); long[] freqs = mKernelUidCpuFreqTimeReader.readFreqs(powerProfile); - mKernelUidCpuFreqTimeReader.setReadBinary(true); mKernelUidCpuClusterTimeReader.setThrottleInterval(0); mKernelUidCpuActiveTimeReader.setThrottleInterval(0); }