Merge "Tune some value of reporting and shards more" into oc-dev

8 files changed, 110 insertions, 44 deletions

diff --git a/src/com/android/tradefed/invoker/ShardMasterResultForwarder.java b/src/com/android/tradefed/invoker/ShardMasterResultForwarder.java
index 15ab8bd6a..b18d439a7 100644
--- a/src/com/android/tradefed/invoker/ShardMasterResultForwarder.java
+++ b/src/com/android/tradefed/invoker/ShardMasterResultForwarder.java
@@ -15,10 +15,12 @@
  */
 package com.android.tradefed.invoker;
 
+import com.android.tradefed.log.LogUtil.CLog;
 import com.android.tradefed.result.ILogSaver;
 import com.android.tradefed.result.ITestInvocationListener;
 import com.android.tradefed.result.LogSaverResultForwarder;
 import com.android.tradefed.result.ResultForwarder;
+import com.android.tradefed.util.TimeUtil;
 
 import java.util.List;
 
@@ -31,10 +33,13 @@ import java.util.List;
  */
 public class ShardMasterResultForwarder extends LogSaverResultForwarder {
 
+    private final int mInitCount;
     private int mShardsRemaining;
     private int mTotalElapsed = 0;
     private boolean mStartReported = false;
 
+    private long mFirstShardEndTime = 0l;
+
     /**
      * Create a {@link ShardMasterResultForwarder}.
      *
@@ -46,6 +51,7 @@ public class ShardMasterResultForwarder extends LogSaverResultForwarder {
             List<ITestInvocationListener> listeners, int expectedShards) {
         super(logSaver, listeners);
         mShardsRemaining = expectedShards;
+        mInitCount = expectedShards;
     }
 
     /**
@@ -75,8 +81,15 @@ public class ShardMasterResultForwarder extends LogSaverResultForwarder {
     @Override
     public void invocationEnded(long elapsedTime) {
         mTotalElapsed += elapsedTime;
+        if (mInitCount == mShardsRemaining) {
+            mFirstShardEndTime = System.currentTimeMillis();
+        }
         mShardsRemaining--;
         if (mShardsRemaining <= 0) {
+            // TODO: consider logging all shard final times.
+            CLog.i(
+                    "There was %s between the first and last shard ended.",
+                    TimeUtil.formatElapsedTime(System.currentTimeMillis() - mFirstShardEndTime));
             super.invocationEnded(mTotalElapsed);
         }
     }
diff --git a/src/com/android/tradefed/result/suite/SuiteResultReporter.java b/src/com/android/tradefed/result/suite/SuiteResultReporter.java
index 8fb467326..a2365649d 100644
--- a/src/com/android/tradefed/result/suite/SuiteResultReporter.java
+++ b/src/com/android/tradefed/result/suite/SuiteResultReporter.java
@@ -21,6 +21,7 @@ import com.android.ddmlib.testrunner.TestRunResult;
 import com.android.tradefed.invoker.IInvocationContext;
 import com.android.tradefed.log.LogUtil.CLog;
 import com.android.tradefed.result.CollectingTestListener;
+import com.android.tradefed.testtype.suite.ITestSuite;
 import com.android.tradefed.testtype.suite.ModuleDefinition;
 import com.android.tradefed.util.TimeUtil;
 
@@ -75,6 +76,19 @@ public class SuiteResultReporter extends CollectingTestListener {
         }
     }
 
+    /** Helper to remove the module checker results from the final list of real module results. */
+    private List<TestRunResult> extractModuleCheckers(Collection<TestRunResult> results) {
+        List<TestRunResult> moduleCheckers = new ArrayList<TestRunResult>();
+        for (TestRunResult t : results) {
+            if (t.getName().startsWith(ITestSuite.MODULE_CHECKER_POST)
+                    || t.getName().startsWith(ITestSuite.MODULE_CHECKER_PRE)) {
+                moduleCheckers.add(t);
+            }
+        }
+        results.removeAll(moduleCheckers);
+        return moduleCheckers;
+    }
+
     @Override
     public void invocationEnded(long elapsedTime) {
         super.invocationEnded(elapsedTime);
@@ -82,6 +96,7 @@ public class SuiteResultReporter extends CollectingTestListener {
 
         // finalize and print results - general
         Collection<TestRunResult> results = getRunResults();
+        List<TestRunResult> moduleCheckers = extractModuleCheckers(results);
 
         mTotalModules = results.size();
 
@@ -109,9 +124,10 @@ public class SuiteResultReporter extends CollectingTestListener {
         // print a short report summary
         CLog.logAndDisplay(LogLevel.INFO, "============================================");
         CLog.logAndDisplay(LogLevel.INFO, "================= Results ==================");
-        printTop10TimeConsumer(results);
-        printTop10SlowModules(results);
+        printModuleTestTime(results);
+        printTopSlowModules(results);
         printPreparationMetrics(mPreparationMap);
+        printModuleCheckersMetric(moduleCheckers);
         CLog.logAndDisplay(LogLevel.INFO, "=============== Summary ===============");
         CLog.logAndDisplay(
                 LogLevel.INFO, "Total Run time: %s", TimeUtil.formatElapsedTime(mElapsedTime));
@@ -144,8 +160,8 @@ public class SuiteResultReporter extends CollectingTestListener {
         CLog.logAndDisplay(LogLevel.INFO, "============================================");
     }
 
-    /** Displays the top 10 time consumer for module tests run. */
-    void printTop10TimeConsumer(Collection<TestRunResult> results) {
+    /** Displays the time consumed by each module to run. */
+    private void printModuleTestTime(Collection<TestRunResult> results) {
         List<TestRunResult> moduleTime = new ArrayList<>();
         moduleTime.addAll(results);
         Collections.sort(
@@ -156,18 +172,20 @@ public class SuiteResultReporter extends CollectingTestListener {
                         return (int) (o2.getElapsedTime() - o1.getElapsedTime());
                     }
                 });
-        int maxModuleDisplay = Math.min(moduleTime.size(), 10);
-        CLog.logAndDisplay(
-                LogLevel.INFO,
-                "============== TOP %s Test Consumer ==============",
-                maxModuleDisplay);
-        for (int i = 0; i < maxModuleDisplay; i++) {
+        long totalRunTime = 0l;
+        CLog.logAndDisplay(LogLevel.INFO, "=============== Consumed Time ==============");
+        for (int i = 0; i < moduleTime.size(); i++) {
             CLog.logAndDisplay(
                     LogLevel.INFO,
                     "    %s: %s",
                     moduleTime.get(i).getName(),
                     TimeUtil.formatElapsedTime(moduleTime.get(i).getElapsedTime()));
+            totalRunTime += moduleTime.get(i).getElapsedTime();
         }
+        CLog.logAndDisplay(
+                LogLevel.INFO,
+                "Total aggregated tests run time: %s",
+                TimeUtil.formatElapsedTime(totalRunTime));
     }
 
     /**
@@ -175,7 +193,7 @@ public class SuiteResultReporter extends CollectingTestListener {
      * modules have way more test cases than others so only looking at elapsed time is not a good
      * metric for slow modules).
      */
-    void printTop10SlowModules(Collection<TestRunResult> results) {
+    private void printTopSlowModules(Collection<TestRunResult> results) {
         List<TestRunResult> moduleTime = new ArrayList<>();
         moduleTime.addAll(results);
         // We don't consider module which runs in less than 5 sec.
@@ -194,7 +212,7 @@ public class SuiteResultReporter extends CollectingTestListener {
                         return rate1.compareTo(rate2);
                     }
                 });
-        int maxModuleDisplay = Math.min(moduleTime.size(), 10);
+        int maxModuleDisplay = moduleTime.size();
         if (maxModuleDisplay == 0) {
             return;
         }
@@ -223,9 +241,32 @@ public class SuiteResultReporter extends CollectingTestListener {
             return;
         }
         CLog.d("============== Modules Preparation Times ==============");
+        long totalPrep = 0l;
+        long totalTear = 0l;
+
         for (String moduleName : metrics.keySet()) {
             CLog.d("    %s => %s", moduleName, metrics.get(moduleName).toString());
+            totalPrep += metrics.get(moduleName).mPrepTime;
+            totalTear += metrics.get(moduleName).mTearDownTime;
+        }
+        CLog.d(
+                "Total preparation time: %s  ||  Total tear down time: %s",
+                TimeUtil.formatElapsedTime(totalPrep), TimeUtil.formatElapsedTime(totalTear));
+        CLog.d("=======================================================");
+    }
+
+    private void printModuleCheckersMetric(List<TestRunResult> moduleCheckerResults) {
+        if (moduleCheckerResults.isEmpty()) {
+            return;
+        }
+        CLog.d("============== Modules Checkers Times ==============");
+        long totalTime = 0l;
+        for (TestRunResult t : moduleCheckerResults) {
+            CLog.d("    %s: %s", t.getName(), TimeUtil.formatElapsedTime(t.getElapsedTime()));
+            totalTime += t.getElapsedTime();
         }
+        CLog.d("Total module checkers time: %s", TimeUtil.formatElapsedTime(totalTime));
+        CLog.d("====================================================");
     }
 
     public int getTotalModules() {
diff --git a/src/com/android/tradefed/testtype/suite/ITestSuite.java b/src/com/android/tradefed/testtype/suite/ITestSuite.java
index 2d12d1504..6fc8a1576 100644
--- a/src/com/android/tradefed/testtype/suite/ITestSuite.java
+++ b/src/com/android/tradefed/testtype/suite/ITestSuite.java
@@ -16,11 +16,11 @@
 package com.android.tradefed.testtype.suite;
 
 import com.android.ddmlib.Log.LogLevel;
-import com.android.ddmlib.testrunner.TestIdentifier;
 import com.android.tradefed.build.IBuildInfo;
 import com.android.tradefed.config.ConfigurationException;
 import com.android.tradefed.config.IConfiguration;
 import com.android.tradefed.config.Option;
+import com.android.tradefed.config.OptionCopier;
 import com.android.tradefed.device.DeviceNotAvailableException;
 import com.android.tradefed.device.ITestDevice;
 import com.android.tradefed.log.LogUtil.CLog;
@@ -54,8 +54,8 @@ public abstract class ITestSuite
                 IShardableTest,
                 ITestCollector {
 
-    protected static final String MODULE_CHECKER_PRE = "PreModuleChecker";
-    protected static final String MODULE_CHECKER_POST = "PostModuleChecker";
+    public static final String MODULE_CHECKER_PRE = "PreModuleChecker";
+    public static final String MODULE_CHECKER_POST = "PostModuleChecker";
 
     // Options for test failure case
     @Option(
@@ -342,14 +342,11 @@ public abstract class ITestSuite
             // do not log here, otherwise it could be very verbose.
             return;
         }
-        TestIdentifier tid = new TestIdentifier(identifier, moduleName);
-        listener.testRunStarted(identifier + "_" + moduleName, 1);
-        listener.testStarted(tid);
+        // Avoid messing with the final test count by making them empty runs.
+        listener.testRunStarted(identifier + "_" + moduleName, 0);
         if (!failures.isEmpty()) {
-            listener.testFailed(
-                    tid, String.format("%s failed '%s' checkers", moduleName, failures));
+            listener.testRunFailed(String.format("%s failed '%s' checkers", moduleName, failures));
         }
-        listener.testEnded(tid, Collections.emptyMap());
         listener.testRunEnded(System.currentTimeMillis() - startTime, Collections.emptyMap());
     }
 
@@ -368,6 +365,8 @@ public abstract class ITestSuite
         }
         injectInfo(runConfig);
 
+        // We split individual tests on double the shardCountHint to provide better average.
+        // The test pool mechanism prevent this from creating too much overhead.
         List<ModuleDefinition> splitModules =
                 ModuleSplitter.splitConfiguration(
                         runConfig, shardCountHint, mShouldMakeDynamicModule);
@@ -378,6 +377,7 @@ public abstract class ITestSuite
         List<IRemoteTest> splitTests = new ArrayList<>();
         for (ModuleDefinition m : splitModules) {
             ITestSuite suite = createInstance();
+            OptionCopier.copyOptionsNoThrow(this, suite);
             suite.mIsSharded = true;
             suite.mDirectModule = m;
             splitTests.add(suite);
diff --git a/src/com/android/tradefed/testtype/suite/ModuleDefinition.java b/src/com/android/tradefed/testtype/suite/ModuleDefinition.java
index 70ed45d45..a1d42898e 100644
--- a/src/com/android/tradefed/testtype/suite/ModuleDefinition.java
+++ b/src/com/android/tradefed/testtype/suite/ModuleDefinition.java
@@ -74,8 +74,11 @@ public class ModuleDefinition implements Comparable<ModuleDefinition>, ITestColl
     private long mElapsedPreparation = 0l;
     private long mElapsedTearDown = 0l;
 
+    private long mElapsedTest = 0l;
+
     public static final String PREPARATION_TIME = "PREP_TIME";
     public static final String TEAR_DOWN_TIME = "TEARDOWN_TIME";
+    public static final String TEST_TIME = "TEST_TIME";
 
     /**
      * Constructor
@@ -196,9 +199,12 @@ public class ModuleDefinition implements Comparable<ModuleDefinition>, ITestColl
                 listener.testFailed(testid, sw.toString());
                 listener.testEnded(testid, Collections.emptyMap());
                 listener.testRunFailed(sw.toString());
-                listener.testRunEnded(0, Collections.emptyMap());
+                Map<String, String> metrics = new HashMap<>();
+                metrics.put(TEST_TIME, "0");
+                listener.testRunEnded(0, metrics);
                 return;
             }
+            mElapsedTest = getCurrentTime();
             while (true) {
                 IRemoteTest test = poll();
                 if (test == null) {
@@ -228,7 +234,6 @@ public class ModuleDefinition implements Comparable<ModuleDefinition>, ITestColl
                     currentTestListener.add(failureListener);
                 }
                 currentTestListener.add(moduleListener);
-
                 try {
                     test.run(new ResultForwarder(currentTestListener));
                 } catch (RuntimeException re) {
@@ -291,7 +296,7 @@ public class ModuleDefinition implements Comparable<ModuleDefinition>, ITestColl
         // put metrics from the preparation
         metrics.put(PREPARATION_TIME, Long.toString(mElapsedPreparation));
         metrics.put(TEAR_DOWN_TIME, Long.toString(mElapsedTearDown));
-
+        metrics.put(TEST_TIME, Long.toString(elapsedTime));
         if (totalExpectedTests != numResults) {
             String error =
                     String.format(
@@ -301,7 +306,7 @@ public class ModuleDefinition implements Comparable<ModuleDefinition>, ITestColl
             CLog.e(error);
             mIsFailedModule = true;
         }
-        listener.testRunEnded(elapsedTime, metrics);
+        listener.testRunEnded(getCurrentTime() - mElapsedTest, metrics);
     }
 
     private void forwardTestResults(
diff --git a/src/com/android/tradefed/testtype/suite/ModuleListener.java b/src/com/android/tradefed/testtype/suite/ModuleListener.java
index 71c8dabee..c3ae9342a 100644
--- a/src/com/android/tradefed/testtype/suite/ModuleListener.java
+++ b/src/com/android/tradefed/testtype/suite/ModuleListener.java
@@ -37,6 +37,7 @@ public class ModuleListener extends CollectingTestListener {
     /** Constructor. Accept the original listener to forward testLog callback. */
     public ModuleListener(ITestInvocationListener listener) {
         mListener = listener;
+        setIsAggregrateMetrics(true);
     }
 
     /** {@inheritDoc} */
diff --git a/src/com/android/tradefed/testtype/suite/ModuleSplitter.java b/src/com/android/tradefed/testtype/suite/ModuleSplitter.java
index 8c00b07f9..eb04cff84 100644
--- a/src/com/android/tradefed/testtype/suite/ModuleSplitter.java
+++ b/src/com/android/tradefed/testtype/suite/ModuleSplitter.java
@@ -62,6 +62,11 @@ public class ModuleSplitter {
             LinkedHashMap<String, IConfiguration> runConfig,
             int shardCount,
             boolean dynamicModule) {
+        if (dynamicModule) {
+            // We maximize the sharding for dynamic to reduce time difference between first and
+            // last shard as much as possible. Overhead is low due to our test pooling.
+            shardCount *= 2;
+        }
         List<ModuleDefinition> runModules = new ArrayList<>();
         for (Entry<String, IConfiguration> configMap : runConfig.entrySet()) {
             validateConfig(configMap.getValue());
@@ -82,12 +87,19 @@ public class ModuleSplitter {
             int shardCount,
             boolean dynamicModule) {
         // If this particular configuration module is declared as 'not shardable' we take it whole
-        // no need to clone target_preparers.
+        // but still split the individual IRemoteTest in a pool.
         if (config.getConfigurationDescription().isNotShardable()) {
-            ModuleDefinition module =
-                    new ModuleDefinition(
-                            moduleName, config.getTests(), config.getTargetPreparers());
-            currentList.add(module);
+            for (int i = 0; i < config.getTests().size(); i++) {
+                if (dynamicModule) {
+                    ModuleDefinition module =
+                            new ModuleDefinition(
+                                    moduleName, config.getTests(), clonePreparers(config));
+                    currentList.add(module);
+                } else {
+                    addModuleToListFromSingleTest(
+                            currentList, config.getTests().get(i), moduleName, config);
+                }
+            }
             return;
         }
 
diff --git a/tests/src/com/android/tradefed/testtype/suite/ITestSuiteTest.java b/tests/src/com/android/tradefed/testtype/suite/ITestSuiteTest.java
index 73238876d..9460d2145 100644
--- a/tests/src/com/android/tradefed/testtype/suite/ITestSuiteTest.java
+++ b/tests/src/com/android/tradefed/testtype/suite/ITestSuiteTest.java
@@ -234,17 +234,11 @@ public class ITestSuiteTest {
                 .andReturn(false);
         expectTestRun(mMockListener);
 
-        mMockListener.testRunStarted(ITestSuite.MODULE_CHECKER_PRE + "_test", 1);
-        TestIdentifier tidPre = new TestIdentifier(ITestSuite.MODULE_CHECKER_PRE, "test");
-        mMockListener.testStarted(tidPre);
-        mMockListener.testEnded(tidPre, Collections.emptyMap());
+        mMockListener.testRunStarted(ITestSuite.MODULE_CHECKER_PRE + "_test", 0);
         mMockListener.testRunEnded(EasyMock.anyLong(), EasyMock.anyObject());
 
-        mMockListener.testRunStarted(ITestSuite.MODULE_CHECKER_POST + "_test", 1);
-        TestIdentifier tid = new TestIdentifier(ITestSuite.MODULE_CHECKER_POST, "test");
-        mMockListener.testStarted(tid);
-        mMockListener.testFailed(EasyMock.eq(tid), EasyMock.anyObject());
-        mMockListener.testEnded(tid, Collections.emptyMap());
+        mMockListener.testRunStarted(ITestSuite.MODULE_CHECKER_POST + "_test", 0);
+        mMockListener.testRunFailed(EasyMock.anyObject());
         mMockListener.testRunEnded(EasyMock.anyLong(), EasyMock.anyObject());
 
         replayMocks();
diff --git a/tests/src/com/android/tradefed/testtype/suite/ModuleSplitterTest.java b/tests/src/com/android/tradefed/testtype/suite/ModuleSplitterTest.java
index 479693d3a..6b724985f 100644
--- a/tests/src/com/android/tradefed/testtype/suite/ModuleSplitterTest.java
+++ b/tests/src/com/android/tradefed/testtype/suite/ModuleSplitterTest.java
@@ -57,9 +57,9 @@ public class ModuleSplitterTest {
         List<ModuleDefinition> res = ModuleSplitter.splitConfiguration(runConfig, 5, true);
         // matching 1 for 1, config to ModuleDefinition since not shardable
         assertEquals(1, res.size());
-        // The original target preparer is still there
-        assertSame(config.getTargetPreparers().get(0), res.get(0).getTargetPreparers().get(0));
-        // The original IRemoteTest is still there
+        // The original target preparer is changed since we split multiple <test> tags.
+        assertNotSame(config.getTargetPreparers().get(0), res.get(0).getTargetPreparers().get(0));
+        // The original IRemoteTest is still there because we use a pool.
         assertSame(config.getTests().get(0), res.get(0).getTests().get(0));
     }
 
@@ -139,8 +139,8 @@ public class ModuleSplitterTest {
 
         runConfig.put("module1", config);
         List<ModuleDefinition> res = ModuleSplitter.splitConfiguration(runConfig, 5, true);
-        // matching 1 for 5 since tests sharding in 5 units.
-        assertEquals(5, res.size());
+        // matching 1 for 10 since tests sharding in 5 units times 2.
+        assertEquals(10, res.size());
         // The original IRemoteTest does not exists anymore, new IRemoteTests have been created.
         for (ModuleDefinition m : res) {
             assertNotSame(config.getTests().get(0), m.getTests().get(0));