Capture the real invocation start time of subprocess

There is some overhead to starting TF (listing devices,etc)
the first time so we do not count this toward our tests
execution metrics.

Test: unit tests
Bug: 62356171
Change-Id: I5ad410440e5fc344415bf9c10815194addb1d7cd

5 files changed, 69 insertions, 12 deletions

diff --git a/src/com/android/tradefed/result/SubprocessResultsReporter.java b/src/com/android/tradefed/result/SubprocessResultsReporter.java
index 38c81de12..a73cbb80a 100644
--- a/src/com/android/tradefed/result/SubprocessResultsReporter.java
+++ b/src/com/android/tradefed/result/SubprocessResultsReporter.java
@@ -24,6 +24,7 @@ import com.android.tradefed.util.StreamUtil;
 import com.android.tradefed.util.SubprocessEventHelper.BaseTestEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.FailedTestEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.InvocationFailedEventInfo;
+import com.android.tradefed.util.SubprocessEventHelper.InvocationStartedEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestEndedEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestLogEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestRunEndedEventInfo;
@@ -157,7 +158,9 @@ public class SubprocessResultsReporter implements ITestInvocationListener, AutoC
      */
     @Override
     public void invocationStarted(IInvocationContext context) {
-        printEvent(SubprocessTestResultsParser.StatusKeys.TEST_TAG, context.getTestTag());
+        InvocationStartedEventInfo info =
+                new InvocationStartedEventInfo(context.getTestTag(), System.currentTimeMillis());
+        printEvent(SubprocessTestResultsParser.StatusKeys.INVOCATION_STARTED, info);
     }
 
     /** {@inheritDoc} */
diff --git a/src/com/android/tradefed/testtype/SubprocessTfLauncher.java b/src/com/android/tradefed/testtype/SubprocessTfLauncher.java
index 2533619f2..51bad420a 100644
--- a/src/com/android/tradefed/testtype/SubprocessTfLauncher.java
+++ b/src/com/android/tradefed/testtype/SubprocessTfLauncher.java
@@ -250,6 +250,9 @@ public abstract class SubprocessTfLauncher
             startTime = System.currentTimeMillis();
             CommandResult result = mRunUtil.runTimedCmd(mMaxTfRunTime, stdout,
                     stderr, mCmdArgs.toArray(new String[0]));
+            if (eventParser.getStartTime() != null) {
+                startTime = eventParser.getStartTime();
+            }
             elapsedTime = System.currentTimeMillis() - startTime;
             // We possibly allow for a little more time if the thread is still processing events.
             if (!eventParser.joinReceiver(EVENT_THREAD_JOIN_TIMEOUT_MS)) {
diff --git a/src/com/android/tradefed/util/SubprocessEventHelper.java b/src/com/android/tradefed/util/SubprocessEventHelper.java
index ef38d0522..577477b72 100644
--- a/src/com/android/tradefed/util/SubprocessEventHelper.java
+++ b/src/com/android/tradefed/util/SubprocessEventHelper.java
@@ -47,6 +47,8 @@ public class SubprocessEventHelper {
     private static final String DATA_TYPE_KEY = "dataType";
     private static final String DATA_FILE_KEY = "dataFile";
 
+    private static final String TEST_TAG_KEY = "testTag";
+
     /**
      * Helper for testRunStarted information
      */
@@ -382,4 +384,39 @@ public class SubprocessEventHelper {
             return tags.toString();
         }
     }
+
+    /** Helper for invocation started information. */
+    public static class InvocationStartedEventInfo {
+        public String mTestTag = null;
+        public Long mStartTime = null;
+
+        public InvocationStartedEventInfo(String testTag, Long startTime) {
+            mTestTag = testTag;
+            mStartTime = startTime;
+        }
+
+        public InvocationStartedEventInfo(JSONObject jsonObject) throws JSONException {
+            mTestTag = jsonObject.getString(TEST_TAG_KEY);
+            if (jsonObject.has(START_TIME)) {
+                mStartTime = jsonObject.getLong(START_TIME);
+            }
+        }
+
+        @Override
+        public String toString() {
+            JSONObject tags = null;
+            try {
+                tags = new JSONObject();
+                if (mTestTag != null) {
+                    tags.put(TEST_TAG_KEY, mTestTag);
+                }
+                if (mStartTime != null) {
+                    tags.put(START_TIME, mStartTime);
+                }
+            } catch (JSONException e) {
+                CLog.e(e);
+            }
+            return tags.toString();
+        }
+    }
 }
diff --git a/src/com/android/tradefed/util/SubprocessTestResultsParser.java b/src/com/android/tradefed/util/SubprocessTestResultsParser.java
index 3e085a5a3..00d2abe0e 100644
--- a/src/com/android/tradefed/util/SubprocessTestResultsParser.java
+++ b/src/com/android/tradefed/util/SubprocessTestResultsParser.java
@@ -24,6 +24,7 @@ import com.android.tradefed.result.InputStreamSource;
 import com.android.tradefed.util.SubprocessEventHelper.BaseTestEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.FailedTestEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.InvocationFailedEventInfo;
