1 /* 2 * Copyright (C) 2017 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 package com.android.tradefed.result.suite; 17 18 import com.android.annotations.VisibleForTesting; 19 import com.android.ddmlib.Log.LogLevel; 20 import com.android.ddmlib.testrunner.TestResult.TestStatus; 21 import com.android.tradefed.invoker.IInvocationContext; 22 import com.android.tradefed.log.LogUtil.CLog; 23 import com.android.tradefed.result.CollectingTestListener; 24 import com.android.tradefed.result.TestRunResult; 25 import com.android.tradefed.result.TestSummary; 26 import com.android.tradefed.result.TestSummary.Type; 27 import com.android.tradefed.result.TestSummary.TypedString; 28 import com.android.tradefed.testtype.Abi; 29 import com.android.tradefed.testtype.IAbi; 30 import com.android.tradefed.testtype.suite.ITestSuite; 31 import com.android.tradefed.testtype.suite.ModuleDefinition; 32 import com.android.tradefed.util.AbiUtils; 33 import com.android.tradefed.util.TimeUtil; 34 35 import java.util.ArrayList; 36 import java.util.Collection; 37 import java.util.Collections; 38 import java.util.Comparator; 39 import java.util.HashMap; 40 import java.util.LinkedHashMap; 41 import java.util.List; 42 import java.util.Map; 43 import java.util.Map.Entry; 44 45 /** Collect test results for an entire suite invocation and output the final results. */ 46 public class SuiteResultReporter extends CollectingTestListener { 47 48 public static final String SUITE_REPORTER_SOURCE = SuiteResultReporter.class.getName(); 49 50 private long mStartTime = 0L; 51 private long mEndTime = 0L; 52 53 private int mTotalModules = 0; 54 private int mCompleteModules = 0; 55 56 private long mTotalTests = 0L; 57 private long mPassedTests = 0L; 58 private long mFailedTests = 0L; 59 private long mSkippedTests = 0L; 60 private long mAssumeFailureTests = 0L; 61 62 // Retry information 63 private long mTotalRetrySuccess = 0L; 64 private Map<String, Long> mModuleRetrySuccess = new LinkedHashMap<>(); 65 private long mTotalRetryFail = 0L; 66 private Map<String, Long> mModuleRetryFail = new LinkedHashMap<>(); 67 private long mTotalRetryTime = 0L; 68 private Map<String, Long> mModuleRetryTime = new LinkedHashMap<>(); 69 70 private Map<String, String> mFailedModule = new HashMap<>(); 71 // Map holding the preparation time for each Module. 72 private Map<String, ModulePrepTimes> mPreparationMap = new HashMap<>(); 73 74 private Map<String, IAbi> mModuleAbi = new LinkedHashMap<>(); 75 76 private StringBuilder mSummary; 77 SuiteResultReporter()78 public SuiteResultReporter() { 79 super(); 80 // force aggregate true to get full metrics. 81 setIsAggregrateMetrics(true); 82 mSummary = new StringBuilder(); 83 } 84 85 @Override invocationStarted(IInvocationContext context)86 public void invocationStarted(IInvocationContext context) { 87 super.invocationStarted(context); 88 mStartTime = getCurrentTime(); 89 } 90 91 @Override testModuleStarted(IInvocationContext moduleContext)92 public void testModuleStarted(IInvocationContext moduleContext) { 93 super.testModuleStarted(moduleContext); 94 // Keep track of the module abi if it has one. 95 List<String> abiName = moduleContext.getAttributes().get(ModuleDefinition.MODULE_ABI); 96 if (abiName != null) { 97 IAbi abi = new Abi(abiName.get(0), AbiUtils.getBitness(abiName.get(0))); 98 mModuleAbi.put( 99 moduleContext.getAttributes().get(ModuleDefinition.MODULE_ID).get(0), abi); 100 } 101 } 102 103 /** Helper to remove the module checker results from the final list of real module results. */ extractModuleCheckers(Collection<TestRunResult> results)104 private List<TestRunResult> extractModuleCheckers(Collection<TestRunResult> results) { 105 List<TestRunResult> moduleCheckers = new ArrayList<TestRunResult>(); 106 for (TestRunResult t : results) { 107 if (t.getName().startsWith(ITestSuite.MODULE_CHECKER_POST) 108 || t.getName().startsWith(ITestSuite.MODULE_CHECKER_PRE)) { 109 moduleCheckers.add(t); 110 } 111 } 112 results.removeAll(moduleCheckers); 113 return moduleCheckers; 114 } 115 116 @Override invocationEnded(long elapsedTime)117 public void invocationEnded(long elapsedTime) { 118 mEndTime = getCurrentTime(); 119 super.invocationEnded(elapsedTime); 120 121 // finalize and print results - general 122 Collection<TestRunResult> results = getMergedTestRunResults(); 123 List<TestRunResult> moduleCheckers = extractModuleCheckers(results); 124 125 mTotalModules = results.size(); 126 127 for (TestRunResult moduleResult : results) { 128 if (!moduleResult.isRunFailure()) { 129 mCompleteModules++; 130 } else { 131 mFailedModule.put(moduleResult.getName(), moduleResult.getRunFailureMessage()); 132 } 133 mTotalTests += moduleResult.getExpectedTestCount(); 134 mPassedTests += moduleResult.getNumTestsInState(TestStatus.PASSED); 135 mFailedTests += moduleResult.getNumAllFailedTests(); 136 mSkippedTests += moduleResult.getNumTestsInState(TestStatus.IGNORED); 137 mAssumeFailureTests += moduleResult.getNumTestsInState(TestStatus.ASSUMPTION_FAILURE); 138 139 // Get the module metrics for target preparation 140 String prepTime = moduleResult.getRunMetrics().get(ModuleDefinition.PREPARATION_TIME); 141 String tearTime = moduleResult.getRunMetrics().get(ModuleDefinition.TEAR_DOWN_TIME); 142 if (prepTime != null && tearTime != null) { 143 mPreparationMap.put( 144 moduleResult.getName(), 145 new ModulePrepTimes(Long.parseLong(prepTime), Long.parseLong(tearTime))); 146 } 147 148 // If they exists, get all the retry information 149 String retrySuccess = 150 moduleResult.getRunMetrics().get(ModuleDefinition.RETRY_SUCCESS_COUNT); 151 if (retrySuccess != null) { 152 mTotalRetrySuccess += Long.parseLong(retrySuccess); 153 mModuleRetrySuccess.put(moduleResult.getName(), Long.parseLong(retrySuccess)); 154 } 155 String retryFailure = 156 moduleResult.getRunMetrics().get(ModuleDefinition.RETRY_FAIL_COUNT); 157 if (retryFailure != null) { 158 mTotalRetryFail += Long.parseLong(retryFailure); 159 mModuleRetryFail.put(moduleResult.getName(), Long.parseLong(retryFailure)); 160 } 161 String retryTime = moduleResult.getRunMetrics().get(ModuleDefinition.RETRY_TIME); 162 if (retryTime != null) { 163 mTotalRetryTime += Long.parseLong(retryTime); 164 mModuleRetryTime.put(moduleResult.getName(), Long.parseLong(retryTime)); 165 } 166 } 167 // print a short report summary 168 mSummary.append("\n============================================\n"); 169 mSummary.append("================= Results ==================\n"); 170 printModuleTestTime(results); 171 printTopSlowModules(results); 172 printPreparationMetrics(mPreparationMap); 173 printModuleCheckersMetric(moduleCheckers); 174 printModuleRetriesInformation(); 175 mSummary.append("=============== Summary ===============\n"); 176 // Print the time from invocation start to end 177 mSummary.append( 178 String.format( 179 "Total Run time: %s\n", TimeUtil.formatElapsedTime(mEndTime - mStartTime))); 180 mSummary.append( 181 String.format("%s/%s modules completed\n", mCompleteModules, mTotalModules)); 182 if (!mFailedModule.isEmpty()) { 183 mSummary.append("Module(s) with run failure(s):\n"); 184 for (Entry<String, String> e : mFailedModule.entrySet()) { 185 mSummary.append(String.format(" %s: %s\n", e.getKey(), e.getValue())); 186 } 187 } 188 mSummary.append(String.format("Total Tests : %s\n", mTotalTests)); 189 mSummary.append(String.format("PASSED : %s\n", mPassedTests)); 190 mSummary.append(String.format("FAILED : %s\n", mFailedTests)); 191 192 if (mSkippedTests > 0l) { 193 mSummary.append(String.format("IGNORED : %s\n", mSkippedTests)); 194 } 195 if (mAssumeFailureTests > 0l) { 196 mSummary.append(String.format("ASSUMPTION_FAILURE: %s\n", mAssumeFailureTests)); 197 } 198 199 if (mCompleteModules != mTotalModules) { 200 mSummary.append( 201 "IMPORTANT: Some modules failed to run to completion, tests counts " 202 + "may be inaccurate.\n"); 203 } 204 205 for (Entry<Integer, List<String>> shard : 206 getInvocationContext().getShardsSerials().entrySet()) { 207 mSummary.append(String.format("Shard %s used: %s\n", shard.getKey(), shard.getValue())); 208 } 209 mSummary.append("============== End of Results ==============\n"); 210 mSummary.append("============================================\n"); 211 CLog.logAndDisplay(LogLevel.INFO, mSummary.toString()); 212 } 213 214 /** Displays the time consumed by each module to run. */ printModuleTestTime(Collection<TestRunResult> results)215 private void printModuleTestTime(Collection<TestRunResult> results) { 216 List<TestRunResult> moduleTime = new ArrayList<>(); 217 moduleTime.addAll(results); 218 Collections.sort( 219 moduleTime, 220 new Comparator<TestRunResult>() { 221 @Override 222 public int compare(TestRunResult o1, TestRunResult o2) { 223 return (int) (o2.getElapsedTime() - o1.getElapsedTime()); 224 } 225 }); 226 long totalRunTime = 0l; 227 mSummary.append("=============== Consumed Time ==============\n"); 228 for (int i = 0; i < moduleTime.size(); i++) { 229 mSummary.append( 230 String.format( 231 " %s: %s\n", 232 moduleTime.get(i).getName(), 233 TimeUtil.formatElapsedTime(moduleTime.get(i).getElapsedTime()))); 234 totalRunTime += moduleTime.get(i).getElapsedTime(); 235 } 236 mSummary.append( 237 String.format( 238 "Total aggregated tests run time: %s\n", 239 TimeUtil.formatElapsedTime(totalRunTime))); 240 } 241 242 /** 243 * Display the average tests / second of modules because elapsed is not always relevant. (Some 244 * modules have way more test cases than others so only looking at elapsed time is not a good 245 * metric for slow modules). 246 */ printTopSlowModules(Collection<TestRunResult> results)247 private void printTopSlowModules(Collection<TestRunResult> results) { 248 List<TestRunResult> moduleTime = new ArrayList<>(); 249 moduleTime.addAll(results); 250 // We don't consider module which runs in less than 5 sec. 251 for (TestRunResult t : results) { 252 if (t.getElapsedTime() < 5000) { 253 moduleTime.remove(t); 254 } 255 } 256 Collections.sort( 257 moduleTime, 258 new Comparator<TestRunResult>() { 259 @Override 260 public int compare(TestRunResult o1, TestRunResult o2) { 261 Float rate1 = ((float) o1.getNumTests() / o1.getElapsedTime()); 262 Float rate2 = ((float) o2.getNumTests() / o2.getElapsedTime()); 263 return rate1.compareTo(rate2); 264 } 265 }); 266 int maxModuleDisplay = moduleTime.size(); 267 if (maxModuleDisplay == 0) { 268 return; 269 } 270 mSummary.append( 271 String.format( 272 "============== TOP %s Slow Modules ==============\n", maxModuleDisplay)); 273 for (int i = 0; i < maxModuleDisplay; i++) { 274 mSummary.append( 275 String.format( 276 " %s: %.02f tests/sec [%s tests / %s msec]\n", 277 moduleTime.get(i).getName(), 278 (moduleTime.get(i).getNumTests() 279 / (moduleTime.get(i).getElapsedTime() / 1000f)), 280 moduleTime.get(i).getNumTests(), 281 moduleTime.get(i).getElapsedTime())); 282 } 283 } 284 285 /** Print the collected times for Module preparation and tear Down. */ printPreparationMetrics(Map<String, ModulePrepTimes> metrics)286 private void printPreparationMetrics(Map<String, ModulePrepTimes> metrics) { 287 if (metrics.isEmpty()) { 288 return; 289 } 290 mSummary.append("============== Modules Preparation Times ==============\n"); 291 long totalPrep = 0l; 292 long totalTear = 0l; 293 294 for (String moduleName : metrics.keySet()) { 295 mSummary.append( 296 String.format( 297 " %s => %s\n", moduleName, metrics.get(moduleName).toString())); 298 totalPrep += metrics.get(moduleName).mPrepTime; 299 totalTear += metrics.get(moduleName).mTearDownTime; 300 } 301 mSummary.append( 302 String.format( 303 "Total preparation time: %s || Total tear down time: %s\n", 304 TimeUtil.formatElapsedTime(totalPrep), 305 TimeUtil.formatElapsedTime(totalTear))); 306 mSummary.append("=======================================================\n"); 307 } 308 printModuleCheckersMetric(List<TestRunResult> moduleCheckerResults)309 private void printModuleCheckersMetric(List<TestRunResult> moduleCheckerResults) { 310 if (moduleCheckerResults.isEmpty()) { 311 return; 312 } 313 mSummary.append("============== Modules Checkers Times ==============\n"); 314 long totalTime = 0l; 315 for (TestRunResult t : moduleCheckerResults) { 316 mSummary.append( 317 String.format( 318 " %s: %s\n", 319 t.getName(), TimeUtil.formatElapsedTime(t.getElapsedTime()))); 320 totalTime += t.getElapsedTime(); 321 } 322 mSummary.append( 323 String.format( 324 "Total module checkers time: %s\n", TimeUtil.formatElapsedTime(totalTime))); 325 mSummary.append("====================================================\n"); 326 } 327 printModuleRetriesInformation()328 private void printModuleRetriesInformation() { 329 if (mModuleRetrySuccess.isEmpty() || mTotalRetryTime == 0L) { 330 return; 331 } 332 mSummary.append("============== Modules Retries Information ==============\n"); 333 for (String t : mModuleRetrySuccess.keySet()) { 334 if (mModuleRetryTime.get(t) == 0L) { 335 continue; 336 } 337 mSummary.append( 338 String.format( 339 " %s:\n" 340 + " Retry Success (Failed test became Pass) = %s\n" 341 + " Retry Failure (Failed test stayed Failed) = %s\n" 342 + " Retry Time = %s\n", 343 t, 344 mModuleRetrySuccess.get(t), 345 mModuleRetryFail.get(t), 346 TimeUtil.formatElapsedTime(mModuleRetryTime.get(t)))); 347 } 348 mSummary.append("Summary:\n"); 349 mSummary.append( 350 String.format( 351 "Total Retry Success (Failed test became Pass) = %s\n" 352 + "Total Retry Failure (Failed test stayed Failed) = %s\n" 353 + "Total Retry Time = %s\n", 354 mTotalRetrySuccess, 355 mTotalRetryFail, 356 TimeUtil.formatElapsedTime(mTotalRetryTime))); 357 mSummary.append("====================================================\n"); 358 } 359 360 /** Returns a map of modules abi: <module id, abi>. */ getModulesAbi()361 public Map<String, IAbi> getModulesAbi() { 362 return mModuleAbi; 363 } 364 getTotalModules()365 public int getTotalModules() { 366 return mTotalModules; 367 } 368 getCompleteModules()369 public int getCompleteModules() { 370 return mCompleteModules; 371 } 372 getTotalTests()373 public long getTotalTests() { 374 return mTotalTests; 375 } 376 getPassedTests()377 public long getPassedTests() { 378 return mPassedTests; 379 } 380 getFailedTests()381 public long getFailedTests() { 382 return mFailedTests; 383 } 384 385 /** Object holder for the preparation and tear down time of one module. */ 386 public static class ModulePrepTimes { 387 388 public final long mPrepTime; 389 public final long mTearDownTime; 390 ModulePrepTimes(long prepTime, long tearTime)391 public ModulePrepTimes(long prepTime, long tearTime) { 392 mPrepTime = prepTime; 393 mTearDownTime = tearTime; 394 } 395 396 @Override toString()397 public String toString() { 398 return String.format("prep = %s ms || clean = %s ms", mPrepTime, mTearDownTime); 399 } 400 } 401 402 @Override getSummary()403 public TestSummary getSummary() { 404 TestSummary summary = new TestSummary(new TypedString(mSummary.toString(), Type.TEXT)); 405 summary.setSource(SUITE_REPORTER_SOURCE); 406 return summary; 407 } 408 409 /** Returns the start time of the invocation. */ getStartTime()410 protected long getStartTime() { 411 return mStartTime; 412 } 413 414 /** Returns the end time of the invocation. */ getEndTime()415 protected long getEndTime() { 416 return mEndTime; 417 } 418 419 @VisibleForTesting getCurrentTime()420 protected long getCurrentTime() { 421 return System.currentTimeMillis(); 422 } 423 } 424