From 6447ca30b8e41c22c7214f201120327057e356dc Mon Sep 17 00:00:00 2001 From: Dianne Hackborn Date: Tue, 7 Apr 2009 19:50:08 -0700 Subject: [PATCH] Fix issue #1769910 (Track activity launch times) The usage stats service now collects per-activity launch time stats. There are a number of fixes and improvements to its statistics management and collection; it now operates its calendar in GMT and ensures that for checkin purposes it always reports one day and only one complete day to the checkin service. Also change the checkin option from "-c" to "--checkin" since it is really a special thing. --- .../java/com/android/internal/app/IUsageStats.aidl | 1 + .../java/com/android/server/BatteryService.java | 2 +- .../android/server/am/ActivityManagerService.java | 4 +- .../com/android/server/am/BatteryStatsService.java | 2 +- .../java/com/android/server/am/HistoryRecord.java | 18 +- .../com/android/server/am/UsageStatsService.java | 492 ++++++++++++++++----- 6 files changed, 392 insertions(+), 127 deletions(-) diff --git a/core/java/com/android/internal/app/IUsageStats.aidl b/core/java/com/android/internal/app/IUsageStats.aidl index 6b053d5c9975..1ea74090a419 100755 --- a/core/java/com/android/internal/app/IUsageStats.aidl +++ b/core/java/com/android/internal/app/IUsageStats.aidl @@ -22,6 +22,7 @@ import com.android.internal.os.PkgUsageStats; interface IUsageStats { void noteResumeComponent(in ComponentName componentName); void notePauseComponent(in ComponentName componentName); + void noteLaunchTime(in ComponentName componentName, int millis); PkgUsageStats getPkgUsageStats(in ComponentName componentName); PkgUsageStats[] getAllPkgUsageStats(); } diff --git a/services/java/com/android/server/BatteryService.java b/services/java/com/android/server/BatteryService.java index 7cd6b1742573..15eafcf19615 100644 --- a/services/java/com/android/server/BatteryService.java +++ b/services/java/com/android/server/BatteryService.java @@ -84,7 +84,7 @@ class BatteryService extends Binder { private static final int CRITICAL_BATTERY_LEVEL = 4; private static final int DUMP_MAX_LENGTH = 24 * 1024; - private static final String[] DUMPSYS_ARGS = new String[] { "-c", "-u" }; + private static final String[] DUMPSYS_ARGS = new String[] { "--checkin", "-u" }; private static final String BATTERY_STATS_SERVICE_NAME = "batteryinfo"; private static final String DUMPSYS_DATA_PATH = "/data/system/"; diff --git a/services/java/com/android/server/am/ActivityManagerService.java b/services/java/com/android/server/am/ActivityManagerService.java index d676c00b952e..59aa29fdf769 100644 --- a/services/java/com/android/server/am/ActivityManagerService.java +++ b/services/java/com/android/server/am/ActivityManagerService.java @@ -1270,7 +1270,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen mBatteryStatsService.getActiveStatistics().writeLocked(); mUsageStatsService = new UsageStatsService( new File( - systemDir, "usagestats.bin").toString()); + systemDir, "usagestats").toString()); mConfiguration.makeDefault(); mProcessStats.init(); @@ -8401,7 +8401,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen private static final void dumpApplicationMemoryUsage(FileDescriptor fd, PrintWriter pw, List list, String prefix, String[] args) { - final boolean isCheckinRequest = scanArgs(args, "-c"); + final boolean isCheckinRequest = scanArgs(args, "--checkin"); long uptime = SystemClock.uptimeMillis(); long realtime = SystemClock.elapsedRealtime(); diff --git a/services/java/com/android/server/am/BatteryStatsService.java b/services/java/com/android/server/am/BatteryStatsService.java index c5907afbd967..e265f43046ca 100644 --- a/services/java/com/android/server/am/BatteryStatsService.java +++ b/services/java/com/android/server/am/BatteryStatsService.java @@ -295,7 +295,7 @@ public final class BatteryStatsService extends IBatteryStats.Stub { boolean isCheckin = false; if (args != null) { for (String arg : args) { - if ("-c".equals(arg)) { + if ("--checkin".equals(arg)) { isCheckin = true; break; } diff --git a/services/java/com/android/server/am/HistoryRecord.java b/services/java/com/android/server/am/HistoryRecord.java index 0f62471ed7d3..ae16b1433ae7 100644 --- a/services/java/com/android/server/am/HistoryRecord.java +++ b/services/java/com/android/server/am/HistoryRecord.java @@ -335,14 +335,18 @@ class HistoryRecord extends IApplicationToken.Stub { public void windowsVisible() { synchronized(service) { - if (ActivityManagerService.SHOW_ACTIVITY_START_TIME - && startTime != 0) { + if (startTime != 0) { long time = SystemClock.uptimeMillis() - startTime; - EventLog.writeEvent(ActivityManagerService.LOG_ACTIVITY_LAUNCH_TIME, - System.identityHashCode(this), shortComponentName, time); - Log.i(ActivityManagerService.TAG, "Displayed activity " - + shortComponentName - + ": " + time + " ms"); + if (ActivityManagerService.SHOW_ACTIVITY_START_TIME) { + EventLog.writeEvent(ActivityManagerService.LOG_ACTIVITY_LAUNCH_TIME, + System.identityHashCode(this), shortComponentName, time); + Log.i(ActivityManagerService.TAG, "Displayed activity " + + shortComponentName + + ": " + time + " ms"); + } + if (time > 0) { + service.mUsageStatsService.noteLaunchTime(realActivity, (int)time); + } startTime = 0; } if (ActivityManagerService.DEBUG_SWITCH) Log.v( diff --git a/services/java/com/android/server/am/UsageStatsService.java b/services/java/com/android/server/am/UsageStatsService.java index 3922f39f52ba..7709efd6b26b 100755 --- a/services/java/com/android/server/am/UsageStatsService.java +++ b/services/java/com/android/server/am/UsageStatsService.java @@ -37,11 +37,11 @@ import java.io.PrintWriter; import java.util.ArrayList; import java.util.Calendar; import java.util.Collections; -import java.util.Date; import java.util.HashMap; import java.util.List; import java.util.Map; import java.util.Set; +import java.util.TimeZone; /** * This service collects the statistics associated with usage @@ -53,6 +53,20 @@ public final class UsageStatsService extends IUsageStats.Stub { public static final String SERVICE_NAME = "usagestats"; private static final boolean localLOGV = false; private static final String TAG = "UsageStats"; + + // Current on-disk Parcel version + private static final int VERSION = 1003; + + private static final int CHECKIN_VERSION = 2; + + private static final String FILE_PREFIX = "usage-"; + + private static final int FILE_WRITE_INTERVAL = 30*60*1000; //ms + + private static final int MAX_NUM_FILES = 5; + + private static final int MAX_LAUNCH_TIME_SAMPLES = 50; + static IUsageStats sService; private Context mContext; // structure used to maintain statistics since the last checkin. @@ -66,16 +80,76 @@ public final class UsageStatsService extends IUsageStats.Stub { // Order of locks is mFileLock followed by mStatsLock to avoid deadlocks private String mResumedPkg; private File mFile; + private String mFileLeaf; //private File mBackupFile; - private long mLastWriteRealTime; - private int _FILE_WRITE_INTERVAL = 30*60*1000; //ms - private static final String _PREFIX_DELIMIT="."; - private String mFilePrefix; + private long mLastWriteElapsedTime; + private File mDir; private Calendar mCal; - private static final int _MAX_NUM_FILES = 10; - private long mLastTime; + private int mLastWriteDay; + + static class TimeStats { + int count; + + boolean haveStats; + + int samples; + int minimum; + int maximum; + int average; + int median; + + int size; + int[] array; + + private int avail; + + void add(int val) { + count++; + if (size > MAX_LAUNCH_TIME_SAMPLES) { + return; + } + if (size >= avail) { + avail = ((avail+2)*3)/2; + int[] newarray = new int[avail]; + if (array != null) { + System.arraycopy(array, 0, newarray, 0, size); + } + array = newarray; + } + array[size] = val; + size++; + haveStats = false; + } + + void computeStats() { + if (haveStats) { + return; + } + + average = 0; + int i = samples = size; + if (i > 0) { + java.util.Arrays.sort(array, 0, i); + i--; + minimum = maximum = average = array[i]; + median = array[i/2]; + while (i > 0) { + i--; + int v = array[i]; + if (v < minimum) minimum = v; + if (v > maximum) maximum = v; + average += v; + } + average = average/size; + } else { + minimum = maximum = median = 0; + } + } + } private class PkgUsageStatsExtended { + final HashMap mLaunchTimes + = new HashMap(); int mLaunchCount; long mUsageTime; long mPausedTime; @@ -85,44 +159,142 @@ public final class UsageStatsService extends IUsageStats.Stub { mLaunchCount = 0; mUsageTime = 0; } + + PkgUsageStatsExtended(Parcel in) { + mLaunchCount = in.readInt(); + mUsageTime = in.readLong(); + if (localLOGV) Log.v(TAG, "Launch count: " + mLaunchCount + + ", Usage time:" + mUsageTime); + + final int N = in.readInt(); + if (localLOGV) Log.v(TAG, "Reading comps: " + N); + for (int i=0; i 0) { + TimeStats times = new TimeStats(); + times.count = count; + times.size = times.avail = M; + times.array = new int[M]; + for (int j=0; j 0) { + for (Map.Entry ent : mLaunchTimes.entrySet()) { + out.writeString(ent.getKey()); + TimeStats times = ent.getValue(); + if (allTimes) { + final int M = times.size; + out.writeInt(M); + out.writeInt(times.count); + for (int j=0; j(); mStatsLock = new Object(); mFileLock = new Object(); - mFilePrefix = fileName; - mCal = Calendar.getInstance(); + mDir = new File(dir); + mCal = Calendar.getInstance(TimeZone.getTimeZone("GMT+0")); + + mDir.mkdir(); + + // Remove any old usage files from previous versions. + File parentDir = mDir.getParentFile(); + String fList[] = parentDir.list(); + if (fList != null) { + String prefix = mDir.getName() + "."; + int i = fList.length; + while (i > 0) { + i--; + if (fList[i].startsWith(prefix)) { + Log.i(TAG, "Deleting old usage file: " + fList[i]); + (new File(parentDir, fList[i])).delete(); + } + } + } + // Update current stats which are binned by date - String uFileName = getCurrentDateStr(mFilePrefix); - mFile = new File(uFileName); + mFileLeaf = getCurrentDateStr(FILE_PREFIX); + mFile = new File(mDir, mFileLeaf); readStatsFromFile(); - mLastWriteRealTime = SystemClock.elapsedRealtime(); - mLastTime = new Date().getTime(); + mLastWriteElapsedTime = SystemClock.elapsedRealtime(); + // mCal was set by getCurrentDateStr(), want to use that same time. + mLastWriteDay = mCal.get(Calendar.DAY_OF_YEAR); } /* * Utility method to convert date into string. */ private String getCurrentDateStr(String prefix) { - mCal.setTime(new Date()); + mCal.setTimeInMillis(System.currentTimeMillis()); StringBuilder sb = new StringBuilder(); if (prefix != null) { sb.append(prefix); - sb.append("."); } + sb.append(mCal.get(Calendar.YEAR)); int mm = mCal.get(Calendar.MONTH) - Calendar.JANUARY +1; if (mm < 10) { sb.append("0"); @@ -133,7 +305,6 @@ public final class UsageStatsService extends IUsageStats.Stub { sb.append("0"); } sb.append(dd); - sb.append(mCal.get(Calendar.YEAR)); return sb.toString(); } @@ -166,11 +337,20 @@ public final class UsageStatsService extends IUsageStats.Stub { private void readStatsFLOCK(File file) throws IOException { Parcel in = getParcelForFile(file); - while (in.dataAvail() > 0) { + int vers = in.readInt(); + if (vers != VERSION) { + Log.w(TAG, "Usage stats version changed; dropping"); + return; + } + int N = in.readInt(); + while (N > 0) { + N--; String pkgName = in.readString(); - PkgUsageStatsExtended pus = new PkgUsageStatsExtended(); - pus.mLaunchCount = in.readInt(); - pus.mUsageTime = in.readLong(); + if (pkgName == null) { + break; + } + if (localLOGV) Log.v(TAG, "Reading package #" + N + ": " + pkgName); + PkgUsageStatsExtended pus = new PkgUsageStatsExtended(in); synchronized (mStatsLock) { mStats.put(pkgName, pus); } @@ -178,27 +358,18 @@ public final class UsageStatsService extends IUsageStats.Stub { } private ArrayList getUsageStatsFileListFLOCK() { - File dir = getUsageFilesDir(); - if (dir == null) { - Log.w(TAG, "Couldnt find writable directory for usage stats file"); - return null; - } // Check if there are too many files in the system and delete older files - String fList[] = dir.list(); + String fList[] = mDir.list(); if (fList == null) { return null; } - File pre = new File(mFilePrefix); - String filePrefix = pre.getName(); - // file name followed by dot - int prefixLen = filePrefix.length()+1; ArrayList fileList = new ArrayList(); for (String file : fList) { - int index = file.indexOf(filePrefix); - if (index == -1) { + if (!file.startsWith(FILE_PREFIX)) { continue; } if (file.endsWith(".bak")) { + (new File(mDir, file)).delete(); continue; } fileList.add(file); @@ -206,20 +377,7 @@ public final class UsageStatsService extends IUsageStats.Stub { return fileList; } - private File getUsageFilesDir() { - if (mFilePrefix == null) { - return null; - } - File pre = new File(mFilePrefix); - return new File(pre.getParent()); - } - private void checkFileLimitFLOCK() { - File dir = getUsageFilesDir(); - if (dir == null) { - Log.w(TAG, "Couldnt find writable directory for usage stats file"); - return; - } // Get all usage stats output files ArrayList fileList = getUsageStatsFileListFLOCK(); if (fileList == null) { @@ -227,49 +385,54 @@ public final class UsageStatsService extends IUsageStats.Stub { return; } int count = fileList.size(); - if (count <= _MAX_NUM_FILES) { + if (count <= MAX_NUM_FILES) { return; } // Sort files Collections.sort(fileList); - count -= _MAX_NUM_FILES; + count -= MAX_NUM_FILES; // Delete older files for (int i = 0; i < count; i++) { String fileName = fileList.get(i); - File file = new File(dir, fileName); - Log.i(TAG, "Deleting file : "+fileName); + File file = new File(mDir, fileName); + Log.i(TAG, "Deleting usage file : " + fileName); file.delete(); } } - private void writeStatsToFile() { + private void writeStatsToFile(boolean force) { synchronized (mFileLock) { - long currTime = new Date().getTime(); - boolean dayChanged = ((currTime - mLastTime) >= (24*60*60*1000)); - long currRealTime = SystemClock.elapsedRealtime(); - if (((currRealTime-mLastWriteRealTime) < _FILE_WRITE_INTERVAL) && - (!dayChanged)) { - // wait till the next update - return; + mCal.setTimeInMillis(System.currentTimeMillis()); + final int curDay = mCal.get(Calendar.DAY_OF_YEAR); + // Determine if the day changed... note that this will be wrong + // if the year has changed but we are in the same day of year... + // we can probably live with this. + final boolean dayChanged = curDay != mLastWriteDay; + long currElapsedTime = SystemClock.elapsedRealtime(); + if (!force) { + if (((currElapsedTime-mLastWriteElapsedTime) < FILE_WRITE_INTERVAL) && + (!dayChanged)) { + // wait till the next update + return; + } } // Get the most recent file - String todayStr = getCurrentDateStr(mFilePrefix); + mFileLeaf = getCurrentDateStr(FILE_PREFIX); // Copy current file to back up File backupFile = new File(mFile.getPath() + ".bak"); mFile.renameTo(backupFile); try { - checkFileLimitFLOCK(); - mFile.createNewFile(); // Write mStats to file - writeStatsFLOCK(); - mLastWriteRealTime = currRealTime; - mLastTime = currTime; + writeStatsFLOCK(!dayChanged); + mLastWriteElapsedTime = currElapsedTime; if (dayChanged) { + mLastWriteDay = curDay; // clear stats synchronized (mStats) { mStats.clear(); } - mFile = new File(todayStr); + mFile = new File(mDir, mFileLeaf); + checkFileLimitFLOCK(); } // Delete the backup file if (backupFile != null) { @@ -278,30 +441,35 @@ public final class UsageStatsService extends IUsageStats.Stub { } catch (IOException e) { Log.w(TAG, "Failed writing stats to file:" + mFile); if (backupFile != null) { + mFile.delete(); backupFile.renameTo(mFile); } } } } - private void writeStatsFLOCK() throws IOException { + private void writeStatsFLOCK(boolean allTimes) throws IOException { FileOutputStream stream = new FileOutputStream(mFile); - Parcel out = Parcel.obtain(); - writeStatsToParcelFLOCK(out); - stream.write(out.marshall()); - out.recycle(); - stream.flush(); - stream.close(); + try { + Parcel out = Parcel.obtain(); + writeStatsToParcelFLOCK(out, allTimes); + stream.write(out.marshall()); + out.recycle(); + stream.flush(); + } finally { + stream.close(); + } } - private void writeStatsToParcelFLOCK(Parcel out) { + private void writeStatsToParcelFLOCK(Parcel out, boolean allTimes) { synchronized (mStatsLock) { + out.writeInt(VERSION); Set keys = mStats.keySet(); + out.writeInt(keys.size()); for (String key : keys) { PkgUsageStatsExtended pus = mStats.get(key); out.writeString(key); - out.writeInt(pus.mLaunchCount); - out.writeLong(pus.mUsageTime); + pus.writeToParcel(out, allTimes); } } } @@ -355,6 +523,10 @@ public final class UsageStatsService extends IUsageStats.Stub { return; } if (localLOGV) Log.i(TAG, "paused component:"+pkgName); + + // Persist current data to file if needed. + writeStatsToFile(false); + synchronized (mStatsLock) { PkgUsageStatsExtended pus = mStats.get(pkgName); if (pus == null) { @@ -364,8 +536,25 @@ public final class UsageStatsService extends IUsageStats.Stub { } pus.updatePause(); } - // Persist data to file - writeStatsToFile(); + } + + public void noteLaunchTime(ComponentName componentName, int millis) { + enforceCallingPermission(); + String pkgName; + if ((componentName == null) || + ((pkgName = componentName.getPackageName()) == null)) { + return; + } + + // Persist current data to file if needed. + writeStatsToFile(false); + + synchronized (mStatsLock) { + PkgUsageStatsExtended pus = mStats.get(pkgName); + if (pus != null) { + pus.addLaunchTime(componentName.getClassName(), millis); + } + } } public void enforceCallingPermission() { @@ -432,27 +621,25 @@ public final class UsageStatsService extends IUsageStats.Stub { } } - private void collectDumpInfoFLOCK(PrintWriter pw, String[] args) { + private void collectDumpInfoFLOCK(PrintWriter pw, boolean isCompactOutput, + boolean deleteAfterPrint) { List fileList = getUsageStatsFileListFLOCK(); if (fileList == null) { return; } - final boolean isCheckinRequest = scanArgs(args, "-c"); Collections.sort(fileList); - File usageFile = new File(mFilePrefix); - String dirName = usageFile.getParent(); - File dir = new File(dirName); - String filePrefix = usageFile.getName(); - // file name followed by dot - int prefixLen = filePrefix.length()+1; - String todayStr = getCurrentDateStr(null); for (String file : fileList) { - File dFile = new File(dir, file); - String dateStr = file.substring(prefixLen); + if (deleteAfterPrint && file.equalsIgnoreCase(mFileLeaf)) { + // In this mode we don't print the current day's stats, since + // they are incomplete. + continue; + } + File dFile = new File(mDir, file); + String dateStr = file.substring(FILE_PREFIX.length()); try { Parcel in = getParcelForFile(dFile); - collectDumpInfoFromParcelFLOCK(in, pw, dateStr, isCheckinRequest); - if (isCheckinRequest && !todayStr.equalsIgnoreCase(dateStr)) { + collectDumpInfoFromParcelFLOCK(in, pw, dateStr, isCompactOutput); + if (deleteAfterPrint) { // Delete old file after collecting info only for checkin requests dFile.delete(); } @@ -466,40 +653,102 @@ public final class UsageStatsService extends IUsageStats.Stub { } private void collectDumpInfoFromParcelFLOCK(Parcel in, PrintWriter pw, - String date, boolean isCheckinRequest) { - StringBuilder sb = new StringBuilder(); - sb.append("Date:"); + String date, boolean isCompactOutput) { + StringBuilder sb = new StringBuilder(512); + if (isCompactOutput) { + sb.append("D:"); + sb.append(CHECKIN_VERSION); + sb.append(','); + } else { + sb.append("Date: "); + } + sb.append(date); - boolean first = true; - while (in.dataAvail() > 0) { + + int vers = in.readInt(); + if (vers != VERSION) { + sb.append(" (old data version)"); + pw.println(sb.toString()); + return; + } + + pw.println(sb.toString()); + int N = in.readInt(); + + while (N > 0) { + N--; String pkgName = in.readString(); - int launchCount = in.readInt(); - long usageTime = in.readLong(); - if (isCheckinRequest) { - if (!first) { - sb.append(","); - } + if (pkgName == null) { + break; + } + sb.setLength(0); + PkgUsageStatsExtended pus = new PkgUsageStatsExtended(in); + if (isCompactOutput) { + sb.append("P:"); sb.append(pkgName); sb.append(","); - sb.append(launchCount); + sb.append(pus.mLaunchCount); sb.append(","); - sb.append(usageTime); - sb.append("ms"); - } else { - if (first) { - sb.append("\n"); + sb.append(pus.mUsageTime); + sb.append('\n'); + final int NC = pus.mLaunchTimes.size(); + if (NC > 0) { + for (Map.Entry ent : pus.mLaunchTimes.entrySet()) { + sb.append("A:"); + sb.append(ent.getKey()); + sb.append(","); + TimeStats times = ent.getValue(); + times.computeStats(); + sb.append(times.count); + sb.append(","); + sb.append(times.samples); + sb.append(","); + sb.append(times.minimum); + sb.append(","); + sb.append(times.maximum); + sb.append(","); + sb.append(times.average); + sb.append(","); + sb.append(times.median); + sb.append('\n'); + } } - sb.append("pkg="); + + } else { + sb.append(" "); sb.append(pkgName); - sb.append(", launchCount="); - sb.append(launchCount); - sb.append(", usageTime="); - sb.append(usageTime); - sb.append(" ms\n"); + sb.append(": "); + sb.append(pus.mLaunchCount); + sb.append(" times, "); + sb.append(pus.mUsageTime); + sb.append(" ms"); + sb.append('\n'); + final int NC = pus.mLaunchTimes.size(); + if (NC > 0) { + for (Map.Entry ent : pus.mLaunchTimes.entrySet()) { + sb.append(" "); + sb.append(ent.getKey()); + TimeStats times = ent.getValue(); + times.computeStats(); + sb.append(": count="); + sb.append(times.count); + sb.append(", samples="); + sb.append(times.samples); + sb.append(", min="); + sb.append(times.minimum); + sb.append(", max="); + sb.append(times.maximum); + sb.append(", avg="); + sb.append(times.average); + sb.append(", med="); + sb.append(times.median); + sb.append('\n'); + } + } } - first = false; + + pw.write(sb.toString()); } - pw.write(sb.toString()); } /** @@ -524,8 +773,19 @@ public final class UsageStatsService extends IUsageStats.Stub { * The data persisted to file is parsed and the stats are computed. */ protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) { + final boolean isCheckinRequest = scanArgs(args, "--checkin"); + final boolean isCompactOutput = isCheckinRequest || scanArgs(args, "-c"); + final boolean deleteAfterPrint = isCheckinRequest || scanArgs(args, "-d"); + + // Make sure the current stats are written to the file. This + // doesn't need to be done if we are deleting files after printing, + // since it that case we won't print the current stats. + if (!deleteAfterPrint) { + writeStatsToFile(true); + } + synchronized (mFileLock) { - collectDumpInfoFLOCK(pw, args); + collectDumpInfoFLOCK(pw, isCompactOutput, deleteAfterPrint); } } -- 2.11.0