/* * Copyright (C) 2016 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License */ package com.android.server.job; import static com.android.server.job.JobSchedulerService.sElapsedRealtimeClock; import static com.android.server.job.JobSchedulerService.sSystemClock; import static com.android.server.job.JobSchedulerService.sUptimeMillisClock; import android.app.job.JobInfo; import android.app.job.JobParameters; import android.os.UserHandle; import android.text.format.DateFormat; import android.util.ArrayMap; import android.util.IndentingPrintWriter; import android.util.SparseArray; import android.util.SparseIntArray; import android.util.TimeUtils; import android.util.proto.ProtoOutputStream; import com.android.internal.util.RingBufferIndices; import com.android.server.job.controllers.JobStatus; public final class JobPackageTracker { // We batch every 30 minutes. static final long BATCHING_TIME = 30*60*1000; // Number of historical data sets we keep. static final int NUM_HISTORY = 5; private static final int EVENT_BUFFER_SIZE = 100; public static final int EVENT_CMD_MASK = 0xff; public static final int EVENT_STOP_REASON_SHIFT = 8; public static final int EVENT_STOP_REASON_MASK = 0xff << EVENT_STOP_REASON_SHIFT; public static final int EVENT_NULL = 0; public static final int EVENT_START_JOB = 1; public static final int EVENT_STOP_JOB = 2; public static final int EVENT_START_PERIODIC_JOB = 3; public static final int EVENT_STOP_PERIODIC_JOB = 4; private final RingBufferIndices mEventIndices = new RingBufferIndices(EVENT_BUFFER_SIZE); private final int[] mEventCmds = new int[EVENT_BUFFER_SIZE]; private final long[] mEventTimes = new long[EVENT_BUFFER_SIZE]; private final int[] mEventUids = new int[EVENT_BUFFER_SIZE]; private final String[] mEventTags = new String[EVENT_BUFFER_SIZE]; private final int[] mEventJobIds = new int[EVENT_BUFFER_SIZE]; private final String[] mEventReasons = new String[EVENT_BUFFER_SIZE]; public void addEvent(int cmd, int uid, String tag, int jobId, int stopReason, String debugReason) { int index = mEventIndices.add(); mEventCmds[index] = cmd | ((stopReason< 0) { time += now - activeStartTime; } return time; } public long getActiveTopTime(long now) { long time = pastActiveTopTime; if (activeTopNesting > 0) { time += now - activeTopStartTime; } return time; } public long getPendingTime(long now) { long time = pastPendingTime; if (pendingNesting > 0) { time += now - pendingStartTime; } return time; } } final static class DataSet { final SparseArray> mEntries = new SparseArray<>(); final long mStartUptimeTime; final long mStartElapsedTime; final long mStartClockTime; long mSummedTime; int mMaxTotalActive; int mMaxFgActive; public DataSet(DataSet otherTimes) { mStartUptimeTime = otherTimes.mStartUptimeTime; mStartElapsedTime = otherTimes.mStartElapsedTime; mStartClockTime = otherTimes.mStartClockTime; } public DataSet() { mStartUptimeTime = sUptimeMillisClock.millis(); mStartElapsedTime = sElapsedRealtimeClock.millis(); mStartClockTime = sSystemClock.millis(); } private PackageEntry getOrCreateEntry(int uid, String pkg) { ArrayMap uidMap = mEntries.get(uid); if (uidMap == null) { uidMap = new ArrayMap<>(); mEntries.put(uid, uidMap); } PackageEntry entry = uidMap.get(pkg); if (entry == null) { entry = new PackageEntry(); uidMap.put(pkg, entry); } return entry; } public PackageEntry getEntry(int uid, String pkg) { ArrayMap uidMap = mEntries.get(uid); if (uidMap == null) { return null; } return uidMap.get(pkg); } long getTotalTime(long now) { if (mSummedTime > 0) { return mSummedTime; } return now - mStartUptimeTime; } void incPending(int uid, String pkg, long now) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.pendingNesting == 0) { pe.pendingStartTime = now; pe.pendingCount++; } pe.pendingNesting++; } void decPending(int uid, String pkg, long now) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.pendingNesting == 1) { pe.pastPendingTime += now - pe.pendingStartTime; } pe.pendingNesting--; } void incActive(int uid, String pkg, long now) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.activeNesting == 0) { pe.activeStartTime = now; pe.activeCount++; } pe.activeNesting++; } void decActive(int uid, String pkg, long now, int stopReason) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.activeNesting == 1) { pe.pastActiveTime += now - pe.activeStartTime; } pe.activeNesting--; int count = pe.stopReasons.get(stopReason, 0); pe.stopReasons.put(stopReason, count+1); } void incActiveTop(int uid, String pkg, long now) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.activeTopNesting == 0) { pe.activeTopStartTime = now; pe.activeTopCount++; } pe.activeTopNesting++; } void decActiveTop(int uid, String pkg, long now, int stopReason) { PackageEntry pe = getOrCreateEntry(uid, pkg); if (pe.activeTopNesting == 1) { pe.pastActiveTopTime += now - pe.activeTopStartTime; } pe.activeTopNesting--; int count = pe.stopReasons.get(stopReason, 0); pe.stopReasons.put(stopReason, count+1); } void finish(DataSet next, long now) { for (int i = mEntries.size() - 1; i >= 0; i--) { ArrayMap uidMap = mEntries.valueAt(i); for (int j = uidMap.size() - 1; j >= 0; j--) { PackageEntry pe = uidMap.valueAt(j); if (pe.activeNesting > 0 || pe.activeTopNesting > 0 || pe.pendingNesting > 0) { // Propagate existing activity in to next data set. PackageEntry nextPe = next.getOrCreateEntry(mEntries.keyAt(i), uidMap.keyAt(j)); nextPe.activeStartTime = now; nextPe.activeNesting = pe.activeNesting; nextPe.activeTopStartTime = now; nextPe.activeTopNesting = pe.activeTopNesting; nextPe.pendingStartTime = now; nextPe.pendingNesting = pe.pendingNesting; // Finish it off. if (pe.activeNesting > 0) { pe.pastActiveTime += now - pe.activeStartTime; pe.activeNesting = 0; } if (pe.activeTopNesting > 0) { pe.pastActiveTopTime += now - pe.activeTopStartTime; pe.activeTopNesting = 0; } if (pe.pendingNesting > 0) { pe.pastPendingTime += now - pe.pendingStartTime; pe.pendingNesting = 0; } } } } } void addTo(DataSet out, long now) { out.mSummedTime += getTotalTime(now); for (int i = mEntries.size() - 1; i >= 0; i--) { ArrayMap uidMap = mEntries.valueAt(i); for (int j = uidMap.size() - 1; j >= 0; j--) { PackageEntry pe = uidMap.valueAt(j); PackageEntry outPe = out.getOrCreateEntry(mEntries.keyAt(i), uidMap.keyAt(j)); outPe.pastActiveTime += pe.pastActiveTime; outPe.activeCount += pe.activeCount; outPe.pastActiveTopTime += pe.pastActiveTopTime; outPe.activeTopCount += pe.activeTopCount; outPe.pastPendingTime += pe.pastPendingTime; outPe.pendingCount += pe.pendingCount; if (pe.activeNesting > 0) { outPe.pastActiveTime += now - pe.activeStartTime; outPe.hadActive = true; } if (pe.activeTopNesting > 0) { outPe.pastActiveTopTime += now - pe.activeTopStartTime; outPe.hadActiveTop = true; } if (pe.pendingNesting > 0) { outPe.pastPendingTime += now - pe.pendingStartTime; outPe.hadPending = true; } for (int k = pe.stopReasons.size()-1; k >= 0; k--) { int type = pe.stopReasons.keyAt(k); outPe.stopReasons.put(type, outPe.stopReasons.get(type, 0) + pe.stopReasons.valueAt(k)); } } } if (mMaxTotalActive > out.mMaxTotalActive) { out.mMaxTotalActive = mMaxTotalActive; } if (mMaxFgActive > out.mMaxFgActive) { out.mMaxFgActive = mMaxFgActive; } } /** Return {@code true} if text was printed. */ boolean printDuration(IndentingPrintWriter pw, long period, long duration, int count, String suffix) { float fraction = duration / (float) period; int percent = (int) ((fraction * 100) + .5f); if (percent > 0) { pw.print(percent); pw.print("% "); pw.print(count); pw.print("x "); pw.print(suffix); return true; } else if (count > 0) { pw.print(count); pw.print("x "); pw.print(suffix); return true; } return false; } void dump(IndentingPrintWriter pw, String header, long now, long nowElapsed, int filterAppId) { final long period = getTotalTime(now); pw.print(header); pw.print(" at "); pw.print(DateFormat.format("yyyy-MM-dd-HH-mm-ss", mStartClockTime).toString()); pw.print(" ("); TimeUtils.formatDuration(mStartElapsedTime, nowElapsed, pw); pw.print(") over "); TimeUtils.formatDuration(period, pw); pw.println(":"); pw.increaseIndent(); pw.print("Max concurrency: "); pw.print(mMaxTotalActive); pw.print(" total, "); pw.print(mMaxFgActive); pw.println(" foreground"); pw.println(); final int NE = mEntries.size(); for (int i = 0; i < NE; i++) { int uid = mEntries.keyAt(i); if (filterAppId != -1 && filterAppId != UserHandle.getAppId(uid)) { continue; } ArrayMap uidMap = mEntries.valueAt(i); final int NP = uidMap.size(); for (int j = 0; j < NP; j++) { PackageEntry pe = uidMap.valueAt(j); UserHandle.formatUid(pw, uid); pw.print(" / "); pw.print(uidMap.keyAt(j)); pw.println(":"); pw.increaseIndent(); if (printDuration(pw, period, pe.getPendingTime(now), pe.pendingCount, "pending")) { pw.print(" "); } if (printDuration(pw, period, pe.getActiveTime(now), pe.activeCount, "active")) { pw.print(" "); } printDuration(pw, period, pe.getActiveTopTime(now), pe.activeTopCount, "active-top"); if (pe.pendingNesting > 0 || pe.hadPending) { pw.print(" (pending)"); } if (pe.activeNesting > 0 || pe.hadActive) { pw.print(" (active)"); } if (pe.activeTopNesting > 0 || pe.hadActiveTop) { pw.print(" (active-top)"); } pw.println(); if (pe.stopReasons.size() > 0) { for (int k = 0; k < pe.stopReasons.size(); k++) { if (k > 0) { pw.print(", "); } pw.print(pe.stopReasons.valueAt(k)); pw.print("x "); pw.print(JobParameters .getInternalReasonCodeDescription(pe.stopReasons.keyAt(k))); } pw.println(); } pw.decreaseIndent(); } } pw.decreaseIndent(); } private void printPackageEntryState(ProtoOutputStream proto, long fieldId, long duration, int count) { final long token = proto.start(fieldId); proto.write(DataSetProto.PackageEntryProto.State.DURATION_MS, duration); proto.write(DataSetProto.PackageEntryProto.State.COUNT, count); proto.end(token); } void dump(ProtoOutputStream proto, long fieldId, long now, long nowElapsed, int filterUid) { final long token = proto.start(fieldId); final long period = getTotalTime(now); proto.write(DataSetProto.START_CLOCK_TIME_MS, mStartClockTime); proto.write(DataSetProto.ELAPSED_TIME_MS, nowElapsed - mStartElapsedTime); proto.write(DataSetProto.PERIOD_MS, period); final int NE = mEntries.size(); for (int i = 0; i < NE; i++) { int uid = mEntries.keyAt(i); if (filterUid != -1 && filterUid != UserHandle.getAppId(uid)) { continue; } ArrayMap uidMap = mEntries.valueAt(i); final int NP = uidMap.size(); for (int j = 0; j < NP; j++) { final long peToken = proto.start(DataSetProto.PACKAGE_ENTRIES); PackageEntry pe = uidMap.valueAt(j); proto.write(DataSetProto.PackageEntryProto.UID, uid); proto.write(DataSetProto.PackageEntryProto.PACKAGE_NAME, uidMap.keyAt(j)); printPackageEntryState(proto, DataSetProto.PackageEntryProto.PENDING_STATE, pe.getPendingTime(now), pe.pendingCount); printPackageEntryState(proto, DataSetProto.PackageEntryProto.ACTIVE_STATE, pe.getActiveTime(now), pe.activeCount); printPackageEntryState(proto, DataSetProto.PackageEntryProto.ACTIVE_TOP_STATE, pe.getActiveTopTime(now), pe.activeTopCount); proto.write(DataSetProto.PackageEntryProto.PENDING, pe.pendingNesting > 0 || pe.hadPending); proto.write(DataSetProto.PackageEntryProto.ACTIVE, pe.activeNesting > 0 || pe.hadActive); proto.write(DataSetProto.PackageEntryProto.ACTIVE_TOP, pe.activeTopNesting > 0 || pe.hadActiveTop); for (int k = 0; k < pe.stopReasons.size(); k++) { final long srcToken = proto.start(DataSetProto.PackageEntryProto.STOP_REASONS); proto.write(DataSetProto.PackageEntryProto.StopReasonCount.REASON, pe.stopReasons.keyAt(k)); proto.write(DataSetProto.PackageEntryProto.StopReasonCount.COUNT, pe.stopReasons.valueAt(k)); proto.end(srcToken); } proto.end(peToken); } } proto.write(DataSetProto.MAX_CONCURRENCY, mMaxTotalActive); proto.write(DataSetProto.MAX_FOREGROUND_CONCURRENCY, mMaxFgActive); proto.end(token); } } void rebatchIfNeeded(long now) { long totalTime = mCurDataSet.getTotalTime(now); if (totalTime > BATCHING_TIME) { DataSet last = mCurDataSet; last.mSummedTime = totalTime; mCurDataSet = new DataSet(); last.finish(mCurDataSet, now); System.arraycopy(mLastDataSets, 0, mLastDataSets, 1, mLastDataSets.length-1); mLastDataSets[0] = last; } } public void notePending(JobStatus job) { final long now = sUptimeMillisClock.millis(); job.madePending = now; rebatchIfNeeded(now); mCurDataSet.incPending(job.getSourceUid(), job.getSourcePackageName(), now); } public void noteNonpending(JobStatus job) { final long now = sUptimeMillisClock.millis(); mCurDataSet.decPending(job.getSourceUid(), job.getSourcePackageName(), now); rebatchIfNeeded(now); } public void noteActive(JobStatus job) { final long now = sUptimeMillisClock.millis(); job.madeActive = now; rebatchIfNeeded(now); if (job.lastEvaluatedBias >= JobInfo.BIAS_TOP_APP) { mCurDataSet.incActiveTop(job.getSourceUid(), job.getSourcePackageName(), now); } else { mCurDataSet.incActive(job.getSourceUid(), job.getSourcePackageName(), now); } addEvent(job.getJob().isPeriodic() ? EVENT_START_PERIODIC_JOB : EVENT_START_JOB, job.getSourceUid(), job.getBatteryName(), job.getJobId(), 0, null); } public void noteInactive(JobStatus job, int stopReason, String debugReason) { final long now = sUptimeMillisClock.millis(); if (job.lastEvaluatedBias >= JobInfo.BIAS_TOP_APP) { mCurDataSet.decActiveTop(job.getSourceUid(), job.getSourcePackageName(), now, stopReason); } else { mCurDataSet.decActive(job.getSourceUid(), job.getSourcePackageName(), now, stopReason); } rebatchIfNeeded(now); addEvent(job.getJob().isPeriodic() ? EVENT_STOP_PERIODIC_JOB : EVENT_STOP_JOB, job.getSourceUid(), job.getBatteryName(), job.getJobId(), stopReason, debugReason); } public void noteConcurrency(int totalActive, int fgActive) { if (totalActive > mCurDataSet.mMaxTotalActive) { mCurDataSet.mMaxTotalActive = totalActive; } if (fgActive > mCurDataSet.mMaxFgActive) { mCurDataSet.mMaxFgActive = fgActive; } } public float getLoadFactor(JobStatus job) { final int uid = job.getSourceUid(); final String pkg = job.getSourcePackageName(); PackageEntry cur = mCurDataSet.getEntry(uid, pkg); PackageEntry last = mLastDataSets[0] != null ? mLastDataSets[0].getEntry(uid, pkg) : null; if (cur == null && last == null) { return 0; } final long now = sUptimeMillisClock.millis(); long time = 0; if (cur != null) { time += cur.getActiveTime(now) + cur.getPendingTime(now); } long period = mCurDataSet.getTotalTime(now); if (last != null) { time += last.getActiveTime(now) + last.getPendingTime(now); period += mLastDataSets[0].getTotalTime(now); } return time / (float)period; } void dump(IndentingPrintWriter pw, int filterAppId) { final long now = sUptimeMillisClock.millis(); final long nowElapsed = sElapsedRealtimeClock.millis(); final DataSet total; if (mLastDataSets[0] != null) { total = new DataSet(mLastDataSets[0]); mLastDataSets[0].addTo(total, now); } else { total = new DataSet(mCurDataSet); } mCurDataSet.addTo(total, now); for (int i = 1; i < mLastDataSets.length; i++) { if (mLastDataSets[i] != null) { mLastDataSets[i].dump(pw, "Historical stats", now, nowElapsed, filterAppId); pw.println(); } } total.dump(pw, "Current stats", now, nowElapsed, filterAppId); } public void dump(ProtoOutputStream proto, long fieldId, int filterUid) { final long token = proto.start(fieldId); final long now = sUptimeMillisClock.millis(); final long nowElapsed = sElapsedRealtimeClock.millis(); final DataSet total; if (mLastDataSets[0] != null) { total = new DataSet(mLastDataSets[0]); mLastDataSets[0].addTo(total, now); } else { total = new DataSet(mCurDataSet); } mCurDataSet.addTo(total, now); for (int i = 1; i < mLastDataSets.length; i++) { if (mLastDataSets[i] != null) { mLastDataSets[i].dump(proto, JobPackageTrackerDumpProto.HISTORICAL_STATS, now, nowElapsed, filterUid); } } total.dump(proto, JobPackageTrackerDumpProto.CURRENT_STATS, now, nowElapsed, filterUid); proto.end(token); } boolean dumpHistory(IndentingPrintWriter pw, int filterAppId) { final int size = mEventIndices.size(); if (size <= 0) { return false; } pw.increaseIndent(); pw.println("Job history:"); pw.decreaseIndent(); final long now = sElapsedRealtimeClock.millis(); for (int i=0; i> EVENT_STOP_REASON_SHIFT)); } } pw.println(); } return true; } public void dumpHistory(ProtoOutputStream proto, long fieldId, int filterUid) { final int size = mEventIndices.size(); if (size == 0) { return; } final long token = proto.start(fieldId); final long now = sElapsedRealtimeClock.millis(); for (int i = 0; i < size; i++) { final int index = mEventIndices.indexOf(i); final int uid = mEventUids[index]; if (filterUid != -1 && filterUid != UserHandle.getAppId(uid)) { continue; } final int cmd = mEventCmds[index] & EVENT_CMD_MASK; if (cmd == EVENT_NULL) { continue; } final long heToken = proto.start(JobPackageHistoryProto.HISTORY_EVENT); proto.write(JobPackageHistoryProto.HistoryEvent.EVENT, cmd); proto.write(JobPackageHistoryProto.HistoryEvent.TIME_SINCE_EVENT_MS, now - mEventTimes[index]); proto.write(JobPackageHistoryProto.HistoryEvent.UID, uid); proto.write(JobPackageHistoryProto.HistoryEvent.JOB_ID, mEventJobIds[index]); proto.write(JobPackageHistoryProto.HistoryEvent.TAG, mEventTags[index]); if (cmd == EVENT_STOP_JOB || cmd == EVENT_STOP_PERIODIC_JOB) { proto.write(JobPackageHistoryProto.HistoryEvent.STOP_REASON, (mEventCmds[index] & EVENT_STOP_REASON_MASK) >> EVENT_STOP_REASON_SHIFT); } proto.end(heToken); } proto.end(token); } }