UsageStats should deal with changing time

When the system time is changed, the UsageStats API
will modify all existing entries to correspond with the
new time change. If the time changed when the device was
off, stats in the future will be deleted.

Change-Id: Ica3e9917d4d1a180f97700e52ab390e3673e1e82

4 files changed, 179 insertions, 84 deletions

diff --git a/services/usage/java/com/android/server/usage/UsageStatsDatabase.java b/services/usage/java/com/android/server/usage/UsageStatsDatabase.java
index 62a7ec0..972c929 100644
--- a/services/usage/java/com/android/server/usage/UsageStatsDatabase.java
+++ b/services/usage/java/com/android/server/usage/UsageStatsDatabase.java
@@ -61,7 +61,7 @@ class UsageStatsDatabase {
     /**
      * Initialize any directories required and index what stats are available.
      */
-    void init() {
+    public void init(long currentTimeMillis) {
         synchronized (mLock) {
             for (File f : mIntervalDirs) {
                 f.mkdirs();
@@ -72,27 +72,53 @@ class UsageStatsDatabase {
             }
 
             checkVersionLocked();
+            indexFilesLocked();
 
-            final FilenameFilter backupFileFilter = new FilenameFilter() {
-                @Override
-                public boolean accept(File dir, String name) {
-                    return !name.endsWith(".bak");
+            // Delete files that are in the future.
+            for (TimeSparseArray<AtomicFile> files : mSortedStatFiles) {
+                final int startIndex = files.closestIndexOnOrAfter(currentTimeMillis);
+                if (startIndex < 0) {
+                    continue;
                 }
-            };
 
-            // Index the available usage stat files on disk.
-            for (int i = 0; i < mSortedStatFiles.length; i++) {
+                final int fileCount = files.size();
+                for (int i = startIndex; i < fileCount; i++) {
+                    files.valueAt(i).delete();
+                }
+
+                // Remove in a separate loop because any accesses (valueAt)
+                // will cause a gc in the SparseArray and mess up the order.
+                for (int i = startIndex; i < fileCount; i++) {
+                    files.removeAt(i);
+                }
+            }
+        }
+    }
+
+    private void indexFilesLocked() {
+        final FilenameFilter backupFileFilter = new FilenameFilter() {
+            @Override
+            public boolean accept(File dir, String name) {
+                return !name.endsWith(".bak");
+            }
+        };
+
+        // Index the available usage stat files on disk.
+        for (int i = 0; i < mSortedStatFiles.length; i++) {
+            if (mSortedStatFiles[i] == null) {
                 mSortedStatFiles[i] = new TimeSparseArray<>();
-                File[] files = mIntervalDirs[i].listFiles(backupFileFilter);
-                if (files != null) {
-                    if (DEBUG) {
-                        Slog.d(TAG, "Found " + files.length + " stat files for interval " + i);
-                    }
+            } else {
+                mSortedStatFiles[i].clear();
+            }
+            File[] files = mIntervalDirs[i].listFiles(backupFileFilter);
+            if (files != null) {
+                if (DEBUG) {
+                    Slog.d(TAG, "Found " + files.length + " stat files for interval " + i);
+                }
 
-                    for (File f : files) {
-                        final AtomicFile af = new AtomicFile(f);
-                        mSortedStatFiles[i].put(UsageStatsXml.parseBeginTime(af), af);
-                    }
+                for (File f : files) {
+                    final AtomicFile af = new AtomicFile(f);
+                    mSortedStatFiles[i].put(UsageStatsXml.parseBeginTime(af), af);
                 }
             }
         }
@@ -135,6 +161,38 @@ class UsageStatsDatabase {
         }
     }
 
+    public void onTimeChanged(long timeDiffMillis) {
+        synchronized (mLock) {
+            for (TimeSparseArray<AtomicFile> files : mSortedStatFiles) {
+                final int fileCount = files.size();
+                for (int i = 0; i < fileCount; i++) {
+                    final AtomicFile file = files.valueAt(i);
+                    final long newTime = files.keyAt(i) + timeDiffMillis;
+                    if (newTime < 0) {
+                        Slog.i(TAG, "Deleting file " + file.getBaseFile().getAbsolutePath()
+                                + " for it is in the future now.");
+                        file.delete();
+                    } else {
+                        try {
+                            file.openRead().close();
+                        } catch (IOException e) {
+                            // Ignore, this is just to make sure there are no backups.
+                        }
+                        final File newFile = new File(file.getBaseFile().getParentFile(),
+                                Long.toString(newTime));
+                        Slog.i(TAG, "Moving file " + file.getBaseFile().getAbsolutePath() + " to "
+                                + newFile.getAbsolutePath());
+                        file.getBaseFile().renameTo(newFile);
+                    }
+                }
+                files.clear();
+            }
+
+            // Now re-index the new files.
+            indexFilesLocked();
+        }
+    }
+
     /**
      * Get the latest stats that exist for this interval type.
      */
@@ -296,25 +354,24 @@ class UsageStatsDatabase {
     /**
      * Remove any usage stat files that are too old.
      */
-    public void prune() {
+    public void prune(final long currentTimeMillis) {
         synchronized (mLock) {
-            long timeNow = System.currentTimeMillis();
-            mCal.setTimeInMillis(timeNow);
+            mCal.setTimeInMillis(currentTimeMillis);
             mCal.addYears(-3);
             pruneFilesOlderThan(mIntervalDirs[UsageStatsManager.INTERVAL_YEARLY],
                     mCal.getTimeInMillis());
 
-            mCal.setTimeInMillis(timeNow);
+            mCal.setTimeInMillis(currentTimeMillis);
             mCal.addMonths(-6);
             pruneFilesOlderThan(mIntervalDirs[UsageStatsManager.INTERVAL_MONTHLY],
                     mCal.getTimeInMillis());
 
-            mCal.setTimeInMillis(timeNow);
+            mCal.setTimeInMillis(currentTimeMillis);
             mCal.addWeeks(-4);
             pruneFilesOlderThan(mIntervalDirs[UsageStatsManager.INTERVAL_WEEKLY],
                     mCal.getTimeInMillis());
 
-            mCal.setTimeInMillis(timeNow);
+            mCal.setTimeInMillis(currentTimeMillis);
             mCal.addDays(-7);
             pruneFilesOlderThan(mIntervalDirs[UsageStatsManager.INTERVAL_DAILY],
                     mCal.getTimeInMillis());
diff --git a/services/usage/java/com/android/server/usage/UsageStatsService.java b/services/usage/java/com/android/server/usage/UsageStatsService.java
index 2dcdcc4..6df09ac 100644
--- a/services/usage/java/com/android/server/usage/UsageStatsService.java
+++ b/services/usage/java/com/android/server/usage/UsageStatsService.java
@@ -64,6 +64,7 @@ public class UsageStatsService extends SystemService implements
     private static final long TEN_SECONDS = 10 * 1000;
     private static final long TWENTY_MINUTES = 20 * 60 * 1000;
     private static final long FLUSH_INTERVAL = DEBUG ? TEN_SECONDS : TWENTY_MINUTES;
+    private static final long TIME_CHANGE_THRESHOLD_MILLIS = 2 * 1000; // Two seconds.
 
     // Handler message types.
     static final int MSG_REPORT_EVENT = 0;
@@ -170,18 +171,47 @@ public class UsageStatsService extends SystemService implements
         }
     }
 
-    private UserUsageStatsService getUserDataAndInitializeIfNeededLocked(int userId) {
+    private UserUsageStatsService getUserDataAndInitializeIfNeededLocked(int userId,
+            long currentTimeMillis) {
         UserUsageStatsService service = mUserState.get(userId);
         if (service == null) {
             service = new UserUsageStatsService(userId,
                     new File(mUsageStatsDir, Integer.toString(userId)), this);
-            service.init();
+            service.init(currentTimeMillis);
             mUserState.put(userId, service);
         }
         return service;
     }
 
     /**
+     * This should be the only way to get the time from the system.
+     */
+    private long checkAndGetTimeLocked() {
+        final long actualSystemTime = System.currentTimeMillis();
+        final long actualRealtime = SystemClock.elapsedRealtime();
+        final long expectedSystemTime = (actualRealtime - mRealTimeSnapshot) + mSystemTimeSnapshot;
+        if (Math.abs(actualSystemTime - expectedSystemTime) > TIME_CHANGE_THRESHOLD_MILLIS) {
+            // The time has changed.
+            final int userCount = mUserState.size();
+            for (int i = 0; i < userCount; i++) {
+                final UserUsageStatsService service = mUserState.valueAt(i);
+                service.onTimeChanged(expectedSystemTime, actualSystemTime);
+            }
+            mRealTimeSnapshot = actualRealtime;
+            mSystemTimeSnapshot = actualSystemTime;
+        }
+        return actualSystemTime;
+    }
+
+    /**
+     * Assuming the event's timestamp is measured in milliseconds since boot,
+     * convert it to a system wall time.
+     */
+    private void convertToSystemTimeLocked(UsageEvents.Event event) {
+        event.mTimeStamp = Math.max(0, event.mTimeStamp - mRealTimeSnapshot) + mSystemTimeSnapshot;
+    }
+
+    /**
      * Called by the Binder stub
      */
     void shutdown() {
@@ -196,7 +226,11 @@ public class UsageStatsService extends SystemService implements
      */
     void reportEvent(UsageEvents.Event event, int userId) {
         synchronized (mLock) {
-            final UserUsageStatsService service = getUserDataAndInitializeIfNeededLocked(userId);
+            final long timeNow = checkAndGetTimeLocked();
+            convertToSystemTimeLocked(event);
+
+            final UserUsageStatsService service =
+                    getUserDataAndInitializeIfNeededLocked(userId, timeNow);
             service.reportEvent(event);
         }
     }
@@ -225,12 +259,14 @@ public class UsageStatsService extends SystemService implements
      * Called by the Binder stub.
      */
     List<UsageStats> queryUsageStats(int userId, int bucketType, long beginTime, long endTime) {
-        if (!validRange(beginTime, endTime)) {
-            return null;
-        }
-
         synchronized (mLock) {
-            UserUsageStatsService service = getUserDataAndInitializeIfNeededLocked(userId);
+            final long timeNow = checkAndGetTimeLocked();
+            if (!validRange(timeNow, beginTime, endTime)) {
+                return null;
+            }
+
+            final UserUsageStatsService service =
+                    getUserDataAndInitializeIfNeededLocked(userId, timeNow);
             return service.queryUsageStats(bucketType, beginTime, endTime);
         }
     }
@@ -240,12 +276,14 @@ public class UsageStatsService extends SystemService implements
      */
     List<ConfigurationStats> queryConfigurationStats(int userId, int bucketType, long beginTime,
             long endTime) {
-        if (!validRange(beginTime, endTime)) {
-            return null;
-        }
-
         synchronized (mLock) {
-            UserUsageStatsService service = getUserDataAndInitializeIfNeededLocked(userId);
+            final long timeNow = checkAndGetTimeLocked();
+            if (!validRange(timeNow, beginTime, endTime)) {
+                return null;
+            }
+
+            final UserUsageStatsService service =
+                    getUserDataAndInitializeIfNeededLocked(userId, timeNow);
             return service.queryConfigurationStats(bucketType, beginTime, endTime);
         }
     }
@@ -254,19 +292,20 @@ public class UsageStatsService extends SystemService implements
      * Called by the Binder stub.
      */
     UsageEvents queryEvents(int userId, long beginTime, long endTime) {
-        if (!validRange(beginTime, endTime)) {
-            return null;
-        }
-
         synchronized (mLock) {
-            UserUsageStatsService service = getUserDataAndInitializeIfNeededLocked(userId);
+            final long timeNow = checkAndGetTimeLocked();
+            if (!validRange(timeNow, beginTime, endTime)) {
+                return null;
+            }
+
+            final UserUsageStatsService service =
+                    getUserDataAndInitializeIfNeededLocked(userId, timeNow);
             return service.queryEvents(beginTime, endTime);
         }
     }
 
-    private static boolean validRange(long beginTime, long endTime) {
-        final long timeNow = System.currentTimeMillis();
-        return beginTime <= timeNow && beginTime < endTime;
+    private static boolean validRange(long currentTime, long beginTime, long endTime) {
+        return beginTime <= currentTime && beginTime < endTime;
     }
 
     private void flushToDiskLocked() {
@@ -386,14 +425,6 @@ public class UsageStatsService extends SystemService implements
      */
     private class LocalService extends UsageStatsManagerInternal {
 
-        /**
-         * The system may have its time change, so at least make sure the events
-         * are monotonic in order.
-         */
-        private long computeMonotonicSystemTime(long realTime) {
-            return (realTime - mRealTimeSnapshot) + mSystemTimeSnapshot;
-        }
-
         @Override
         public void reportEvent(ComponentName component, int userId, int eventType) {
             if (component == null) {
@@ -404,7 +435,10 @@ public class UsageStatsService extends SystemService implements
             UsageEvents.Event event = new UsageEvents.Event();
             event.mPackage = component.getPackageName();
             event.mClass = component.getClassName();
-            event.mTimeStamp = computeMonotonicSystemTime(SystemClock.elapsedRealtime());
+
+            // This will later be converted to system time.
+            event.mTimeStamp = SystemClock.elapsedRealtime();
+
             event.mEventType = eventType;
             mHandler.obtainMessage(MSG_REPORT_EVENT, userId, 0, event).sendToTarget();
         }
@@ -418,7 +452,10 @@ public class UsageStatsService extends SystemService implements
 
             UsageEvents.Event event = new UsageEvents.Event();
             event.mPackage = "android";
-            event.mTimeStamp = computeMonotonicSystemTime(SystemClock.elapsedRealtime());
+
+            // This will later be converted to system time.
+            event.mTimeStamp = SystemClock.elapsedRealtime();
+
             event.mEventType = UsageEvents.Event.CONFIGURATION_CHANGE;
             event.mConfiguration = new Configuration(config);
             mHandler.obtainMessage(MSG_REPORT_EVENT, userId, 0, event).sendToTarget();
diff --git a/services/usage/java/com/android/server/usage/UserUsageStatsService.java b/services/usage/java/com/android/server/usage/UserUsageStatsService.java
index 2769666..4916ec2 100644
--- a/services/usage/java/com/android/server/usage/UserUsageStatsService.java
+++ b/services/usage/java/com/android/server/usage/UserUsageStatsService.java
@@ -22,6 +22,7 @@ import android.app.usage.UsageEvents;
 import android.app.usage.UsageStats;
 import android.app.usage.UsageStatsManager;
 import android.content.res.Configuration;
+import android.os.SystemClock;
 import android.util.ArraySet;
 import android.util.Slog;
 
@@ -62,10 +63,9 @@ class UserUsageStatsService {
         mLogPrefix = "User[" + Integer.toString(userId) + "] ";
     }
 
-    void init() {
-        mDatabase.init();
+    void init(final long currentTimeMillis) {
+        mDatabase.init(currentTimeMillis);
 
-        final long timeNow = System.currentTimeMillis();
         int nullCount = 0;
         for (int i = 0; i < mCurrentStats.length; i++) {
             mCurrentStats[i] = mDatabase.getLatestUsageStats(i);
@@ -73,11 +73,6 @@ class UserUsageStatsService {
                 // Find out how many intervals we don't have data for.
                 // Ideally it should be all or none.
                 nullCount++;
-            } else if (mCurrentStats[i].beginTime > timeNow) {
-                Slog.e(TAG, mLogPrefix + "Interval " + i + " has stat in the future " +
-                        mCurrentStats[i].beginTime);
-                mCurrentStats[i] = null;
-                nullCount++;
             }
         }
 
@@ -92,7 +87,7 @@ class UserUsageStatsService {
 
             // By calling loadActiveStats, we will
             // generate new stats for each bucket.
-            loadActiveStats();
+            loadActiveStats(currentTimeMillis, false);
         } else {
             // Set up the expiry date to be one day from the latest daily stat.
             // This may actually be today and we will rollover on the first event
@@ -123,6 +118,12 @@ class UserUsageStatsService {
         }
     }
 
+    void onTimeChanged(long oldTime, long newTime) {
+        persistActiveStats();
+        mDatabase.onTimeChanged(newTime - oldTime);
+        loadActiveStats(newTime, true);
+    }
+
     void reportEvent(UsageEvents.Event event) {
         if (DEBUG) {
             Slog.d(TAG, mLogPrefix + "Got usage event for " + event.mPackage
@@ -132,7 +133,7 @@ class UserUsageStatsService {
 
         if (event.mTimeStamp >= mDailyExpiryDate.getTimeInMillis()) {
             // Need to rollover
-            rolloverStats();
+            rolloverStats(event.mTimeStamp);
         }
 
         final IntervalStats currentDailyStats = mCurrentStats[UsageStatsManager.INTERVAL_DAILY];
@@ -330,8 +331,8 @@ class UserUsageStatsService {
         }
     }
 
-    private void rolloverStats() {
-        final long startTime = System.currentTimeMillis();
+    private void rolloverStats(final long currentTimeMillis) {
+        final long startTime = SystemClock.elapsedRealtime();
         Slog.i(TAG, mLogPrefix + "Rolling over usage stats");
 
         // Finish any ongoing events with an END_OF_DAY event. Make a note of which components
@@ -348,7 +349,7 @@ class UserUsageStatsService {
                     continuePreviousDay.add(pkgStats.mPackageName);
                     stat.update(pkgStats.mPackageName, mDailyExpiryDate.getTimeInMillis() - 1,
                             UsageEvents.Event.END_OF_DAY);
-                    mStatsChanged = true;
+                    notifyStatsChanged();
                 }
             }
 
@@ -356,8 +357,8 @@ class UserUsageStatsService {
         }
 
         persistActiveStats();
-        mDatabase.prune();
-        loadActiveStats();
+        mDatabase.prune(currentTimeMillis);
+        loadActiveStats(currentTimeMillis, false);
 
         final int continueCount = continuePreviousDay.size();
         for (int i = 0; i < continueCount; i++) {
@@ -366,12 +367,12 @@ class UserUsageStatsService {
             for (IntervalStats stat : mCurrentStats) {
                 stat.update(name, beginTime, UsageEvents.Event.CONTINUE_PREVIOUS_DAY);
                 stat.updateConfigurationStats(previousConfig, beginTime);
-                mStatsChanged = true;
+                notifyStatsChanged();
             }
         }
         persistActiveStats();
 
-        final long totalTime = System.currentTimeMillis() - startTime;
+        final long totalTime = SystemClock.elapsedRealtime() - startTime;
         Slog.i(TAG, mLogPrefix + "Rolling over usage stats complete. Took " + totalTime
                 + " milliseconds");
     }
@@ -383,15 +384,16 @@ class UserUsageStatsService {
         }
     }
 
-    private void loadActiveStats() {
-        final long timeNow = System.currentTimeMillis();
-
+    /**
+     * @param force To force all in-memory stats to be reloaded.
+     */
+    private void loadActiveStats(final long currentTimeMillis, boolean force) {
         final UnixCalendar tempCal = mDailyExpiryDate;
         for (int intervalType = 0; intervalType < mCurrentStats.length; intervalType++) {
-            tempCal.setTimeInMillis(timeNow);
+            tempCal.setTimeInMillis(currentTimeMillis);
             UnixCalendar.truncateTo(tempCal, intervalType);
 
-            if (mCurrentStats[intervalType] != null &&
+            if (!force && mCurrentStats[intervalType] != null &&
                     mCurrentStats[intervalType].beginTime == tempCal.getTimeInMillis()) {
                 // These are the same, no need to load them (in memory stats are always newer
                 // than persisted stats).
@@ -399,11 +401,7 @@ class UserUsageStatsService {
             }
 
             final long lastBeginTime = mDatabase.getLatestUsageStatsBeginTime(intervalType);
-            if (lastBeginTime > timeNow) {
-                Slog.e(TAG, mLogPrefix + "Latest usage stats for interval " +
-                        intervalType + " begins in the future");
-                mCurrentStats[intervalType] = null;
-            } else if (lastBeginTime >= tempCal.getTimeInMillis()) {
+            if (lastBeginTime >= tempCal.getTimeInMillis()) {
                 if (DEBUG) {
                     Slog.d(TAG, mLogPrefix + "Loading existing stats @ " +
                             sDateFormat.format(lastBeginTime) + "(" + lastBeginTime +
@@ -423,11 +421,11 @@ class UserUsageStatsService {
                 }
                 mCurrentStats[intervalType] = new IntervalStats();
                 mCurrentStats[intervalType].beginTime = tempCal.getTimeInMillis();
-                mCurrentStats[intervalType].endTime = timeNow;
+                mCurrentStats[intervalType].endTime = currentTimeMillis;
             }
         }
         mStatsChanged = false;
-        mDailyExpiryDate.setTimeInMillis(timeNow);
+        mDailyExpiryDate.setTimeInMillis(currentTimeMillis);
         mDailyExpiryDate.addDays(1);
         mDailyExpiryDate.truncateToDay();
         Slog.i(TAG, mLogPrefix + "Rollover scheduled @ " +
diff --git a/tests/UsageStatsTest/src/com/android/tests/usagestats/UsageLogActivity.java b/tests/UsageStatsTest/src/com/android/tests/usagestats/UsageLogActivity.java
index 31e7c38..d9a3b61 100644
--- a/tests/UsageStatsTest/src/com/android/tests/usagestats/UsageLogActivity.java
+++ b/tests/UsageStatsTest/src/com/android/tests/usagestats/UsageLogActivity.java
@@ -86,7 +86,10 @@ public class UsageLogActivity extends ListActivity implements Runnable {
                 }
                 mEvents.addFirst(event);
             }
-            notifyDataSetChanged();
+
+            if (lastTimeStamp != 0) {
+                notifyDataSetChanged();
+            }
             return lastTimeStamp;
         }