From 389a916769aaf4b329839285d2f975fc23aadfb4 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Tue, 3 Aug 2010 15:41:05 -0700 Subject: [PATCH] Usage Stats: don't block writing stats to disk. I was seeing lots of stack traces of people hung for noticeable amounts of time when switching between activities. e.g. On of the common gmail stacks showing this pause was: android.os.StrictMode$StrictModeDiskWriteViolation: policy=391 violation=1 at android.os.StrictMode$AndroidBlockGuardPolicy.startHandlingViolationException(StrictMode.java:272) at android.os.StrictMode$AndroidBlockGuardPolicy.onWriteToDisk(StrictMode.java:243) at dalvik.system.BlockGuard$WrappedFileSystem.open(BlockGuard.java:238) at java.io.FileOutputStream.(FileOutputStream.java:97) at java.io.FileOutputStream.(FileOutputStream.java:69) at com.android.server.am.UsageStatsService.writeStatsFLOCK(UsageStatsService.java:424) at com.android.server.am.UsageStatsService.writeStatsToFile(UsageStatsService.java:398) at com.android.server.am.UsageStatsService.notePauseComponent(UsageStatsService.java:539) at com.android.server.am.ActivityManagerService.updateUsageStats(ActivityManagerService.java:1856) at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:667) at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:2925) at com.android.server.am.ActivityStack.requestFinishActivityLocked(ActivityStack.java:2836) at com.android.server.am.ActivityManagerService.finishActivity(ActivityManagerService.java:2276) at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:237) at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:1415) at android.os.Binder.execTransact(Binder.java:320) at dalvik.system.NativeStart.run(Native Method) at android.app.ActivityManagerProxy.finishActivity(ActivityManagerNative.java:1454) at android.app.Activity.finish(Activity.java:3260) at android.app.Activity.onBackPressed(Activity.java:1929) at android.app.Activity.onKeyUp(Activity.java:1907) at android.view.KeyEvent.dispatch(KeyEvent.java:1088) at android.app.Activity.dispatchKeyEvent(Activity.java:2087) at com.android.internal.policy.impl.PhoneWindow$DecorView.dispatchKeyEvent(PhoneWindow.java:1661) at android.view.ViewRoot.deliverKeyEventToViewHierarchy(ViewRoot.java:2543) at android.view.ViewRoot.handleFinishedEvent(ViewRoot.java:2516) at android.view.ViewRoot.handleMessage(ViewRoot.java:1866) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:123) at android.app.ActivityThread.main(ActivityThread.java:3609) at java.lang.reflect.Method.invokeNative(Native Method) at java.lang.reflect.Method.invoke(Method.java:521) at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626) at dalvik.system.NativeStart.main(Native Method) Change-Id: Id49157bc635017292eaefddc5e22d73f5f4ab05e --- .../android/server/am/UsageStatsService.java | 121 ++++++++++++------ 1 file changed, 81 insertions(+), 40 deletions(-) diff --git a/services/java/com/android/server/am/UsageStatsService.java b/services/java/com/android/server/am/UsageStatsService.java index 1b9e1c77fa87d..3f15d0a5bffd6 100644 --- a/services/java/com/android/server/am/UsageStatsService.java +++ b/services/java/com/android/server/am/UsageStatsService.java @@ -44,6 +44,9 @@ import java.util.List; import java.util.Map; import java.util.Set; import java.util.TimeZone; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.concurrent.atomic.AtomicLong; /** * This service collects the statistics associated with usage @@ -88,11 +91,13 @@ public final class UsageStatsService extends IUsageStats.Stub { private boolean mIsResumed; private File mFile; private String mFileLeaf; - //private File mBackupFile; - private long mLastWriteElapsedTime; private File mDir; - private Calendar mCal; - private int mLastWriteDay; + + private Calendar mCal; // guarded by itself + + private final AtomicInteger mLastWriteDay = new AtomicInteger(-1); + private final AtomicLong mLastWriteElapsedTime = new AtomicLong(0); + private final AtomicBoolean mUnforcedDiskWriteRunning = new AtomicBoolean(false); static class TimeStats { int count; @@ -241,31 +246,33 @@ public final class UsageStatsService extends IUsageStats.Stub { mFileLeaf = getCurrentDateStr(FILE_PREFIX); mFile = new File(mDir, mFileLeaf); readStatsFromFile(); - mLastWriteElapsedTime = SystemClock.elapsedRealtime(); + mLastWriteElapsedTime.set(SystemClock.elapsedRealtime()); // mCal was set by getCurrentDateStr(), want to use that same time. - mLastWriteDay = mCal.get(Calendar.DAY_OF_YEAR); + mLastWriteDay.set(mCal.get(Calendar.DAY_OF_YEAR)); } /* * Utility method to convert date into string. */ private String getCurrentDateStr(String prefix) { - mCal.setTimeInMillis(System.currentTimeMillis()); StringBuilder sb = new StringBuilder(); - if (prefix != null) { - sb.append(prefix); + synchronized (mCal) { + mCal.setTimeInMillis(System.currentTimeMillis()); + if (prefix != null) { + sb.append(prefix); + } + sb.append(mCal.get(Calendar.YEAR)); + int mm = mCal.get(Calendar.MONTH) - Calendar.JANUARY +1; + if (mm < 10) { + sb.append("0"); + } + sb.append(mm); + int dd = mCal.get(Calendar.DAY_OF_MONTH); + if (dd < 10) { + sb.append("0"); + } + sb.append(dd); } - sb.append(mCal.get(Calendar.YEAR)); - int mm = mCal.get(Calendar.MONTH) - Calendar.JANUARY +1; - if (mm < 10) { - sb.append("0"); - } - sb.append(mm); - int dd = mCal.get(Calendar.DAY_OF_MONTH); - if (dd < 10) { - sb.append("0"); - } - sb.append(dd); return sb.toString(); } @@ -360,23 +367,56 @@ public final class UsageStatsService extends IUsageStats.Stub { file.delete(); } } - - private void writeStatsToFile(boolean force) { - synchronized (mFileLock) { + + /** + * Conditionally start up a disk write if it's been awhile, or the + * day has rolled over. + * + * This is called indirectly from user-facing actions (when + * 'force' is false) so it tries to be quick, without writing to + * disk directly or acquiring heavy locks. + * + * @params force do an unconditional, synchronous stats flush + * to disk on the current thread. + */ + private void writeStatsToFile(final boolean force) { + int curDay; + synchronized (mCal) { 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; - } + curDay = mCal.get(Calendar.DAY_OF_YEAR); + } + final boolean dayChanged = curDay != mLastWriteDay.get(); + + // 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 long currElapsedTime = SystemClock.elapsedRealtime(); + + // Fast common path, without taking the often-contentious + // mFileLock. + if (!force) { + if (!dayChanged && + (currElapsedTime - mLastWriteElapsedTime.get()) < FILE_WRITE_INTERVAL) { + // wait till the next update + return; } + if (mUnforcedDiskWriteRunning.compareAndSet(false, true)) { + new Thread("UsageStatsService_DiskWriter") { + public void run() { + try { + Slog.d(TAG, "Disk writer thread starting."); + writeStatsToFile(true); + } finally { + mUnforcedDiskWriteRunning.set(false); + Slog.d(TAG, "Disk writer thread ending."); + } + } + }.start(); + } + return; + } + + synchronized (mFileLock) { // Get the most recent file mFileLeaf = getCurrentDateStr(FILE_PREFIX); // Copy current file to back up @@ -395,10 +435,10 @@ public final class UsageStatsService extends IUsageStats.Stub { try { // Write mStats to file - writeStatsFLOCK(); - mLastWriteElapsedTime = currElapsedTime; + writeStatsFLOCK(mFile); + mLastWriteElapsedTime.set(currElapsedTime); if (dayChanged) { - mLastWriteDay = curDay; + mLastWriteDay.set(curDay); // clear stats synchronized (mStats) { mStats.clear(); @@ -418,10 +458,11 @@ public final class UsageStatsService extends IUsageStats.Stub { } } } + Slog.d(TAG, "Dumped usage stats."); } - private void writeStatsFLOCK() throws IOException { - FileOutputStream stream = new FileOutputStream(mFile); + private void writeStatsFLOCK(File file) throws IOException { + FileOutputStream stream = new FileOutputStream(file); try { Parcel out = Parcel.obtain(); writeStatsToParcelFLOCK(out);