Merge "Capture the real invocation start time of subprocess" into oc-dev

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);