ResearchLog. Track time of log statements

Log statements are now recorded with a timestamp.  This is important for filtering out statements
not part of words that are sampled when spaces are inserted automatically.

multi-project commit with Change-Id: I68221a2528045d25632aef4bb716f92a4f4a56a4

Change-Id: I9f49c36391e1e1773b6d4876d7387c893024f87b

java/src/com/android/inputmethod/research/LogUnit.java

@@ -18,7 +18,7 @@ package com.android.inputmethod.research;
 
 import com.android.inputmethod.latin.CollectionUtils;
 
-import java.util.ArrayList;
+import java.util.List;
 
 /**
  * A group of log statements related to each other.
@@ -35,16 +35,39 @@ import java.util.ArrayList;
  * been published recently, or whether the LogUnit contains numbers, etc.
  */
 /* package */ class LogUnit {
-    private final ArrayList<String[]> mKeysList = CollectionUtils.newArrayList();
+    private final List<String[]> mKeysList;
-    private final ArrayList<Object[]> mValuesList = CollectionUtils.newArrayList();
+    private final List<Object[]> mValuesList;
-    private final ArrayList<Boolean> mIsPotentiallyPrivate = CollectionUtils.newArrayList();
+    // Assume that mTimeList is sorted in increasing order.  Do not insert null values into
+    // mTimeList.
+    private final List<Long> mTimeList;
+    private final List<Boolean> mIsPotentiallyPrivate;
     private String mWord;
     private boolean mContainsDigit;
 
+    public LogUnit() {
+        mKeysList = CollectionUtils.newArrayList();
+        mValuesList = CollectionUtils.newArrayList();
+        mTimeList = CollectionUtils.newArrayList();
+        mIsPotentiallyPrivate = CollectionUtils.newArrayList();
+    }
+
+    private LogUnit(final List<String[]> keysList, final List<Object[]> valuesList,
+            final List<Long> timeList, final List<Boolean> isPotentiallyPrivate) {
+        mKeysList = keysList;
+        mValuesList = valuesList;
+        mTimeList = timeList;
+        mIsPotentiallyPrivate = isPotentiallyPrivate;
+    }
+
+    /**
+     * Adds a new log statement.  The time parameter in successive calls to this method must be
+     * monotonically increasing, or splitByTime() will not work.
+     */
     public void addLogStatement(final String[] keys, final Object[] values,
-            final Boolean isPotentiallyPrivate) {
+            final long time, final boolean isPotentiallyPrivate) {
         mKeysList.add(keys);
         mValuesList.add(values);
+        mTimeList.add(time);
         mIsPotentiallyPrivate.add(isPotentiallyPrivate);
     }
 
@@ -52,7 +75,7 @@ import java.util.ArrayList;
         final int size = mKeysList.size();
         for (int i = 0; i < size; i++) {
             if (!mIsPotentiallyPrivate.get(i) || isIncludingPrivateData) {
-                researchLog.outputEvent(mKeysList.get(i), mValuesList.get(i));
+                researchLog.outputEvent(mKeysList.get(i), mValuesList.get(i), mTimeList.get(i));
             }
         }
     }
@@ -80,4 +103,26 @@ import java.util.ArrayList;
     public boolean isEmpty() {
         return mKeysList.isEmpty();
     }
+
+    /**
+     * Split this logUnit, with all events before maxTime staying in the current logUnit, and all
+     * events after maxTime going into a new LogUnit that is returned.
+     */
+    public LogUnit splitByTime(final long maxTime) {
+        // Assume that mTimeList is in sorted order.
+        final int length = mTimeList.size();
+        for (int index = 0; index < length; index++) {
+            if (mTimeList.get(index) >= maxTime) {
+                final LogUnit newLogUnit = new LogUnit(
+                        mKeysList.subList(index, length),
+                        mValuesList.subList(index, length),
+                        mTimeList.subList(index, length),
+                        mIsPotentiallyPrivate.subList(index, length));
+                newLogUnit.mWord = null;
+                newLogUnit.mContainsDigit = mContainsDigit;
+                return newLogUnit;
+            }
+        }
+        return new LogUnit();
+    }
 }

java/src/com/android/inputmethod/research/ResearchLog.java

