Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 389a9167 authored by Brad Fitzpatrick's avatar Brad Fitzpatrick
Browse files

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.<init>(FileOutputStream.java:97)
  at java.io.FileOutputStream.<init>(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
parent 5d46ce24
Loading
Loading
Loading
Loading
+81 −40
Original line number Diff line number Diff line
@@ -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,17 +246,18 @@ 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();
        synchronized (mCal) {
            mCal.setTimeInMillis(System.currentTimeMillis());
            if (prefix != null) {
                sb.append(prefix);
            }
@@ -266,6 +272,7 @@ public final class UsageStatsService extends IUsageStats.Stub {
                sb.append("0");
            }
            sb.append(dd);
        }
        return sb.toString();
    }
    
@@ -361,22 +368,55 @@ public final class UsageStatsService extends IUsageStats.Stub {
        }
    }

    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);
            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 boolean dayChanged =  curDay != mLastWriteDay;
            long currElapsedTime = SystemClock.elapsedRealtime();
        final long currElapsedTime = SystemClock.elapsedRealtime();

        // Fast common path, without taking the often-contentious
        // mFileLock.
        if (!force) {
                if (((currElapsedTime-mLastWriteElapsedTime) < FILE_WRITE_INTERVAL) &&
                        (!dayChanged)) {
            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);