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