+import com.android.tradefed.util.SubprocessEventHelper.InvocationStartedEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestEndedEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestLogEventInfo;
 import com.android.tradefed.util.SubprocessEventHelper.TestRunEndedEventInfo;
@@ -64,6 +65,7 @@ public class SubprocessTestResultsParser implements Closeable {
     private Map<String, EventHandler> mHandlerMap = null;
     private EventReceiverThread mEventReceiver = null;
     private IInvocationContext mContext = null;
+    private Long mStartTime = null;
 
     /** Relevant test status keys. */
     public static class StatusKeys {
@@ -77,7 +79,7 @@ public class SubprocessTestResultsParser implements Closeable {
         public static final String TEST_RUN_FAILED = "TEST_RUN_FAILED";
         public static final String TEST_RUN_STARTED = "TEST_RUN_STARTED";
         public static final String TEST_LOG = "TEST_LOG";
-        public static final String TEST_TAG = "TEST_TAG";
+        public static final String INVOCATION_STARTED = "INVOCATION_STARTED";
     }
 
     /**
@@ -209,7 +211,7 @@ public class SubprocessTestResultsParser implements Closeable {
         sb.append(StatusKeys.TEST_RUN_FAILED).append("|");
         sb.append(StatusKeys.TEST_RUN_STARTED).append("|");
         sb.append(StatusKeys.TEST_LOG).append("|");
-        sb.append(StatusKeys.TEST_TAG);
+        sb.append(StatusKeys.INVOCATION_STARTED);
         String patt = String.format("(.*)(%s)( )(.*)", sb.toString());
         mPattern = Pattern.compile(patt);
 
@@ -226,7 +228,7 @@ public class SubprocessTestResultsParser implements Closeable {
         mHandlerMap.put(StatusKeys.TEST_RUN_FAILED, new TestRunFailedEventHandler());
         mHandlerMap.put(StatusKeys.TEST_RUN_STARTED, new TestRunStartedEventHandler());
         mHandlerMap.put(StatusKeys.TEST_LOG, new TestLogEventHandler());
-        mHandlerMap.put(StatusKeys.TEST_TAG, new TestTagEventHandler());
+        mHandlerMap.put(StatusKeys.INVOCATION_STARTED, new InvocationStartedEventHandler());
     }
 
     public void parseFile(File file) {
@@ -404,15 +406,23 @@ public class SubprocessTestResultsParser implements Closeable {
         }
     }
 
-    /*
-     * The parent process should use the test tag of the subprocess if it's not set yet.
-     */
-    private class TestTagEventHandler implements EventHandler {
+    private class InvocationStartedEventHandler implements EventHandler {
         @Override
-        public void handleEvent(String testTag) {
+        public void handleEvent(String eventJson) throws JSONException {
+            InvocationStartedEventInfo eventStart =
+                    new InvocationStartedEventInfo(new JSONObject(eventJson));
             if (mContext.getTestTag() == null || "stub".equals(mContext.getTestTag())) {
-                mContext.setTestTag(testTag);
+                mContext.setTestTag(eventStart.mTestTag);
             }
+            mStartTime = eventStart.mStartTime;
         }
     }
+
+    /**
+     * Returns the start time associated with the invocation start event from the subprocess
+     * invocation.
+     */
+    public Long getStartTime() {
+        return mStartTime;
+    }
 }
diff --git a/tests/src/com/android/tradefed/util/SubprocessTestResultsParserTest.java b/tests/src/com/android/tradefed/util/SubprocessTestResultsParserTest.java
index c4c8d0f54..036ce2fc5 100644
--- a/tests/src/com/android/tradefed/util/SubprocessTestResultsParserTest.java
+++ b/tests/src/com/android/tradefed/util/SubprocessTestResultsParserTest.java
@@ -16,8 +16,8 @@
 package com.android.tradefed.util;
 
 import com.android.ddmlib.testrunner.TestIdentifier;
-import com.android.tradefed.log.LogUtil.CLog;
 import com.android.tradefed.invoker.InvocationContext;
+import com.android.tradefed.log.LogUtil.CLog;
 import com.android.tradefed.result.ITestInvocationListener;
 
 import junit.framework.TestCase;
@@ -335,11 +335,15 @@ public class SubprocessTestResultsParserTest extends TestCase {
         SubprocessTestResultsParser resultParser = null;
         try {
             resultParser = new SubprocessTestResultsParser(mockRunListener, false, context);
-            String testTagEvent = String.format("TEST_TAG %s", subTestTag);
+            String testTagEvent =
+                    String.format(
+                            "INVOCATION_STARTED {\"testTag\": \"%s\",\"start_time\":250}",
+                            subTestTag);
             FileUtil.writeToFile(testTagEvent, tmp, true);
             resultParser.parseFile(tmp);
             EasyMock.verify(mockRunListener);
             assertEquals(subTestTag, context.getTestTag());
+            assertEquals(250l, resultParser.getStartTime().longValue());
         } finally {
             StreamUtil.close(resultParser);
             FileUtil.deleteFile(tmp);