1 /* 2 * Copyright (C) 2015 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 17 package com.android.performance.tests; 18 19 import com.android.ddmlib.IDevice; 20 import com.android.ddmlib.testrunner.IRemoteAndroidTestRunner; 21 import com.android.ddmlib.testrunner.RemoteAndroidTestRunner; 22 import com.android.tradefed.config.Option; 23 import com.android.tradefed.config.Option.Importance; 24 import com.android.tradefed.device.DeviceNotAvailableException; 25 import com.android.tradefed.device.ITestDevice; 26 import com.android.tradefed.device.LogcatReceiver; 27 import com.android.tradefed.log.LogUtil.CLog; 28 import com.android.tradefed.result.CollectingTestListener; 29 import com.android.tradefed.result.FileInputStreamSource; 30 import com.android.tradefed.result.ITestInvocationListener; 31 import com.android.tradefed.result.InputStreamSource; 32 import com.android.tradefed.result.LogDataType; 33 import com.android.tradefed.result.TestResult; 34 import com.android.tradefed.testtype.IDeviceTest; 35 import com.android.tradefed.testtype.IRemoteTest; 36 import com.android.tradefed.util.FileUtil; 37 import com.android.tradefed.util.ListInstrumentationParser; 38 import com.android.tradefed.util.ListInstrumentationParser.InstrumentationTarget; 39 import com.android.tradefed.util.StreamUtil; 40 import com.android.tradefed.util.proto.TfMetricProtoUtil; 41 42 import org.junit.Assert; 43 44 import java.io.BufferedReader; 45 import java.io.File; 46 import java.io.FileNotFoundException; 47 import java.io.FileReader; 48 import java.io.IOException; 49 import java.io.InputStreamReader; 50 import java.util.ArrayList; 51 import java.util.Collection; 52 import java.util.HashMap; 53 import java.util.HashSet; 54 import java.util.LinkedList; 55 import java.util.List; 56 import java.util.Map; 57 import java.util.Set; 58 import java.util.regex.Matcher; 59 import java.util.regex.Pattern; 60 61 /** 62 * To test the app launch performance for the list of activities present in the given target package 63 * or the custom list of activities present in the target package.Activities are launched number of 64 * times present in the launch count. Launch time is analyzed from the logcat data and more detailed 65 * timing(section names) is analyzed from the atrace files captured when launching each activity. 66 */ 67 public class HermeticLaunchTest implements IRemoteTest, IDeviceTest { 68 69 private static enum AtraceSectionOptions { 70 LAYOUT("layout"), 71 DRAW("draw"), 72 BINDAPPLICATION("bindApplication"), 73 ACTIVITYSTART("activityStart"), 74 ONCREATE("onCreate"), 75 INFLATE("inflate"); 76 77 private final String name; 78 AtraceSectionOptions(String s)79 private AtraceSectionOptions(String s) { 80 this.name = s; 81 } 82 83 @Override toString()84 public String toString() { 85 return name; 86 } 87 } 88 89 private static final String TOTALLAUNCHTIME = "totalLaunchTime"; 90 private static final String LOGCAT_CMD = "logcat -v threadtime " 91 + "ActivityManager:* ActivityTaskManager:* *:s"; 92 private static final String LAUNCH_PREFIX = 93 "^\\d*-\\d*\\s*\\d*:\\d*:\\d*.\\d*\\s*\\d*\\s*" 94 + "\\d*\\s*I (ActivityTaskManager|ActivityManager): Displayed\\s*"; 95 private static final String LAUNCH_SUFFIX = 96 ":\\s*\\+(?<launchtime>.[a-zA-Z\\d]*)\\s*" + "(?<totallaunch>.*)\\s*$"; 97 private static final Pattern LAUNCH_ENTRY = 98 Pattern.compile( 99 "^\\d*-\\d*\\s*\\d*:\\d*:\\d*." 100 + "\\d*\\s*\\d*\\s*\\d*\\s*I (ActivityTaskManager|ActivityManager):" 101 + " Displayed\\s*(?<launchinfo>.*)\\s*$"); 102 private static final Pattern TRACE_ENTRY1 = 103 Pattern.compile( 104 "^[^-]*-(?<tid>\\d+)\\s+\\[\\d+\\]\\s+\\S{4}\\s+" 105 + "(?<secs>\\d+)\\.(?<usecs>\\d+):\\s+(?<function>.*)\\s*$"); 106 private static final Pattern TRACE_ENTRY2 = 107 Pattern.compile( 108 "^[^-]*-(?<tid>\\d+)\\s*\\(\\s*\\d*-*\\)\\s*\\[\\d+\\]\\s+\\S{4}\\s+" 109 + "(?<secs>\\d+)\\.(?<usecs>\\d+):\\s+(?<function>.*)\\s*$"); 110 private static final Pattern ATRACE_BEGIN = 111 Pattern.compile("tracing_mark_write: B\\|(?<pid>\\d+)\\|(?<name>.+)"); 112 // Matches new and old format of END time stamp. 113 // rformanceLaunc-6315 ( 6315) [007] ...1 182.622217: tracing_mark_write: E|6315 114 // rformanceLaunc-6315 ( 6315) [007] ...1 182.622217: tracing_mark_write: E 115 private static final Pattern ATRACE_END = 116 Pattern.compile("tracing_mark_write: E\\|*(?<procid>\\d*)"); 117 private static final Pattern ATRACE_COUNTER = 118 Pattern.compile( 119 "tracing_mark_write: C\\|(?<pid>\\d+)\\|(?<name>[^|]+)\\|(?<value>\\d+)"); 120 private static final Pattern ATRACE_HEADER_ENTRIES = 121 Pattern.compile( 122 "# entries-in-buffer/entries-written:\\s+(?<buffered>\\d+)/" 123 + "(?<written>\\d+)\\s+#P:\\d+\\s*"); 124 private static final int LOGCAT_SIZE = 20971520; // 20 mb 125 private static final long SEC_TO_MILLI = 1000; 126 private static final long MILLI_TO_MICRO = 1000; 127 128 @Option(name = "runner", description = "The instrumentation test runner class name to use.") 129 private String mRunnerName = ""; 130 131 @Option( 132 name = "package", 133 shortName = 'p', 134 description = "The manifest package name of the Android test application to run.", 135 importance = Importance.IF_UNSET) 136 private String mPackageName = "com.android.performanceapp.tests"; 137 138 @Option( 139 name = "target-package", 140 description = "package which contains all the " + "activities to launch") 141 private String mtargetPackage = null; 142 143 @Option( 144 name = "activity-names", 145 description = 146 "Fully qualified activity " 147 + "names separated by comma" 148 + "If not set then all the activities will be included for launching") 149 private String mactivityNames = ""; 150 151 @Option(name = "launch-count", description = "number of time to launch the each activity") 152 private int mlaunchCount = 10; 153 154 @Option(name = "trace-category", description = "comma separated list of trace categories") 155 private String mtraceCategory = "am,view,gfx,dalvik"; 156 157 @Option(name = "save-atrace", description = "Upload the atrace file in permanent storage") 158 private boolean mSaveAtrace = false; 159 160 @Option( 161 name = "atrace-section", 162 description = "Section to be parsed from atrace file. " + "This option can be repeated") 163 private Set<AtraceSectionOptions> mSectionOptionSet = new HashSet<>(); 164 165 @Option(name = "instantapp-url", description = "URL used to launch instant app") 166 private String mInstantAppUrl = ""; 167 168 @Option( 169 name = "isolated-storage", 170 description = 171 "If set to false, the '--no-isolated-storage' flag will be passed to the am " 172 + "instrument command. Only works for Q or later." 173 ) 174 private boolean mIsolatedStorage = true; 175 176 private ITestDevice mDevice = null; 177 private IRemoteAndroidTestRunner mRunner; 178 private LogcatReceiver mLogcat; 179 private Set<String> mSectionSet = new HashSet<>(); 180 private Map<String, String> mActivityTraceFileMap; 181 private Map<String, Map<String, String>> mActivityTimeResultMap = new HashMap<>(); 182 private Map<String, String> activityErrMsg = new HashMap<>(); 183 private ListInstrumentationParser mListInstrumentationParser = null; 184 185 @Override run(ITestInvocationListener listener)186 public void run(ITestInvocationListener listener) throws DeviceNotAvailableException { 187 188 mLogcat = new LogcatReceiver(getDevice(), LOGCAT_CMD, LOGCAT_SIZE, 0); 189 mLogcat.start(); 190 try { 191 if (mSectionOptionSet.isEmpty()) { 192 // Default sections 193 mSectionOptionSet.add(AtraceSectionOptions.LAYOUT); 194 mSectionOptionSet.add(AtraceSectionOptions.DRAW); 195 mSectionOptionSet.add(AtraceSectionOptions.BINDAPPLICATION); 196 mSectionOptionSet.add(AtraceSectionOptions.ACTIVITYSTART); 197 mSectionOptionSet.add(AtraceSectionOptions.ONCREATE); 198 mSectionOptionSet.add(AtraceSectionOptions.INFLATE); 199 } else if (mSectionOptionSet.contains(AtraceSectionOptions.LAYOUT)) { 200 // If layout is added, draw should also be included 201 mSectionOptionSet.add(AtraceSectionOptions.DRAW); 202 } 203 204 for (AtraceSectionOptions sectionOption : mSectionOptionSet) { 205 mSectionSet.add(sectionOption.toString()); 206 } 207 208 // Remove if there is already existing atrace_logs folder 209 mDevice.executeShellCommand("rm -rf ${EXTERNAL_STORAGE}/atrace_logs"); 210 211 if (mRunnerName.isEmpty()) { 212 mRunnerName = queryRunnerName(); 213 } 214 215 mRunner = 216 createRemoteAndroidTestRunner(mPackageName, mRunnerName, mDevice.getIDevice()); 217 CollectingTestListener collectingListener = new CollectingTestListener(); 218 mDevice.runInstrumentationTests(mRunner, collectingListener); 219 220 Collection<TestResult> testResultsCollection = 221 collectingListener.getCurrentRunResults().getTestResults().values(); 222 List<TestResult> testResults = new ArrayList<>(testResultsCollection); 223 /* 224 * Expected Metrics : Map of <activity name>=<comma separated list of atrace file names 225 * in external storage of the device> 226 */ 227 mActivityTraceFileMap = testResults.get(0).getMetrics(); 228 Assert.assertTrue( 229 "Unable to get the path to the trace files stored in the device", 230 (mActivityTraceFileMap != null && !mActivityTraceFileMap.isEmpty())); 231 232 // Analyze the logcat data to get total launch time 233 analyzeLogCatData(mActivityTraceFileMap.keySet()); 234 } finally { 235 // Stop the logcat 236 mLogcat.stop(); 237 } 238 239 // Analyze the atrace data to get bindApplication,activityStart etc.. 240 analyzeAtraceData(listener); 241 242 // Report the metrics to dashboard 243 reportMetrics(listener); 244 } 245 246 /** 247 * Report run metrics by creating an empty test run to stick them in. 248 * 249 * @param listener The {@link ITestInvocationListener} of test results 250 */ reportMetrics(ITestInvocationListener listener)251 private void reportMetrics(ITestInvocationListener listener) { 252 for (String activityName : mActivityTimeResultMap.keySet()) { 253 // Get the activity name alone from pkgname.activityname 254 String[] activityNameSplit = activityName.split("\\."); 255 if (!activityErrMsg.containsKey(activityName)) { 256 Map<String, String> activityMetrics = mActivityTimeResultMap.get(activityName); 257 if (activityMetrics != null && !activityMetrics.isEmpty()) { 258 CLog.v("Metrics for the activity : %s", activityName); 259 for (String sectionName : activityMetrics.keySet()) { 260 CLog.v( 261 String.format( 262 "Section name : %s - Time taken : %s", 263 sectionName, activityMetrics.get(sectionName))); 264 } 265 listener.testRunStarted( 266 activityNameSplit[activityNameSplit.length - 1].trim(), 0); 267 listener.testRunEnded(0, TfMetricProtoUtil.upgradeConvert(activityMetrics)); 268 } 269 } else { 270 listener.testRunStarted(activityNameSplit[activityNameSplit.length - 1].trim(), 0); 271 listener.testRunFailed(activityErrMsg.get(activityName)); 272 } 273 } 274 } 275 276 /** 277 * Method to create the runner with given list of arguments 278 * 279 * @return the {@link IRemoteAndroidTestRunner} to use. 280 * @throws DeviceNotAvailableException 281 */ createRemoteAndroidTestRunner( String packageName, String runnerName, IDevice device)282 IRemoteAndroidTestRunner createRemoteAndroidTestRunner( 283 String packageName, String runnerName, IDevice device) 284 throws DeviceNotAvailableException { 285 RemoteAndroidTestRunner runner = 286 new RemoteAndroidTestRunner(packageName, runnerName, device); 287 runner.addInstrumentationArg("targetpackage", mtargetPackage); 288 runner.addInstrumentationArg("launchcount", mlaunchCount + ""); 289 runner.addInstrumentationArg("tracecategory", mtraceCategory); 290 if (!mInstantAppUrl.isEmpty()) { 291 runner.addInstrumentationArg("instanturl", mInstantAppUrl); 292 } 293 if (mactivityNames != null && !mactivityNames.isEmpty()) { 294 runner.addInstrumentationArg("activitylist", mactivityNames); 295 } 296 if (!mSaveAtrace) { 297 runner.addInstrumentationArg("recordtrace", "false"); 298 } 299 300 String runOptions = ""; 301 302 // isolated-storage flag only exists in Q and after. 303 if (!mIsolatedStorage && getDevice().checkApiLevelAgainstNextRelease(29)) { 304 305 runOptions += "--no-isolated-storage "; 306 } 307 308 runner.setRunOptions(runOptions); 309 310 return runner; 311 } 312 313 /** 314 * Get the {@link ListInstrumentationParser} used to parse 'pm list instrumentation' queries. 315 */ getListInstrumentationParser()316 protected ListInstrumentationParser getListInstrumentationParser() { 317 if (mListInstrumentationParser == null) { 318 mListInstrumentationParser = new ListInstrumentationParser(); 319 } 320 return mListInstrumentationParser; 321 } 322 323 /** 324 * Query the device for a test runner to use. 325 * 326 * @return the first test runner name that matches the package or null if we don't find any. 327 * @throws DeviceNotAvailableException 328 */ queryRunnerName()329 protected String queryRunnerName() throws DeviceNotAvailableException { 330 ListInstrumentationParser parser = getListInstrumentationParser(); 331 getDevice().executeShellCommand("pm list instrumentation", parser); 332 333 for (InstrumentationTarget target : parser.getInstrumentationTargets()) { 334 if (mPackageName.equals(target.packageName)) { 335 return target.runnerName; 336 } 337 } 338 throw new RuntimeException( 339 String.format("Unable to determine runner name for package: %s", mPackageName)); 340 } 341 342 /** 343 * To analyze the log cat data to get the display time reported by activity manager during the 344 * launches activitySet is set of activityNames returned as a part of testMetrics from the 345 * device 346 */ analyzeLogCatData(Set<String> activitySet)347 public void analyzeLogCatData(Set<String> activitySet) { 348 Map<String, List<Integer>> amLaunchTimes = new HashMap<>(); 349 350 Map<Pattern, String> activityPatternMap = new HashMap<>(); 351 Matcher match = null; 352 String line; 353 354 /* 355 * Sample line format in logcat 06-17 16:55:49.6 60 642 I 356 * (ActivityTaskManager|ActivityManager): Displayed pkg/.activity: +Tms (total +9s9ms) 357 */ 358 for (String activityName : activitySet) { 359 int lastIndex = activityName.lastIndexOf("."); 360 /* 361 * actvitySet has set of activity names in the format packageName.activityName logcat 362 * has the format packageName/.activityName --> activityAlias 363 */ 364 String activityAlias = new String(); 365 if (mInstantAppUrl.isEmpty()) { 366 activityAlias = 367 activityName.subSequence(0, lastIndex) 368 + "/" 369 + activityName.subSequence(lastIndex, activityName.length()); 370 } else { 371 activityAlias = mtargetPackage + ".*"; 372 } 373 String finalPattern = LAUNCH_PREFIX + activityAlias + LAUNCH_SUFFIX; 374 activityPatternMap.put(Pattern.compile(finalPattern), activityName); 375 } 376 377 try (InputStreamSource input = mLogcat.getLogcatData(); 378 BufferedReader br = 379 new BufferedReader(new InputStreamReader(input.createInputStream()))) { 380 while ((line = br.readLine()) != null) { 381 /* 382 * Launch entry needed otherwise we will end up in comparing all the lines for all 383 * the patterns 384 */ 385 if ((match = matches(LAUNCH_ENTRY, line)) != null) { 386 for (Pattern pattern : activityPatternMap.keySet()) { 387 if ((match = matches(pattern, line)) != null) { 388 CLog.v("Launch Info : %s", line); 389 int displayTimeInMs = extractLaunchTime(match.group("launchtime")); 390 String activityName = activityPatternMap.get(pattern); 391 if (amLaunchTimes.containsKey(activityName)) { 392 amLaunchTimes.get(activityName).add(displayTimeInMs); 393 } else { 394 List<Integer> launchTimes = new ArrayList<>(); 395 launchTimes.add(displayTimeInMs); 396 amLaunchTimes.put(activityName, launchTimes); 397 } 398 } 399 } 400 } 401 } 402 } catch (IOException io) { 403 CLog.e(io); 404 } 405 406 // Verify logcat data 407 for (String activityName : amLaunchTimes.keySet()) { 408 Assert.assertEquals( 409 "Data lost for launch time for the activity :" + activityName, 410 amLaunchTimes.get(activityName).size(), 411 mlaunchCount); 412 } 413 414 /* 415 * Extract and store the average launch time data reported by activity manager for each 416 * activity 417 */ 418 for (String activityName : amLaunchTimes.keySet()) { 419 Double totalTime = 0d; 420 for (Integer launchTime : amLaunchTimes.get(activityName)) { 421 totalTime += launchTime; 422 } 423 Double averageTime = Double.valueOf(totalTime / amLaunchTimes.get(activityName).size()); 424 if (mActivityTimeResultMap.containsKey(activityName)) { 425 mActivityTimeResultMap 426 .get(activityName) 427 .put(TOTALLAUNCHTIME, String.format("%.2f", averageTime)); 428 } else { 429 Map<String, String> launchTime = new HashMap<>(); 430 launchTime.put(TOTALLAUNCHTIME, String.format("%.2f", averageTime)); 431 mActivityTimeResultMap.put(activityName, launchTime); 432 } 433 } 434 } 435 436 /** 437 * To extract the launch time displayed in given line 438 * 439 * @param duration 440 * @return 441 */ extractLaunchTime(String duration)442 public int extractLaunchTime(String duration) { 443 String formattedString = duration.replace("ms", ""); 444 if (formattedString.contains("s")) { 445 String[] splitString = formattedString.split("s"); 446 int finalTimeInMs = Integer.parseInt(splitString[0]) * 1000; 447 finalTimeInMs = finalTimeInMs + Integer.parseInt(splitString[1]); 448 return finalTimeInMs; 449 } else { 450 return Integer.parseInt(formattedString); 451 } 452 } 453 454 /** To analyze the trace data collected in the device during each activity launch. */ analyzeAtraceData(ITestInvocationListener listener)455 public void analyzeAtraceData(ITestInvocationListener listener) 456 throws DeviceNotAvailableException { 457 for (String activityName : mActivityTraceFileMap.keySet()) { 458 try { 459 // Get the list of associated filenames for given activity 460 String filePathAll = mActivityTraceFileMap.get(activityName); 461 Assert.assertNotNull( 462 String.format( 463 "Unable to find trace file paths for activity : %s", activityName), 464 filePathAll); 465 String[] filePaths = filePathAll.split(","); 466 Assert.assertEquals( 467 String.format( 468 "Unable to find file path for all the launches " 469 + "for the activity :%s", 470 activityName), 471 filePaths.length, 472 mlaunchCount); 473 // Pull and parse the info 474 List<Map<String, List<SectionPeriod>>> mutipleLaunchTraceInfo = new LinkedList<>(); 475 for (int count = 0; count < filePaths.length; count++) { 476 File currentAtraceFile = pullAtraceInfoFile(filePaths[count]); 477 String[] splitName = filePaths[count].split("-"); 478 // Process id is appended to original file name 479 Map<String, List<SectionPeriod>> singleLaunchTraceInfo = 480 parseAtraceInfoFile(currentAtraceFile, splitName[splitName.length - 1]); 481 // Upload the file if needed 482 if (mSaveAtrace) { 483 try (FileInputStreamSource stream = 484 new FileInputStreamSource(currentAtraceFile)) { 485 listener.testLog(currentAtraceFile.getName(), LogDataType.TEXT, stream); 486 } 487 } 488 // Remove the atrace files 489 FileUtil.deleteFile(currentAtraceFile); 490 mutipleLaunchTraceInfo.add(singleLaunchTraceInfo); 491 } 492 493 // Verify and Average out the aTrace Info and store it in result map 494 averageAtraceData(activityName, mutipleLaunchTraceInfo); 495 } catch (FileNotFoundException foe) { 496 CLog.e(foe); 497 activityErrMsg.put( 498 activityName, 499 "Unable to find the trace file for the activity launch :" + activityName); 500 } catch (IOException ioe) { 501 CLog.e(ioe); 502 activityErrMsg.put( 503 activityName, 504 "Unable to read the contents of the atrace file for the activity :" 505 + activityName); 506 } 507 } 508 } 509 510 /** 511 * To pull the trace file from the device 512 * 513 * @param aTraceFile 514 * @return 515 * @throws DeviceNotAvailableException 516 */ pullAtraceInfoFile(String aTraceFile)517 public File pullAtraceInfoFile(String aTraceFile) throws DeviceNotAvailableException { 518 String dir = "${EXTERNAL_STORAGE}/atrace_logs"; 519 File atraceFileHandler = null; 520 atraceFileHandler = getDevice().pullFile(dir + "/" + aTraceFile); 521 Assert.assertTrue("Unable to retrieve the atrace files", atraceFileHandler != null); 522 return atraceFileHandler; 523 } 524 525 /** 526 * To parse and find the time taken for the given section names in each launch 527 * 528 * @param currentAtraceFile 529 * @param sectionSet 530 * @param processId 531 * @return 532 * @throws FileNotFoundException,IOException 533 */ parseAtraceInfoFile( File currentAtraceFile, String processId)534 public Map<String, List<SectionPeriod>> parseAtraceInfoFile( 535 File currentAtraceFile, String processId) throws FileNotFoundException, IOException { 536 CLog.v("Currently parsing :" + currentAtraceFile.getName()); 537 String line; 538 BufferedReader br = null; 539 br = new BufferedReader(new FileReader(currentAtraceFile)); 540 LinkedList<TraceRecord> processStack = new LinkedList<>(); 541 Map<String, List<SectionPeriod>> sectionInfo = new HashMap<>(); 542 543 while ((line = br.readLine()) != null) { 544 // Skip extra lines that aren't part of the trace 545 if (line.isEmpty() 546 || line.startsWith("capturing trace...") 547 || line.equals("TRACE:") 548 || line.equals("done")) { 549 continue; 550 } 551 // Header information 552 Matcher match = null; 553 // Check if any trace entries were lost 554 if ((match = matches(ATRACE_HEADER_ENTRIES, line)) != null) { 555 int buffered = Integer.parseInt(match.group("buffered")); 556 int written = Integer.parseInt(match.group("written")); 557 if (written != buffered) { 558 CLog.w( 559 String.format( 560 "%d trace entries lost for the file %s", 561 written - buffered, currentAtraceFile.getName())); 562 } 563 } else if ((match = matches(TRACE_ENTRY1, line)) != null 564 || (match = matches(TRACE_ENTRY2, line)) != null) { 565 /* 566 * Two trace entries because trace format differs across devices <...>-tid [yyy] 567 * ...1 zzz.ttt: tracing_mark_write: B|xxxx|tag_name pkg.name ( tid) [yyy] ...1 568 * zzz.tttt: tracing_mark_write: B|xxxx|tag_name 569 */ 570 long timestamp = 571 SEC_TO_MILLI * Long.parseLong(match.group("secs")) 572 + Long.parseLong(match.group("usecs")) / MILLI_TO_MICRO; 573 // Get the function name from the trace entry 574 String taskId = match.group("tid"); 575 String function = match.group("function"); 576 // Analyze the lines that matches the processid 577 if (!taskId.equals(processId)) { 578 continue; 579 } 580 if ((match = matches(ATRACE_BEGIN, function)) != null) { 581 // Matching pattern looks like tracing_mark_write: B|xxxx|tag_name 582 String sectionName = match.group("name"); 583 // Push to the stack 584 processStack.add(new TraceRecord(sectionName, taskId, timestamp)); 585 } else if ((match = matches(ATRACE_END, function)) != null) { 586 /* 587 * Matching pattern looks like tracing_mark_write: E Pop from the stack when end 588 * reaches 589 */ 590 String endProcId = match.group("procid"); 591 if (endProcId.isEmpty() || endProcId.equals(processId)) { 592 TraceRecord matchingBegin = processStack.removeLast(); 593 if (mSectionSet.contains(matchingBegin.name)) { 594 if (sectionInfo.containsKey(matchingBegin.name)) { 595 SectionPeriod newSecPeriod = 596 new SectionPeriod(matchingBegin.timestamp, timestamp); 597 CLog.v( 598 "Section :%s took :%f msecs ", 599 matchingBegin.name, newSecPeriod.duration); 600 sectionInfo.get(matchingBegin.name).add(newSecPeriod); 601 } else { 602 List<SectionPeriod> infoList = new LinkedList<>(); 603 SectionPeriod newSecPeriod = 604 new SectionPeriod(matchingBegin.timestamp, timestamp); 605 CLog.v( 606 String.format( 607 "Section :%s took :%f msecs ", 608 matchingBegin.name, newSecPeriod.duration)); 609 infoList.add(newSecPeriod); 610 sectionInfo.put(matchingBegin.name, infoList); 611 } 612 } 613 } 614 } else if ((match = matches(ATRACE_COUNTER, function)) != null) { 615 // Skip this for now. May want to track these later if needed. 616 } 617 } 618 } 619 StreamUtil.close(br); 620 return sectionInfo; 621 } 622 623 /** 624 * To take the average of the multiple launches for each activity 625 * 626 * @param activityName 627 * @param mutipleLaunchTraceInfo 628 */ averageAtraceData( String activityName, List<Map<String, List<SectionPeriod>>> mutipleLaunchTraceInfo)629 public void averageAtraceData( 630 String activityName, List<Map<String, List<SectionPeriod>>> mutipleLaunchTraceInfo) { 631 String verificationResult = verifyAtraceMapInfo(mutipleLaunchTraceInfo); 632 if (verificationResult != null) { 633 CLog.w( 634 "Not all the section info captured for the activity :%s. Missing: %s. " 635 + "Please go to atrace file to look for detail.", 636 activityName, verificationResult); 637 } 638 Map<String, Double> launchSum = new HashMap<>(); 639 for (String sectionName : mSectionSet) { 640 launchSum.put(sectionName, 0d); 641 } 642 for (Map<String, List<SectionPeriod>> singleLaunchInfo : mutipleLaunchTraceInfo) { 643 for (String sectionName : singleLaunchInfo.keySet()) { 644 for (SectionPeriod secPeriod : singleLaunchInfo.get(sectionName)) { 645 if (sectionName.equals(AtraceSectionOptions.DRAW.toString())) { 646 // Get the first draw time for the launch 647 Double currentSum = launchSum.get(sectionName) + secPeriod.duration; 648 launchSum.put(sectionName, currentSum); 649 break; 650 } 651 // Sum the multiple layout times before the first draw in this launch 652 if (sectionName.equals(AtraceSectionOptions.LAYOUT.toString())) { 653 Double drawStartTime = 654 singleLaunchInfo 655 .get(AtraceSectionOptions.DRAW.toString()) 656 .get(0) 657 .startTime; 658 if (drawStartTime < secPeriod.startTime) { 659 break; 660 } 661 } 662 Double currentSum = launchSum.get(sectionName) + secPeriod.duration; 663 launchSum.put(sectionName, currentSum); 664 } 665 } 666 } 667 // Update the final result map 668 for (String sectionName : mSectionSet) { 669 Double averageTime = launchSum.get(sectionName) / mutipleLaunchTraceInfo.size(); 670 mActivityTimeResultMap 671 .get(activityName) 672 .put(sectionName, String.format("%.2f", averageTime)); 673 } 674 } 675 676 /** 677 * To check if all the section info caught for all the app launches 678 * 679 * @param multipleLaunchTraceInfo 680 * @return String: the missing section name, null if no section info missing. 681 */ verifyAtraceMapInfo( List<Map<String, List<SectionPeriod>>> multipleLaunchTraceInfo)682 public String verifyAtraceMapInfo( 683 List<Map<String, List<SectionPeriod>>> multipleLaunchTraceInfo) { 684 for (Map<String, List<SectionPeriod>> singleLaunchInfo : multipleLaunchTraceInfo) { 685 Set<String> testSet = new HashSet<>(mSectionSet); 686 testSet.removeAll(singleLaunchInfo.keySet()); 687 if (testSet.size() != 0) { 688 return testSet.toString(); 689 } 690 } 691 return null; 692 } 693 694 /** 695 * Checks whether {@code line} matches the given {@link Pattern}. 696 * 697 * @return The resulting {@link Matcher} obtained by matching the {@code line} against 698 * {@code pattern}, or null if the {@code line} does not match. 699 */ matches(Pattern pattern, String line)700 private static Matcher matches(Pattern pattern, String line) { 701 Matcher ret = pattern.matcher(line); 702 return ret.matches() ? ret : null; 703 } 704 705 @Override setDevice(ITestDevice device)706 public void setDevice(ITestDevice device) { 707 mDevice = device; 708 } 709 710 @Override getDevice()711 public ITestDevice getDevice() { 712 return mDevice; 713 } 714 715 /** 716 * A record to keep track of the section start time,end time and the duration in milliseconds. 717 */ 718 public static class SectionPeriod { 719 720 private double startTime; 721 private double endTime; 722 private double duration; 723 SectionPeriod(double startTime, double endTime)724 public SectionPeriod(double startTime, double endTime) { 725 this.startTime = startTime; 726 this.endTime = endTime; 727 this.duration = endTime - startTime; 728 } 729 getStartTime()730 public double getStartTime() { 731 return startTime; 732 } 733 setStartTime(long startTime)734 public void setStartTime(long startTime) { 735 this.startTime = startTime; 736 } 737 getEndTime()738 public double getEndTime() { 739 return endTime; 740 } 741 setEndTime(long endTime)742 public void setEndTime(long endTime) { 743 this.endTime = endTime; 744 } 745 getDuration()746 public double getDuration() { 747 return duration; 748 } 749 setDuration(long duration)750 public void setDuration(long duration) { 751 this.duration = duration; 752 } 753 } 754 755 /** 756 * A record of a trace event. Includes the name of the section, and the time that the event 757 * occurred (in milliseconds). 758 */ 759 public static class TraceRecord { 760 761 private String name; 762 private String processId; 763 private double timestamp; 764 765 /** 766 * Construct a new {@link TraceRecord} with the given {@code name} and {@code timestamp} . 767 */ TraceRecord(String name, String processId, long timestamp)768 public TraceRecord(String name, String processId, long timestamp) { 769 this.name = name; 770 this.processId = processId; 771 this.timestamp = timestamp; 772 } 773 getName()774 public String getName() { 775 return name; 776 } 777 setName(String name)778 public void setName(String name) { 779 this.name = name; 780 } 781 getProcessId()782 public String getProcessId() { 783 return processId; 784 } 785 setProcessId(String processId)786 public void setProcessId(String processId) { 787 this.processId = processId; 788 } 789 getTimestamp()790 public double getTimestamp() { 791 return timestamp; 792 } 793 setTimestamp(long timestamp)794 public void setTimestamp(long timestamp) { 795 this.timestamp = timestamp; 796 } 797 } 798 } 799