@@ -207,7 +207,7 @@ public class ResearchLog {
     private static final String UPTIME_KEY = "_ut";
     private static final String EVENT_TYPE_KEY = "_ty";
 
-    void outputEvent(final String[] keys, final Object[] values) {
+    void outputEvent(final String[] keys, final Object[] values, final long time) {
         // Not thread safe.
         if (keys.length == 0) {
             return;
@@ -225,7 +225,7 @@ public class ResearchLog {
             }
             mJsonWriter.beginObject();
             mJsonWriter.name(CURRENT_TIME_KEY).value(System.currentTimeMillis());
-            mJsonWriter.name(UPTIME_KEY).value(SystemClock.uptimeMillis());
+            mJsonWriter.name(UPTIME_KEY).value(time);
             mJsonWriter.name(EVENT_TYPE_KEY).value(keys[0]);
             final int length = values.length;
             for (int i = 0; i < length; i++) {

java/src/com/android/inputmethod/research/ResearchLogger.java

@@ -379,7 +379,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             Log.d(TAG, "stop called");
         }
         logStatistics();
-        commitCurrentLogUnit();
+        commitCurrentLogUnit(SystemClock.uptimeMillis());
 
         if (mMainLogBuffer != null) {
             publishLogBuffer(mMainLogBuffer, mMainResearchLog, false /* isIncludingPrivateData */);
@@ -547,7 +547,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             return;
         }
         if (includeHistory) {
-            commitCurrentLogUnit();
+            commitCurrentLogUnit(SystemClock.uptimeMillis());
         } else {
             mFeedbackLogBuffer.clear();
         }
@@ -556,7 +556,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             feedbackContents
         };
         feedbackLogUnit.addLogStatement(EVENTKEYS_FEEDBACK, values,
-                false /* isPotentiallyPrivate */);
+                SystemClock.uptimeMillis(), false /* isPotentiallyPrivate */);
         mFeedbackLogBuffer.shiftIn(feedbackLogUnit);
         publishLogBuffer(mFeedbackLogBuffer, mFeedbackLog, true /* isIncludingPrivateData */);
         mFeedbackLog.close(new Runnable() {
@@ -657,8 +657,9 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
     private synchronized void enqueuePotentiallyPrivateEvent(final String[] keys,
             final Object[] values) {
         assert values.length + 1 == keys.length;
+        final long time = SystemClock.uptimeMillis();
         if (isAllowedToLog()) {
-            mCurrentLogUnit.addLogStatement(keys, values, true /* isPotentiallyPrivate */);
+            mCurrentLogUnit.addLogStatement(keys, values, time, true /* isPotentiallyPrivate */);
         }
     }
 
@@ -680,16 +681,18 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
      */
     private synchronized void enqueueEvent(final String[] keys, final Object[] values) {
         assert values.length + 1 == keys.length;
+        final long time = SystemClock.uptimeMillis();
         if (isAllowedToLog()) {
-            mCurrentLogUnit.addLogStatement(keys, values, false /* isPotentiallyPrivate */);
+            mCurrentLogUnit.addLogStatement(keys, values, time, false /* isPotentiallyPrivate */);
         }
     }
 
-    /* package for test */ void commitCurrentLogUnit() {
+    /* package for test */ void commitCurrentLogUnit(final long maxTime) {
         if (DEBUG) {
             Log.d(TAG, "commitCurrentLogUnit");
         }
         if (!mCurrentLogUnit.isEmpty()) {
+            final LogUnit newLogUnit = mCurrentLogUnit.splitByTime(maxTime);
             if (mMainLogBuffer != null) {
                 mMainLogBuffer.shiftIn(mCurrentLogUnit);
                 if (mMainLogBuffer.isSafeToLog() && mMainResearchLog != null) {
@@ -701,7 +704,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             if (mFeedbackLogBuffer != null) {
                 mFeedbackLogBuffer.shiftIn(mCurrentLogUnit);
             }
-            mCurrentLogUnit = new LogUnit();
+            mCurrentLogUnit = newLogUnit;
             Log.d(TAG, "commitCurrentLogUnit");
         }
     }
@@ -719,7 +722,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             isIncludingPrivateData
         };
         openingLogUnit.addLogStatement(EVENTKEYS_LOG_SEGMENT_START, values,
-                false /* isPotentiallyPrivate */);
+                SystemClock.uptimeMillis(), false /* isPotentiallyPrivate */);
         researchLog.publish(openingLogUnit, true /* isIncludingPrivateData */);
         LogUnit logUnit;
         while ((logUnit = logBuffer.shiftOut()) != null) {
@@ -727,7 +730,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
         }
         final LogUnit closingLogUnit = new LogUnit();
         closingLogUnit.addLogStatement(EVENTKEYS_LOG_SEGMENT_END, EVENTKEYS_NULLVALUES,
-                false /* isPotentiallyPrivate */);
+                SystemClock.uptimeMillis(), false /* isPotentiallyPrivate */);
         researchLog.publish(closingLogUnit, true /* isIncludingPrivateData */);
     }
 
@@ -742,13 +745,13 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
         return false;
     }
 
-    private void onWordComplete(final String word) {
+    private void onWordComplete(final String word, final long maxTime) {
         Log.d(TAG, "onWordComplete: " + word);
         if (word != null && word.length() > 0 && hasLetters(word)) {
             mCurrentLogUnit.setWord(word);
             mStatistics.recordWordEntered();
         }
-        commitCurrentLogUnit();
+        commitCurrentLogUnit(maxTime);
     }
 
     private static int scrubDigitFromCodePoint(int codePoint) {
@@ -958,7 +961,7 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
             }
             final ResearchLogger researchLogger = getInstance();
             researchLogger.enqueueEvent(EVENTKEYS_LATINIME_ONWINDOWHIDDEN, values);
-            researchLogger.commitCurrentLogUnit();
+            researchLogger.commitCurrentLogUnit(SystemClock.uptimeMillis());
             getInstance().stop();
         }
     }
@@ -1205,7 +1208,8 @@ public class ResearchLogger implements SharedPreferences.OnSharedPreferenceChang
         final ResearchLogger researchLogger = getInstance();
         researchLogger.enqueuePotentiallyPrivateEvent(EVENTKEYS_RICHINPUTCONNECTION_COMMITTEXT,
                 values);
-        researchLogger.onWordComplete(scrubbedWord);
+        // TODO: Replace Long.MAX_VALUE with timestamp of last data to include
+        researchLogger.onWordComplete(scrubbedWord, Long.MAX_VALUE);
     }
 
     private static final String[] EVENTKEYS_RICHINPUTCONNECTION_DELETESURROUNDINGTEXT = {