OSDN Git Service

Log deferred jobs metrics to batterystats
authorAmith Yamasani <yamasani@google.com>
Fri, 16 Feb 2018 19:29:54 +0000 (11:29 -0800)
committerAmith Yamasani <yamasani@google.com>
Mon, 19 Feb 2018 06:43:13 +0000 (22:43 -0800)
Log the deferred jobs event count, number of deferred jobs,
time since last job execution and break those down into
different time-since buckets in case the average becomes
too noisy.

Bug: 70297451
Test: dumpsys batterystats --checkin

Change-Id: Iafad6137989246f203a623ce1511140d4eac35b0

core/java/android/os/BatteryStats.java
core/java/android/os/BatteryStatsInternal.java
core/java/com/android/internal/os/BatteryStatsImpl.java
services/core/java/com/android/server/am/BatteryStatsService.java
services/core/java/com/android/server/job/JobSchedulerService.java

index 7cd58e8..6ecf6d5 100644 (file)
@@ -287,6 +287,16 @@ public abstract class BatteryStats implements Parcelable {
     private static final String SYNC_DATA = "sy";
     private static final String JOB_DATA = "jb";
     private static final String JOB_COMPLETION_DATA = "jbc";
+
+    /**
+     * jbd line is:
+     * BATTERY_STATS_CHECKIN_VERSION, uid, which, "jbd",
+     * jobsDeferredEventCount, jobsDeferredCount, averageLatencyMillis,
+     * count at latency < 1 hr, count at latency < 2 hrs, count at latency < 6 hrs, beyond 6 hrs
+     * <p>
+     * @see #JOB_FRESHNESS_BUCKETS
+     */
+    private static final String JOBS_DEFERRED_DATA = "jbd";
     private static final String KERNEL_WAKELOCK_DATA = "kwl";
     private static final String WAKEUP_REASON_DATA = "wr";
     private static final String NETWORK_DATA = "nt";
@@ -349,6 +359,19 @@ public abstract class BatteryStats implements Parcelable {
     public static final String UID_TIMES_TYPE_ALL = "A";
 
     /**
+     * These are the thresholds for bucketing last time since a job was run for an app
+     * that just moved to ACTIVE due to a launch. So if the last time a job ran was less
+     * than 30 minutes ago, then it's reasonably fresh, 2 hours ago, not so fresh and so
+     * on.
+     */
+    public static final long[] JOB_FRESHNESS_BUCKETS = {
+            1 * 60 * 60 * 1000L,
+            2 * 60 * 60 * 1000L,
+            6 * 60 * 60 * 1000L,
+            Long.MAX_VALUE
+    };
+
+    /**
      * State for keeping track of counting information.
      */
     public static abstract class Counter {
@@ -846,6 +869,20 @@ public abstract class BatteryStats implements Parcelable {
          */
         public abstract long getWifiRadioApWakeupCount(int which);
 
+        /**
+         * Appends the deferred jobs data to the StringBuilder passed in, in checkin format
+         * @param sb StringBuilder that can be overwritten with the deferred jobs data
+         * @param which one of STATS_*
+         */
+        public abstract void getDeferredJobsCheckinLineLocked(StringBuilder sb, int which);
+
+        /**
+         * Appends the deferred jobs data to the StringBuilder passed in
+         * @param sb StringBuilder that can be overwritten with the deferred jobs data
+         * @param which one of STATS_*
+         */
+        public abstract void getDeferredJobsLineLocked(StringBuilder sb, int which);
+
         public static abstract class Sensor {
             /*
              * FIXME: it's not correct to use this magic value because it
@@ -4070,6 +4107,12 @@ public abstract class BatteryStats implements Parcelable {
                 }
             }
 
+            // Dump deferred jobs stats
+            u.getDeferredJobsCheckinLineLocked(sb, which);
+            if (sb.length() > 0) {
+                dumpLine(pw, uid, category, JOBS_DEFERRED_DATA, sb.toString());
+            }
+
             dumpTimer(pw, uid, category, FLASHLIGHT_DATA, u.getFlashlightTurnedOnTimer(),
                     rawRealtime, which);
             dumpTimer(pw, uid, category, CAMERA_DATA, u.getCameraTurnedOnTimer(),
@@ -5698,6 +5741,11 @@ public abstract class BatteryStats implements Parcelable {
                 }
             }
 
+            u.getDeferredJobsLineLocked(sb, which);
+            if (sb.length() > 0) {
+                pw.print("    Jobs deferred on launch "); pw.println(sb.toString());
+            }
+
             uidActivity |= printTimer(pw, sb, u.getFlashlightTurnedOnTimer(), rawRealtime, which,
                     prefix, "Flashlight");
             uidActivity |= printTimer(pw, sb, u.getCameraTurnedOnTimer(), rawRealtime, which,
index b0436eb..679f18e 100644 (file)
@@ -18,7 +18,7 @@ package android.os;
 
 /**
  * Battery stats local system service interface. This is used to pass internal data out of
- * BatteryStatsImpl.
+ * BatteryStatsImpl, as well as make unchecked calls into BatteryStatsImpl.
  *
  * @hide Only for use within Android OS.
  */
@@ -32,4 +32,13 @@ public abstract class BatteryStatsInternal {
      * Returns the mobile data interfaces.
      */
     public abstract String[] getMobileIfaces();
+
+    /**
+     * Inform battery stats how many deferred jobs existed when the app got launched and how
+     * long ago was the last job execution for the app.
+     * @param uid the uid of the app.
+     * @param numDeferred number of deferred jobs.
+     * @param sinceLast how long in millis has it been since a job was run
+     */
+    public abstract void noteJobsDeferred(int uid, int numDeferred, long sinceLast);
 }
index 4e51591..d1932cf 100644 (file)
@@ -134,7 +134,7 @@ public class BatteryStatsImpl extends BatteryStats {
     private static final int MAGIC = 0xBA757475; // 'BATSTATS'
 
     // Current on-disk Parcel version
-    private static final int VERSION = 174 + (USE_OLD_HISTORY ? 1000 : 0);
+    private static final int VERSION = 175 + (USE_OLD_HISTORY ? 1000 : 0);
 
     // Maximum number of items we will record in the history.
     private static final int MAX_HISTORY_ITEMS;
@@ -1222,7 +1222,7 @@ public class BatteryStatsImpl extends BatteryStats {
          * @param out the Parcel to be written to.
          * @param counter a Counter, or null.
          */
-        public static void writeCounterToParcel(Parcel out, Counter counter) {
+        public static void writeCounterToParcel(Parcel out, @Nullable Counter counter) {
             if (counter == null) {
                 out.writeInt(0); // indicates null
                 return;
@@ -1232,6 +1232,19 @@ public class BatteryStatsImpl extends BatteryStats {
             counter.writeToParcel(out);
         }
 
+        /**
+         * Reads a Counter that was written using {@link #writeCounterToParcel(Parcel, Counter)}.
+         * @param timeBase the timebase to assign to the Counter
+         * @param in the parcel to read from
+         * @return the Counter or null.
+         */
+        public static @Nullable Counter readCounterFromParcel(TimeBase timeBase, Parcel in) {
+            if (in.readInt() == 0) {
+                return null;
+            }
+            return new Counter(timeBase, in);
+        }
+
         @Override
         public int getCountLocked(int which) {
             int val = mCount.get();
@@ -4071,6 +4084,11 @@ public class BatteryStatsImpl extends BatteryStats {
         addHistoryEventLocked(elapsedRealtime, uptime, HistoryItem.EVENT_JOB_FINISH, name, uid);
     }
 
+    public void noteJobsDeferredLocked(int uid, int numDeferred, long sinceLast) {
+        uid = mapUid(uid);
+        getUidStatsLocked(uid).noteJobsDeferredLocked(numDeferred, sinceLast);
+    }
+
     public void noteAlarmStartLocked(String name, WorkSource workSource, int uid) {
         noteAlarmStartOrFinishLocked(HistoryItem.EVENT_ALARM_START, name, workSource, uid);
     }
@@ -6749,6 +6767,29 @@ public class BatteryStatsImpl extends BatteryStats {
         final ArrayMap<String, SparseIntArray> mJobCompletions = new ArrayMap<>();
 
         /**
+         * Count of app launch events that had associated deferred job counts or info about
+         * last time a job was run.
+         */
+        Counter mJobsDeferredEventCount;
+
+        /**
+         * Count of deferred jobs that were pending when the app was launched or brought to
+         * the foreground through a user interaction.
+         */
+        Counter mJobsDeferredCount;
+
+        /**
+         * Sum of time since the last time a job was run for this app before it was launched.
+         */
+        LongSamplingCounter mJobsFreshnessTimeMs;
+
+        /**
+         * Array of counts of instances where the time since the last job was run for the app
+         * fell within one of the thresholds in {@link #JOB_FRESHNESS_BUCKETS}.
+         */
+        final Counter[] mJobsFreshnessBuckets;
+
+        /**
          * The statistics we have collected for this uid's sensor activations.
          */
         final SparseArray<Sensor> mSensorStats = new SparseArray<>();
@@ -6822,6 +6863,10 @@ public class BatteryStatsImpl extends BatteryStats {
             mWifiMulticastTimer = new StopwatchTimer(mBsi.mClocks, this, WIFI_MULTICAST_ENABLED,
                     mBsi.mWifiMulticastTimers, mBsi.mOnBatteryTimeBase);
             mProcessStateTimer = new StopwatchTimer[NUM_PROCESS_STATE];
+            mJobsDeferredEventCount = new Counter(mBsi.mOnBatteryTimeBase);
+            mJobsDeferredCount = new Counter(mBsi.mOnBatteryTimeBase);
+            mJobsFreshnessTimeMs = new LongSamplingCounter(mBsi.mOnBatteryTimeBase);
+            mJobsFreshnessBuckets = new Counter[JOB_FRESHNESS_BUCKETS.length];
         }
 
         @VisibleForTesting
@@ -7799,6 +7844,55 @@ public class BatteryStatsImpl extends BatteryStats {
             return 0;
         }
 
+        @Override
+        public void getDeferredJobsCheckinLineLocked(StringBuilder sb, int which) {
+            sb.setLength(0);
+            final int deferredEventCount = mJobsDeferredEventCount.getCountLocked(which);
+            if (deferredEventCount == 0) {
+                return;
+            }
+            final int deferredCount = mJobsDeferredCount.getCountLocked(which);
+            final long averageLatency = deferredEventCount != 0
+                    ? mJobsFreshnessTimeMs.getCountLocked(which) / deferredEventCount
+                    : 0L;
+            sb.append(deferredEventCount); sb.append(',');
+            sb.append(deferredCount); sb.append(',');
+            sb.append(averageLatency);
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                if (mJobsFreshnessBuckets[i] == null) {
+                    sb.append(",0");
+                } else {
+                    sb.append(",");
+                    sb.append(mJobsFreshnessBuckets[i].getCountLocked(which));
+                }
+            }
+        }
+
+        @Override
+        public void getDeferredJobsLineLocked(StringBuilder sb, int which) {
+            sb.setLength(0);
+            final int deferredEventCount = mJobsDeferredEventCount.getCountLocked(which);
+            if (deferredEventCount == 0) {
+                return;
+            }
+            final int deferredCount = mJobsDeferredCount.getCountLocked(which);
+            final long averageLatency = deferredEventCount != 0
+                    ? mJobsFreshnessTimeMs.getCountLocked(which) / deferredEventCount
+                    : 0L;
+            sb.append("times="); sb.append(deferredEventCount); sb.append(", ");
+            sb.append("count="); sb.append(deferredCount); sb.append(", ");
+            sb.append("avgLatency="); sb.append(averageLatency); sb.append(", ");
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                sb.append("<"); sb.append(JOB_FRESHNESS_BUCKETS[i]); sb.append("ms=");
+                if (mJobsFreshnessBuckets[i] == null) {
+                    sb.append("0");
+                } else {
+                    sb.append(mJobsFreshnessBuckets[i].getCountLocked(which));
+                }
+                sb.append(" ");
+            }
+        }
+
         void initNetworkActivityLocked() {
             mNetworkByteActivityCounters = new LongSamplingCounter[NUM_NETWORK_ACTIVITY_TYPES];
             mNetworkPacketActivityCounters = new LongSamplingCounter[NUM_NETWORK_ACTIVITY_TYPES];
@@ -7982,6 +8076,16 @@ public class BatteryStatsImpl extends BatteryStats {
             }
             mJobStats.cleanup();
             mJobCompletions.clear();
+
+            mJobsDeferredEventCount.reset(false);
+            mJobsDeferredCount.reset(false);
+            mJobsFreshnessTimeMs.reset(false);
+            for (int ij = 0; ij < JOB_FRESHNESS_BUCKETS.length; ij++) {
+                if (mJobsFreshnessBuckets[ij] != null) {
+                    mJobsFreshnessBuckets[ij].reset(false);
+                }
+            }
+
             for (int ise=mSensorStats.size()-1; ise>=0; ise--) {
                 Sensor s = mSensorStats.valueAt(ise);
                 if (s.reset()) {
@@ -7990,6 +8094,7 @@ public class BatteryStatsImpl extends BatteryStats {
                     active = true;
                 }
             }
+
             for (int ip=mProcessStats.size()-1; ip>=0; ip--) {
                 Proc proc = mProcessStats.valueAt(ip);
                 proc.detach();
@@ -8207,6 +8312,13 @@ public class BatteryStatsImpl extends BatteryStats {
 
             writeJobCompletionsToParcelLocked(out);
 
+            mJobsDeferredEventCount.writeToParcel(out);
+            mJobsDeferredCount.writeToParcel(out);
+            mJobsFreshnessTimeMs.writeToParcel(out);
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                Counter.writeCounterToParcel(out, mJobsFreshnessBuckets[i]);
+            }
+
             int NSE = mSensorStats.size();
             out.writeInt(NSE);
             for (int ise=0; ise<NSE; ise++) {
@@ -8502,6 +8614,14 @@ public class BatteryStatsImpl extends BatteryStats {
 
             readJobCompletionsFromParcelLocked(in);
 
+            mJobsDeferredEventCount = new Counter(mBsi.mOnBatteryTimeBase, in);
+            mJobsDeferredCount = new Counter(mBsi.mOnBatteryTimeBase, in);
+            mJobsFreshnessTimeMs = new LongSamplingCounter(mBsi.mOnBatteryTimeBase, in);
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                mJobsFreshnessBuckets[i] = Counter.readCounterFromParcel(mBsi.mOnBatteryTimeBase,
+                        in);
+            }
+
             int numSensors = in.readInt();
             mSensorStats.clear();
             for (int k = 0; k < numSensors; k++) {
@@ -8770,6 +8890,26 @@ public class BatteryStatsImpl extends BatteryStats {
             }
         }
 
+        public void noteJobsDeferredLocked(int numDeferred, long sinceLast) {
+            mJobsDeferredEventCount.addAtomic(1);
+            mJobsDeferredCount.addAtomic(numDeferred);
+            if (sinceLast != 0) {
+                // Add the total time, which can be divided by the event count to get an average
+                mJobsFreshnessTimeMs.addCountLocked(sinceLast);
+                // Also keep track of how many times there were in these different buckets.
+                for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                    if (sinceLast < JOB_FRESHNESS_BUCKETS[i]) {
+                        if (mJobsFreshnessBuckets[i] == null) {
+                            mJobsFreshnessBuckets[i] = new Counter(
+                                    mBsi.mOnBatteryTimeBase);
+                        }
+                        mJobsFreshnessBuckets[i].addAtomic(1);
+                        break;
+                    }
+                }
+            }
+        }
+
         /**
          * The statistics associated with a particular wake lock.
          */
@@ -13921,6 +14061,16 @@ public class BatteryStatsImpl extends BatteryStats {
 
             u.readJobCompletionsFromParcelLocked(in);
 
+            u.mJobsDeferredEventCount.readSummaryFromParcelLocked(in);
+            u.mJobsDeferredCount.readSummaryFromParcelLocked(in);
+            u.mJobsFreshnessTimeMs.readSummaryFromParcelLocked(in);
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                if (in.readInt() != 0) {
+                    u.mJobsFreshnessBuckets[i] = new Counter(u.mBsi.mOnBatteryTimeBase);
+                    u.mJobsFreshnessBuckets[i].readSummaryFromParcelLocked(in);
+                }
+            }
+
             int NP = in.readInt();
             if (NP > 1000) {
                 throw new ParcelFormatException("File corrupt: too many sensors " + NP);
@@ -14419,6 +14569,17 @@ public class BatteryStatsImpl extends BatteryStats {
 
             u.writeJobCompletionsToParcelLocked(out);
 
+            u.mJobsDeferredEventCount.writeSummaryFromParcelLocked(out);
+            u.mJobsDeferredCount.writeSummaryFromParcelLocked(out);
+            u.mJobsFreshnessTimeMs.writeSummaryFromParcelLocked(out);
+            for (int i = 0; i < JOB_FRESHNESS_BUCKETS.length; i++) {
+                if (u.mJobsFreshnessBuckets[i] != null) {
+                    u.mJobsFreshnessBuckets[i].writeSummaryFromParcelLocked(out);
+                } else {
+                    out.writeInt(0);
+                }
+            }
+
             int NSE = u.mSensorStats.size();
             out.writeInt(NSE);
             for (int ise=0; ise<NSE; ise++) {
index 9d1adb2..dd2358c 100644 (file)
@@ -202,6 +202,12 @@ public final class BatteryStatsService extends IBatteryStats.Stub
         public String[] getMobileIfaces() {
             return mStats.getMobileIfaces().clone();
         }
+
+        @Override
+        public void noteJobsDeferred(int uid, int numDeferred, long sinceLast) {
+            if (DBG) Slog.d(TAG, "Jobs deferred " + uid + ": " + numDeferred + " " + sinceLast);
+            BatteryStatsService.this.noteJobsDeferred(uid, numDeferred, sinceLast);
+        }
     }
 
     private static void awaitUninterruptibly(Future<?> future) {
@@ -456,6 +462,13 @@ public final class BatteryStatsService extends IBatteryStats.Stub
         }
     }
 
+    void noteJobsDeferred(int uid, int numDeferred, long sinceLast) {
+        // No need to enforce calling permission, as it is called from an internal interface
+        synchronized (mStats) {
+            mStats.noteJobsDeferredLocked(uid, numDeferred, sinceLast);
+        }
+    }
+
     public void noteWakupAlarm(String name, int uid, WorkSource workSource, String tag) {
         enforceCallingPermission();
         synchronized (mStats) {
index c33d7f4..05c7f19 100644 (file)
@@ -49,6 +49,7 @@ import android.content.pm.ServiceInfo;
 import android.database.ContentObserver;
 import android.net.Uri;
 import android.os.BatteryStats;
+import android.os.BatteryStatsInternal;
 import android.os.Binder;
 import android.os.Handler;
 import android.os.Looper;
@@ -62,6 +63,7 @@ import android.os.SystemClock;
 import android.os.UserHandle;
 import android.os.UserManagerInternal;
 import android.provider.Settings;
+import android.text.format.DateUtils;
 import android.util.KeyValueListParser;
 import android.util.Slog;
 import android.util.SparseArray;
@@ -2282,14 +2284,20 @@ public final class JobSchedulerService extends com.android.server.SystemService
                 return;
             }
 
-            final long sinceLast = sElapsedRealtimeClock.millis() -
-                    mUsageStats.getTimeSinceLastJobRun(packageName, userId);
+            long sinceLast = mUsageStats.getTimeSinceLastJobRun(packageName, userId);
+            if (sinceLast > 2 * DateUtils.DAY_IN_MILLIS) {
+                // Too long ago, not worth logging
+                sinceLast = 0L;
+            }
             final DeferredJobCounter counter = new DeferredJobCounter();
             synchronized (mLock) {
                 mJobs.forEachJobForSourceUid(uid, counter);
             }
-
-            mUsageStats.reportAppJobState(packageName, userId, counter.numDeferred(), sinceLast);
+            if (counter.numDeferred() > 0 || sinceLast > 0) {
+                BatteryStatsInternal mBatteryStatsInternal = LocalServices.getService
+                        (BatteryStatsInternal.class);
+                mBatteryStatsInternal.noteJobsDeferred(uid, counter.numDeferred(), sinceLast);
+            }
         }
     }