1 /* 2 * Copyright (C) 2024 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.boot; 17 18 import com.android.ddmlib.testrunner.IRemoteAndroidTestRunner; 19 import com.android.ddmlib.testrunner.RemoteAndroidTestRunner; 20 import com.android.loganalysis.item.DmesgActionInfoItem; 21 import com.android.loganalysis.item.DmesgServiceInfoItem; 22 import com.android.loganalysis.item.DmesgStageInfoItem; 23 import com.android.loganalysis.item.GenericTimingItem; 24 import com.android.loganalysis.item.SystemServicesTimingItem; 25 import com.android.loganalysis.parser.DmesgParser; 26 import com.android.loganalysis.parser.TimingsLogParser; 27 import com.android.tradefed.build.IBuildInfo; 28 import com.android.tradefed.config.IConfiguration; 29 import com.android.tradefed.config.IConfigurationReceiver; 30 import com.android.tradefed.config.Option; 31 import com.android.tradefed.config.Option.Importance; 32 import com.android.tradefed.device.DeviceNotAvailableException; 33 import com.android.tradefed.device.LogcatReceiver; 34 import com.android.tradefed.device.metric.IMetricCollector; 35 import com.android.tradefed.device.metric.IMetricCollectorReceiver; 36 import com.android.tradefed.error.IHarnessException; 37 import com.android.tradefed.invoker.IInvocationContext; 38 import com.android.tradefed.invoker.TestInformation; 39 import com.android.tradefed.log.LogUtil.CLog; 40 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric; 41 import com.android.tradefed.result.CollectingTestListener; 42 import com.android.tradefed.result.FailureDescription; 43 import com.android.tradefed.result.ITestInvocationListener; 44 import com.android.tradefed.result.InputStreamSource; 45 import com.android.tradefed.result.LogDataType; 46 import com.android.tradefed.result.TestDescription; 47 import com.android.tradefed.result.error.ErrorIdentifier; 48 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 49 import com.android.tradefed.testtype.IBuildReceiver; 50 import com.android.tradefed.testtype.IDeviceTest; 51 import com.android.tradefed.testtype.IRemoteTest; 52 import com.android.tradefed.testtype.InstalledInstrumentationsTest; 53 import com.android.tradefed.testtype.IInvocationContextReceiver; 54 import com.android.tradefed.util.CommandResult; 55 import com.android.tradefed.util.CommandStatus; 56 import com.android.tradefed.util.IRunUtil; 57 import com.android.tradefed.util.RunUtil; 58 59 import com.google.common.annotations.VisibleForTesting; 60 61 import java.io.BufferedReader; 62 import java.io.File; 63 import java.io.FileInputStream; 64 import java.io.IOException; 65 import java.io.InputStream; 66 import java.io.InputStreamReader; 67 import java.text.DateFormat; 68 import java.text.ParseException; 69 import java.text.SimpleDateFormat; 70 import java.util.ArrayList; 71 import java.util.Arrays; 72 import java.util.Collection; 73 import java.util.Date; 74 import java.util.HashMap; 75 import java.util.HashSet; 76 import java.util.LinkedHashMap; 77 import java.util.List; 78 import java.util.Map; 79 import java.util.Set; 80 import java.util.regex.Matcher; 81 import java.util.regex.Pattern; 82 83 /** Performs successive reboots and computes various boottime metrics */ 84 public class BootTimeTest extends InstalledInstrumentationsTest 85 implements IRemoteTest, 86 IDeviceTest, 87 IBuildReceiver, 88 IConfigurationReceiver, 89 IInvocationContextReceiver, 90 IMetricCollectorReceiver { 91 protected static final String ONLINE = "online"; 92 protected static final String BOOTTIME_TEST = "BootTimeTest"; 93 protected static final long INVALID_TIME_DURATION = -1; 94 95 private static final String SUCCESSIVE_BOOT_TEST = "SuccessiveBootTest"; 96 private static final String SUCCESSIVE_BOOT_UNLOCK_TEST = "SuccessiveBootUnlockTest"; 97 private static final String SUCCESSIVE_ONLINE = "successive-online"; 98 private static final String SUCCESSIVE_BOOT = "successive-boot"; 99 private static final String LOGCAT_CMD = "logcat *:V"; 100 private static final String LOGCAT_CMD_ALL = "logcat -b all *:V"; 101 private static final String LOGCAT_CMD_STATISTICS = "logcat --statistics --pid %d"; 102 private static final String LOGCAT_CMD_STATISTICS_ALL = "logcat --statistics"; 103 private static final long LOGCAT_SIZE = 80 * 1024 * 1024; 104 private static final String BOOT_COMPLETED_PROP = "getprop sys.boot_completed"; 105 private static final String BOOT_COMPLETED_VAL = "1"; 106 private static final String BOOT_TIME_PROP = "ro.boot.boottime"; 107 private static final String BOOTLOADER_PREFIX = "bootloader-"; 108 private static final String BOOTLOADER_TIME = "bootloader_time"; 109 private static final String LOGCAT_FILE = "Successive_reboots_logcat"; 110 private static final String LOGCAT_UNLOCK_FILE = "Successive_reboots_unlock_logcat"; 111 private static final String BOOT_COMPLETE_ACTION = "sys.boot_completed=1"; 112 private static final String RUNNER = "androidx.test.runner.AndroidJUnitRunner"; 113 private static final String PACKAGE_NAME = "com.android.boothelper"; 114 private static final String CLASS_NAME = "com.android.boothelper.BootHelperTest"; 115 private static final String SETUP_PIN_TEST = "setupLockScreenPin"; 116 private static final String UNLOCK_PIN_TEST = "unlockScreenWithPin"; 117 private static final String UNLOCK_TIME = "screen_unlocktime"; 118 private static final String F2FS_SHUTDOWN_COMMAND = "f2fs_io shutdown 4 /data"; 119 private static final String F2FS_SHUTDOWN_SUCCESS_OUTPUT = "Shutdown /data with level=4"; 120 private static final int BOOT_COMPLETE_POLL_INTERVAL = 1000; 121 private static final int BOOT_COMPLETE_POLL_RETRY_COUNT = 45; 122 private static final String ROOT = "root"; 123 private static final String DMESG_FILE = "/data/local/tmp/dmesglogs.txt"; 124 private static final String DUMP_DMESG = String.format("dmesg > %s", DMESG_FILE); 125 private static final String INIT = "init_"; 126 private static final String START_TIME = "_START_TIME"; 127 private static final String DURATION = "_DURATION"; 128 private static final String END_TIME = "_END_TIME"; 129 private static final String ACTION = "action_"; 130 private static final String INIT_STAGE = "init_stage_"; 131 /** logcat command for selinux, pinnerservice, fatal messages */ 132 private static final String LOGCAT_COMBINED_CMD = 133 "logcat -b all auditd:* PinnerService:* \\*:F"; 134 private static final String TOTAL_BOOT_TIME = "TOTAL_BOOT_TIME"; 135 private static final String BOOT_PHASE_1000 = "starting_phase_1000"; 136 private static final String METRIC_KEY_SEPARATOR = "_"; 137 private static final String LOGCAT_STATISTICS_SIZE = "logcat_statistics_size_bytes"; 138 private static final String LOGCAT_STATISTICS_DIFF_SIZE = 139 "logcat_statistics_size_bytes_dropped"; 140 private static final String DMESG_BOOT_COMPLETE_TIME = 141 "dmesg_action_sys.boot_completed_first_timestamp"; 142 private static final String MAKE_DIR = "mkdir %s"; 143 private static final String FOLDER_NAME_FORMAT = "sample_%s"; 144 private static final String RANDOM_FILE_CMD = "dd if=/dev/urandom of=%s bs=%d%s count=1"; 145 private static final String KB_IDENTIFIER = "k"; 146 private static final String MB_IDENTIFIER = "m"; 147 private static final String BYTES_TRANSFERRED = "bytes transferred"; 148 private static final String RM_DIR = "rm -rf %s"; 149 private static final String RAMDUMP_STATUS = "ramdump -s"; 150 private static final String BOOTLOADER_PHASE_SW = "SW"; 151 private static final String STORAGE_TYPE = "ro.boot.hardware.ufs"; 152 private static final String PERFETTO_TRACE_FILE_CHECK_CMD = "ls -l /data/misc/perfetto-traces"; 153 private static final String FINAL_PERFETTO_TRACE_LOCATION = "/data/local/tmp/%s.perfetto-trace"; 154 private static final String PERFETTO_TRACE_MV_CMD = 155 "mv /data/misc/perfetto-traces/boottrace.perfetto-trace %s"; 156 157 private static final String TIMESTAMP_PID = 158 "^(\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}.\\d{3})\\s+" + "(\\d+)\\s+(\\d+)\\s+([A-Z])\\s+"; 159 // 04-05 18:26:52.637 2161 2176 I BootHelperTest: Screen Unlocked 160 private static final String ALL_PROCESS_CMD = "ps -A"; 161 private static final Pattern SCREEN_UNLOCKED = 162 Pattern.compile(TIMESTAMP_PID + "(.+?)\\s*: Screen Unlocked$"); 163 // 04-05 18:26:54.320 1013 1121 I ActivityManager: Displayed 164 // com.google.android.apps.nexuslauncher/.NexusLauncherActivity: +648ms 165 private static final Pattern DISPLAYED_LAUNCHER = 166 Pattern.compile( 167 TIMESTAMP_PID 168 + "(.+?)\\s*: Displayed" 169 + " com.google.android.apps.nexuslauncher/.NexusLauncherActivity:" 170 + "\\s*(.*)$"); 171 /** Matches the line indicating kernel start. It is starting point of the whole boot process */ 172 private static final Pattern KERNEL_START_PATTERN = Pattern.compile("Linux version"); 173 /** Matches the logcat line indicating boot completed */ 174 private static final Pattern LOGCAT_BOOT_COMPLETED = Pattern.compile("Starting phase 1000"); 175 176 private static final Pattern LOGCAT_STATISTICS_HEADER_PATTERN = 177 Pattern.compile( 178 "^size\\/num\\s*(\\w+)\\s*(\\w+)\\s*(\\w+)\\s*(\\w+)\\s*(\\w+)*", 179 Pattern.CASE_INSENSITIVE); 180 private static final Pattern LOGCAT_STATISTICS_TOTAL_PATTERN = 181 Pattern.compile( 182 "Total\\s*(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+)\\s*" 183 + "(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+).*", 184 Pattern.CASE_INSENSITIVE); 185 private static final Pattern LOGCAT_STATISTICS_NOW_PATTERN = 186 Pattern.compile( 187 "Now\\s+(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+)\\s*" 188 + "(\\d+)\\/(\\d+)\\s*(\\d+)\\/(\\d+).*", 189 Pattern.CASE_INSENSITIVE); 190 private static final Pattern LOGCAT_STATISTICS_PID_PATTERN = 191 Pattern.compile( 192 "Logging for this PID.*\\s+([0-9]+)$", 193 Pattern.CASE_INSENSITIVE | Pattern.MULTILINE | Pattern.DOTALL); 194 195 private static final String METRIC_COUNT = "MetricCount"; 196 197 @Option(name = "test-run-name", description = "run name to report to result reporters") 198 private String mTestRunName = BOOTTIME_TEST; 199 200 @Option(name = "device-boot-time", description = "Max time in ms to wait for device to boot.") 201 protected long mDeviceBootTime = 5 * 60 * 1000; 202 203 @Option( 204 name = "first-boot", 205 description = "Calculate the boot time metrics after flashing the device") 206 private boolean mFirstBoot = true; 207 208 @Option( 209 name = "successive-boot-prepare-cmd", 210 description = 211 "A list of adb commands to run after first boot to prepare for successive" 212 + " boot tests") 213 private List<String> mDeviceSetupCommands = new ArrayList<>(); 214 215 @Option( 216 name = "test-file-name", 217 description = 218 "Name of a apk in expanded test zip to install on device. Can be repeated.", 219 importance = Importance.IF_UNSET) 220 private List<File> mTestFileNames = new ArrayList<>(); 221 222 @Option(name = "successive-boot", description = "Calculate the successive boot delay info") 223 private boolean mSuccessiveBoot = false; 224 225 @Option( 226 name = "boot-count", 227 description = 228 "Number of times to boot the devices to calculate the successive boot delay." 229 + " Second boot after the first boot will be skipped for correctness.") 230 private int mBootCount = 5; 231 232 @Option( 233 name = "boot-delay", 234 isTimeVal = true, 235 description = "Time to wait between the successive boots.") 236 private long mBootDelayTime = 2000; 237 238 @Option( 239 name = "after-boot-delay", 240 isTimeVal = true, 241 description = "Time to wait immediately after the successive boots.") 242 private long mAfterBootDelayTime = 0; 243 244 @Option( 245 name = "post-initial-boot-idle", 246 isTimeVal = true, 247 description = 248 "Time to keep device idle after the initial boot up. This can help stablize " 249 + "certain metrics like detecting post boot crashes and " 250 + "SELinux denials.") 251 private long mPostInitialBootIdle = 0L; 252 253 @Option( 254 name = "granular-boot-info", 255 description = "Parse the granular timing info from successive boot time.") 256 private boolean mGranularBootInfo = false; 257 258 @Option( 259 name = "boot-time-pattern", 260 description = 261 "Named boot time regex patterns which are used to capture signals in logcat and" 262 + " calculate duration between device boot to the signal being logged." 263 + " Key: name of custom boot metric, Value: regex to match single" 264 + " logcat line. Maybe repeated.") 265 private Map<String, String> mBootTimePatterns = new HashMap<>(); 266 267 @Option(name = "dmesg-info", description = "Collect the init services info from dmesg logs.") 268 private boolean mDmesgInfo = false; 269 270 // Use this flag not to dump the dmesg logs immediately after the device is online. 271 // Use it only if some of the boot dmesg logs are cleared when waiting until boot completed. 272 // By default this is set to true which might result in duplicate logging. 273 @Option( 274 name = "dump-dmesg-immediate", 275 description = 276 "Whether to dump the dmesg logs" + "immediately after the device is online") 277 private boolean mDumpDmesgImmediate = true; 278 279 @Option(name = "bootloader-info", description = "Collect the boot loader timing.") 280 private boolean mBootloaderInfo = false; 281 282 @Option( 283 name = "report-storage-suffix-metric", 284 description = "separately report boot time" + " results for storage type") 285 private boolean mReportStorageSuffixMetric = false; 286 287 @Option( 288 name = "report-boottime-per-iteration", 289 description = "separately report boot time results per iteration") 290 private boolean mBootTimePerIteration = true; 291 292 // 03-10 21:43:40.328 1005 1005 D SystemServerTiming:StartWifi took to 293 // complete: 3474ms 294 // 03-10 21:43:40.328 1005 1005 D component:subcomponent took to complete: 295 // 3474ms 296 @Option( 297 name = "components", 298 shortName = 'c', 299 description = 300 "Comma separated list of component names to parse the granular boot info" 301 + " printed in the logcat.") 302 private String mComponentNames = null; 303 304 @Option( 305 name = "full-components", 306 shortName = 'f', 307 description = 308 "Comma separated list of component_subcomponent names to parse the granular" 309 + " boot info printed in the logcat.") 310 private String mFullCompNames = null; 311 312 @Option( 313 name = "test-reboot-unlock", 314 description = "Test the reboot scenario with" + "screen unlock.") 315 private boolean mRebootUnlock = false; 316 317 @Option( 318 name = "force-f2fs-shutdown", 319 description = "Force f2fs shutdown to trigger fsck check during the reboot.") 320 private boolean mForceF2FsShutdown = false; 321 322 @Option( 323 name = "skip-pin-setup", 324 description = 325 "Skip the pin setup if already set once" 326 + "and not needed for the second run especially in local testing.") 327 private boolean mSkipPinSetup = false; 328 329 @Option( 330 name = "collect-logcat-info", 331 description = "Run logcat --statistics command and collect data") 332 private boolean mCollectLogcat = false; 333 334 @Option( 335 name = "metric-prefix-pattern-for-count", 336 description = 337 "A list of metric prefix pattern that will be used to count number of metrics" 338 + " generated in the test") 339 private List<String> mMetricPrefixPatternForCount = new ArrayList<>(); 340 341 private IBuildInfo mBuildInfo; 342 private IConfiguration mConfiguration; 343 private TestInformation mTestInfo; 344 private Map<String, List<Double>> mBootInfo = new LinkedHashMap<>(); 345 private Map<String, Double> mBootIterationInfo = new LinkedHashMap<>(); 346 private LogcatReceiver mRebootLogcatReceiver = null; 347 protected String mExtraFirstBootError = null; 348 private IRemoteAndroidTestRunner mRunner = null; 349 private Set<String> mParsedLines = new HashSet<String>(); 350 private List<String> mInstalledPackages = new ArrayList<String>(); 351 private IInvocationContext mInvocationContext = null; 352 private List<IMetricCollector> mCollectors = new ArrayList<>(); 353 354 /** {@inheritDoc} */ 355 @Override setBuild(IBuildInfo buildInfo)356 public void setBuild(IBuildInfo buildInfo) { 357 mBuildInfo = buildInfo; 358 } 359 360 /** {@inheritDoc} */ 361 @Override setConfiguration(IConfiguration configuration)362 public void setConfiguration(IConfiguration configuration) { 363 // Ensure the configuration is set on InstalledInstrumentationsTest 364 super.setConfiguration(configuration); 365 mConfiguration = configuration; 366 } 367 getTestInformation()368 public TestInformation getTestInformation() { 369 return mTestInfo; 370 } 371 372 @VisibleForTesting setRebootLogcatReceiver(LogcatReceiver receiver)373 void setRebootLogcatReceiver(LogcatReceiver receiver) { 374 mRebootLogcatReceiver = receiver; 375 } 376 377 @VisibleForTesting setDmesgBootCompleteTime(List<Double> bootCompleteTime)378 void setDmesgBootCompleteTime(List<Double> bootCompleteTime) { 379 mBootInfo.put(DMESG_BOOT_COMPLETE_TIME, bootCompleteTime); 380 } 381 382 @VisibleForTesting setDmesgBootIterationTime(Double bootCompleteTime)383 void setDmesgBootIterationTime(Double bootCompleteTime) { 384 mBootIterationInfo.put(DMESG_BOOT_COMPLETE_TIME, bootCompleteTime); 385 } 386 387 @VisibleForTesting getBootMetricValues(String bootMetricKey)388 List<Double> getBootMetricValues(String bootMetricKey) { 389 return mBootInfo.getOrDefault(bootMetricKey, new ArrayList<>()); 390 } 391 392 @Override setMetricCollectors(List<IMetricCollector> collectors)393 public void setMetricCollectors(List<IMetricCollector> collectors) { 394 mCollectors = collectors; 395 } 396 397 @Override setInvocationContext(IInvocationContext invocationContext)398 public void setInvocationContext(IInvocationContext invocationContext) { 399 mInvocationContext = invocationContext; 400 } 401 402 /** Returns the {@link IBuildInfo} for the test. */ getBuildInfo()403 public IBuildInfo getBuildInfo() { 404 return mBuildInfo; 405 } 406 407 /** Returns the {@link IRunUtil} instance to use to run some command. */ getRunUtil()408 public IRunUtil getRunUtil() { 409 return RunUtil.getDefault(); 410 } 411 412 /** {@inheritDoc} */ 413 @Override run(TestInformation testInfo, ITestInvocationListener listener)414 public void run(TestInformation testInfo, ITestInvocationListener listener) 415 throws DeviceNotAvailableException { 416 mTestInfo = testInfo; 417 long start = System.currentTimeMillis(); 418 listener.testRunStarted(mTestRunName, mBootCount + 1); 419 for (IMetricCollector collector : mCollectors) { 420 listener = collector.init(mInvocationContext, listener); 421 } 422 try { 423 try { 424 // Set the current date from the host in test device. 425 getDevice().setDate(null); 426 427 // Setup device for successive boots, e.g. dismiss SuW 428 setupDeviceForSuccessiveBoots(); 429 430 Map<String, String> successiveResult = new HashMap<>(); 431 boolean isSuccessiveBootsSuccess = true; 432 TestDescription successiveBootTestId = 433 new TestDescription( 434 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 435 SUCCESSIVE_BOOT_TEST); 436 try { 437 // Skip second boot from successive boot delay calculation 438 doSecondBoot(); 439 testSuccessiveBoots(false, listener); 440 // Reports average value of individual metrics collected 441 listener.testStarted(successiveBootTestId); 442 } catch (RuntimeException re) { 443 CLog.e(re); 444 isSuccessiveBootsSuccess = false; 445 listener.testStarted(successiveBootTestId); 446 listener.testFailed( 447 successiveBootTestId, 448 String.format("RuntimeException during successive reboots: %s", re)); 449 } catch (DeviceNotAvailableException dnae) { 450 CLog.e("Device not available after successive reboots"); 451 CLog.e(dnae); 452 isSuccessiveBootsSuccess = false; 453 listener.testStarted(successiveBootTestId); 454 listener.testFailed( 455 successiveBootTestId, 456 String.format( 457 "Device not available after successive reboots; %s", dnae)); 458 } finally { 459 if (isSuccessiveBootsSuccess) { 460 if (null != mRebootLogcatReceiver) { 461 try (InputStreamSource logcatData = 462 mRebootLogcatReceiver.getLogcatData()) { 463 listener.testLog(LOGCAT_FILE, LogDataType.TEXT, logcatData); 464 } 465 mRebootLogcatReceiver.stop(); 466 } 467 listener.testEnded(successiveBootTestId, successiveResult); 468 // Report separately the hardware Storage specific boot time results. 469 if (!successiveResult.isEmpty() && mReportStorageSuffixMetric) { 470 reportStorageSpecificMetrics(listener, successiveResult); 471 } 472 } else { 473 listener.testEnded(successiveBootTestId, successiveResult); 474 } 475 } 476 477 // Test to measure the reboot time and time from unlocking the 478 // screen using the pin 479 // till the NexusLauncherActivity is displayed. 480 if (mRebootUnlock) { 481 mBootInfo.clear(); 482 Map<String, String> successiveBootUnlockResult = new HashMap<>(); 483 TestDescription successiveBootUnlockTestId = 484 new TestDescription( 485 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 486 SUCCESSIVE_BOOT_UNLOCK_TEST); 487 try { 488 // If pin is already set skip the setup method otherwise 489 // setup the pin. 490 if (!mSkipPinSetup) { 491 mRunner = createRemoteAndroidTestRunner(SETUP_PIN_TEST); 492 getDevice() 493 .runInstrumentationTests(mRunner, new CollectingTestListener()); 494 } 495 testSuccessiveBoots(true, listener); 496 } finally { 497 if (null != mRebootLogcatReceiver) { 498 try (InputStreamSource logcatData = 499 mRebootLogcatReceiver.getLogcatData()) { 500 listener.testLog(LOGCAT_UNLOCK_FILE, LogDataType.TEXT, logcatData); 501 } 502 mRebootLogcatReceiver.stop(); 503 } 504 listener.testStarted(successiveBootUnlockTestId); 505 listener.testEnded(successiveBootUnlockTestId, successiveBootUnlockResult); 506 } 507 } 508 } finally { 509 // Finish run for boot test. Health check below will start its own test run. 510 listener.testRunEnded( 511 System.currentTimeMillis() - start, new HashMap<String, Metric>()); 512 } 513 } finally { 514 finalTearDown(listener); 515 } 516 } 517 518 /** Final optional tear down step for the Boot test. */ finalTearDown(ITestInvocationListener listener)519 public void finalTearDown(ITestInvocationListener listener) throws DeviceNotAvailableException { 520 // empty on purpose 521 } 522 523 /** 524 * Look for the perfetto trace file collected during reboot under /data/misc/perfetto-traces and 525 * copy the file under /data/local/tmp using the test iteration name and return the path to the 526 * newly copied trace file. 527 */ processPerfettoFile(String testId)528 private String processPerfettoFile(String testId) throws DeviceNotAvailableException { 529 CommandResult result = getDevice().executeShellV2Command(PERFETTO_TRACE_FILE_CHECK_CMD); 530 if (result != null) { 531 CLog.i( 532 "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s", 533 PERFETTO_TRACE_FILE_CHECK_CMD, 534 result.getStdout(), 535 result.getStderr(), 536 result.getStatus()); 537 if (CommandStatus.SUCCESS.equals(result.getStatus()) 538 && result.getStdout().contains("boottrace.perfetto-trace")) { 539 // Move the perfetto trace file to the new location and rename it using the test 540 // name. 541 String finalTraceFileLocation = 542 String.format(FINAL_PERFETTO_TRACE_LOCATION, testId); 543 CommandResult moveResult = 544 getDevice() 545 .executeShellV2Command( 546 String.format( 547 PERFETTO_TRACE_MV_CMD, finalTraceFileLocation)); 548 if (moveResult != null) { 549 CLog.i( 550 "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s", 551 PERFETTO_TRACE_MV_CMD, 552 moveResult.getStdout(), 553 moveResult.getStderr(), 554 moveResult.getStatus()); 555 if (CommandStatus.SUCCESS.equals(result.getStatus())) { 556 return finalTraceFileLocation; 557 } 558 } 559 } 560 } 561 return null; 562 } 563 setupDeviceForSuccessiveBoots()564 private void setupDeviceForSuccessiveBoots() throws DeviceNotAvailableException { 565 // Run the list of post first boot setup commands 566 for (String cmd : mDeviceSetupCommands) { 567 CommandResult result; 568 result = getDevice().executeShellV2Command(cmd); 569 if (!CommandStatus.SUCCESS.equals(result.getStatus())) { 570 CLog.w( 571 "Post boot setup cmd: '%s' failed, returned:\nstdout:%s\nstderr:%s", 572 cmd, result.getStdout(), result.getStderr()); 573 } 574 } 575 } 576 577 /** Do the second boot on the device to exclude from the successive boot time calculations */ doSecondBoot()578 private void doSecondBoot() throws DeviceNotAvailableException { 579 getDevice().nonBlockingReboot(); 580 getDevice().waitForDeviceOnline(); 581 getDevice().waitForDeviceAvailable(mDeviceBootTime); 582 } 583 584 /** 585 * Clear the existing logs and start capturing the logcat 586 * 587 * <p>It will record from all logcat buffers if user provided any custom boot time metric 588 * patterns 589 */ clearAndStartLogcat()590 private void clearAndStartLogcat() throws DeviceNotAvailableException { 591 getDevice().executeShellCommand("logcat -c"); 592 boolean allBuffers = !mBootTimePatterns.isEmpty(); 593 if (mRebootLogcatReceiver == null) { 594 mRebootLogcatReceiver = 595 new LogcatReceiver( 596 getDevice(), allBuffers ? LOGCAT_CMD_ALL : LOGCAT_CMD, LOGCAT_SIZE, 0); 597 } 598 mRebootLogcatReceiver.start(); 599 } 600 601 /** 602 * To perform the successive boot for given boot count and take the average of boot time and 603 * online time delays 604 * 605 * @param dismissPin to dismiss pin after reboot 606 */ testSuccessiveBoots(boolean dismissPin, ITestInvocationListener listener)607 private void testSuccessiveBoots(boolean dismissPin, ITestInvocationListener listener) 608 throws DeviceNotAvailableException { 609 CLog.v("Waiting for %d msecs before successive boots.", mBootDelayTime); 610 getRunUtil().sleep(mBootDelayTime); 611 for (int count = 0; count < mBootCount; count++) { 612 getDevice().enableAdbRoot(); 613 // Property used for collecting the perfetto trace file on boot. 614 getDevice().executeShellCommand("setprop persist.debug.perfetto.boottrace 1"); 615 // Attempt to shurdown F2FS if the option is enabled. 616 if (mForceF2FsShutdown) { 617 String output = getDevice().executeShellCommand(F2FS_SHUTDOWN_COMMAND).trim(); 618 if (!F2FS_SHUTDOWN_SUCCESS_OUTPUT.equalsIgnoreCase(output)) { 619 CLog.e("Unable to shutdown the F2FS."); 620 } else { 621 CLog.i("F2FS shutdown successful."); 622 } 623 } 624 625 DmesgParser dmesgLogParser = null; 626 double bootStart = INVALID_TIME_DURATION; 627 double onlineTime = INVALID_TIME_DURATION; 628 double bootTime = INVALID_TIME_DURATION; 629 String testId = String.format("%s.%s$%d", BOOTTIME_TEST, BOOTTIME_TEST, (count + 1)); 630 TestDescription successiveBootIterationTestId; 631 if (!dismissPin) { 632 successiveBootIterationTestId = 633 new TestDescription(testId, String.format("%s", SUCCESSIVE_BOOT_TEST)); 634 } else { 635 successiveBootIterationTestId = 636 new TestDescription( 637 testId, String.format("%s", SUCCESSIVE_BOOT_UNLOCK_TEST)); 638 } 639 if (mGranularBootInfo || dismissPin) { 640 clearAndStartLogcat(); 641 getRunUtil().sleep(5000); 642 } 643 getDevice().nonBlockingReboot(); 644 bootStart = System.currentTimeMillis(); 645 getDevice().waitForDeviceOnline(); 646 onlineTime = System.currentTimeMillis() - bootStart; 647 getDevice().enableAdbRoot(); 648 dmesgLogParser = new DmesgParser(); 649 if (mDmesgInfo && mDumpDmesgImmediate) { 650 // Collect the dmesg logs after device is online and 651 // after the device is boot completed to avoid losing the 652 // initial logs in some devices. 653 parseDmesgInfo(dmesgLogParser); 654 } 655 try { 656 waitForBootCompleted(); 657 } catch (InterruptedException e) { 658 CLog.e("Sleep Interrupted"); 659 CLog.e(e); 660 } catch (DeviceNotAvailableException dne) { 661 CLog.e("Device not available"); 662 CLog.e(dne); 663 } 664 bootTime = System.currentTimeMillis() - bootStart; 665 if (mDmesgInfo) { 666 // Collect the dmesg logs after device is online and 667 // after the device is boot completed to avoid losing the 668 // initial logs. 669 parseDmesgInfo(dmesgLogParser); 670 if (!dmesgLogParser.getServiceInfoItems().isEmpty()) { 671 analyzeDmesgServiceInfo(dmesgLogParser.getServiceInfoItems().values()); 672 } 673 if (!dmesgLogParser.getStageInfoItems().isEmpty()) { 674 analyzeDmesgStageInfo(dmesgLogParser.getStageInfoItems()); 675 } 676 if (!dmesgLogParser.getActionInfoItems().isEmpty()) { 677 analyzeDmesgActionInfo(dmesgLogParser.getActionInfoItems()); 678 } 679 } 680 681 // Parse logcat info 682 Map<String, String> collectLogcatInfoResult = new HashMap<>(); 683 if (mCollectLogcat) { 684 collectLogcatInfoResult.putAll(collectLogcatInfo()); 685 } 686 687 // Parse bootloader timing info 688 if (mBootloaderInfo) analyzeBootloaderTimingInfo(); 689 690 if (dismissPin) { 691 getRunUtil().sleep(2000); 692 mRunner = createRemoteAndroidTestRunner(UNLOCK_PIN_TEST); 693 getDevice().runInstrumentationTests(mRunner, new CollectingTestListener()); 694 } 695 696 if (mBootTimePerIteration) { 697 listener.testStarted(successiveBootIterationTestId); 698 } 699 700 CLog.v("Waiting for %d msecs immediately after successive boot.", mAfterBootDelayTime); 701 getRunUtil().sleep(mAfterBootDelayTime); 702 if (onlineTime != INVALID_TIME_DURATION) { 703 if (mBootInfo.containsKey(SUCCESSIVE_ONLINE)) { 704 mBootInfo.get(SUCCESSIVE_ONLINE).add(onlineTime); 705 } else { 706 List<Double> onlineDelayList = new ArrayList<Double>(); 707 onlineDelayList.add(onlineTime); 708 mBootInfo.put(SUCCESSIVE_ONLINE, onlineDelayList); 709 } 710 mBootIterationInfo.put(SUCCESSIVE_ONLINE, onlineTime); 711 } 712 if (bootTime != INVALID_TIME_DURATION) { 713 if (mBootInfo.containsKey(SUCCESSIVE_BOOT)) { 714 mBootInfo.get(SUCCESSIVE_BOOT).add(bootTime); 715 } else { 716 List<Double> bootDelayList = new ArrayList<>(); 717 bootDelayList.add(bootTime); 718 mBootInfo.put(SUCCESSIVE_BOOT, bootDelayList); 719 } 720 mBootIterationInfo.put(SUCCESSIVE_BOOT, bootTime); 721 } 722 if (mGranularBootInfo) { 723 getRunUtil().sleep(15000); 724 analyzeGranularBootInfo(); 725 analyzeCustomBootInfo(); 726 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData()) { 727 listener.testLog( 728 String.format("%s_%d", LOGCAT_FILE, (count + 1)), 729 LogDataType.TEXT, 730 logcatData); 731 } 732 if (count != (mBootCount - 1)) { 733 mRebootLogcatReceiver.stop(); 734 mRebootLogcatReceiver = null; 735 } 736 } 737 if (dismissPin) { 738 analyzeUnlockBootInfo(); 739 if (count != (mBootCount - 1)) { 740 mRebootLogcatReceiver.stop(); 741 mRebootLogcatReceiver = null; 742 } 743 } 744 745 String perfettoTraceFilePath = 746 processPerfettoFile( 747 String.format( 748 "%s_%s", 749 successiveBootIterationTestId.getClassName().replace("$", "_"), 750 successiveBootIterationTestId.getTestName())); 751 752 if (mBootTimePerIteration) { 753 Map<String, String> iterationResult = new HashMap<>(); 754 for (Map.Entry<String, Double> bootData : mBootIterationInfo.entrySet()) { 755 iterationResult.put(bootData.getKey(), bootData.getValue().toString()); 756 } 757 if (perfettoTraceFilePath != null) { 758 iterationResult.put("perfetto_file_path", perfettoTraceFilePath); 759 } 760 if (!collectLogcatInfoResult.isEmpty()) { 761 iterationResult.putAll(collectLogcatInfoResult); 762 } 763 // If metric-prefix-pattern-for-count is present, calculate the count 764 // of all metrics with the prefix pattern and add the count as a new metric to the 765 // iterationResult map. 766 if (!mMetricPrefixPatternForCount.isEmpty()) { 767 for (String metricPrefixPattern : mMetricPrefixPatternForCount) { 768 long metricCount = 769 iterationResult.entrySet().stream() 770 .filter( 771 (entry) -> 772 entry.getKey() 773 .startsWith(metricPrefixPattern)) 774 .count(); 775 iterationResult.put( 776 metricPrefixPattern + METRIC_COUNT, Long.toString(metricCount)); 777 } 778 } 779 listener.testEnded(successiveBootIterationTestId, iterationResult); 780 } 781 782 mBootIterationInfo.clear(); 783 CLog.v("Waiting for %d msecs after boot completed.", mBootDelayTime); 784 getRunUtil().sleep(mBootDelayTime); 785 } 786 } 787 788 /** Get the logcat statistics info */ collectLogcatInfo()789 private Map<String, String> collectLogcatInfo() throws DeviceNotAvailableException { 790 Map<String, String> results = new HashMap<>(); 791 // Parse logcat in global level 792 results.putAll(extractLogcatInfo("general")); 793 return results; 794 } 795 796 /** Get the logcat statistics info */ extractLogcatInfo(String processName)797 private Map<String, String> extractLogcatInfo(String processName) 798 throws DeviceNotAvailableException { 799 Map<String, String> results = new HashMap<>(); 800 String runCommand = LOGCAT_CMD_STATISTICS_ALL; 801 String output = getDevice().executeShellCommand(runCommand); 802 String[] outputList = output.split("\\n\\n"); 803 804 // General statistics 805 // Sample output for $ logcat --statistics 806 // size/num main system crash kernel Total 807 // Total 33/23 96/91 3870/4 70/1 513/41 808 // Now 92/70 4/15 0/0 13/11 33/26 809 // Logspan 5:15:15.15 11d 20:37:31.37 13:20:54.185 11d 20:40:06.816 810 // Overhead 253454 56415 255139 1330477 811 Matcher matcherHeader = LOGCAT_STATISTICS_HEADER_PATTERN.matcher(outputList[0]); 812 Matcher matcherTotal = LOGCAT_STATISTICS_TOTAL_PATTERN.matcher(outputList[0]); 813 Matcher matcherNow = LOGCAT_STATISTICS_NOW_PATTERN.matcher(outputList[0]); 814 boolean headerFound = matcherHeader.find(); 815 boolean totalFound = matcherTotal.find(); 816 boolean nowFound = matcherNow.find(); 817 if (headerFound && totalFound && nowFound) { 818 // There are 6 columns in the output, but we just want to extract column 1 to 4 819 for (int i = 1; i < 5; i++) { 820 String bufferHeader = matcherHeader.group(i).trim(); 821 results.put( 822 String.join( 823 METRIC_KEY_SEPARATOR, 824 LOGCAT_STATISTICS_SIZE, 825 bufferHeader, 826 processName), 827 matcherTotal.group(i * 2 - 1).trim()); 828 results.put( 829 String.join( 830 METRIC_KEY_SEPARATOR, 831 LOGCAT_STATISTICS_DIFF_SIZE, 832 bufferHeader, 833 processName), 834 Integer.toString( 835 Integer.valueOf(matcherTotal.group(i * 2 - 1).trim()) 836 - Integer.valueOf(matcherNow.group(i * 2 - 1).trim()))); 837 } 838 } 839 return results; 840 } 841 842 /** 843 * Parse the logcat file for granular boot info (eg different system services start time) based 844 * on the component name or full component name (i.e component_subcompname) 845 */ analyzeGranularBootInfo()846 private void analyzeGranularBootInfo() { 847 String[] compStr = new String[0]; 848 String[] fullCompStr = new String[0]; 849 boolean isFilterSet = false; 850 851 if (null != mComponentNames) { 852 compStr = mComponentNames.split(","); 853 isFilterSet = true; 854 } 855 if (null != mFullCompNames) { 856 fullCompStr = mFullCompNames.split(","); 857 isFilterSet = true; 858 } 859 860 Set<String> compSet = new HashSet<>(Arrays.asList(compStr)); 861 Set<String> fullCompSet = new HashSet<>(Arrays.asList(fullCompStr)); 862 863 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 864 InputStream logcatStream = logcatData.createInputStream(); 865 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 866 BufferedReader br = new BufferedReader(logcatReader)) { 867 868 TimingsLogParser parser = new TimingsLogParser(); 869 List<SystemServicesTimingItem> items = parser.parseSystemServicesTimingItems(br); 870 for (SystemServicesTimingItem item : items) { 871 String componentName = item.getComponent(); 872 String fullCompName = 873 String.format("%s_%s", item.getComponent(), item.getSubcomponent()); 874 // If filter not set then capture timing info for all the 875 // components otherwise 876 // only for the given component names and full component 877 // names. 878 if (!isFilterSet 879 || compSet.contains(componentName) 880 || fullCompSet.contains(fullCompName)) { 881 Double time = 882 item.getDuration() != null ? item.getDuration() : item.getStartTime(); 883 if (time == null) { 884 continue; 885 } 886 if (mBootInfo.containsKey(fullCompName)) { 887 mBootInfo.get(fullCompName).add(time); 888 } else { 889 List<Double> delayList = new ArrayList<>(); 890 delayList.add(time); 891 mBootInfo.put(fullCompName, delayList); 892 } 893 mBootIterationInfo.put(fullCompName, time); 894 } 895 } 896 } catch (IOException ioe) { 897 CLog.e("Problem in parsing the granular boot delay information"); 898 CLog.e(ioe); 899 } 900 } 901 902 /** Parse the logcat file to get boot time metrics given patterns defined by tester. */ analyzeCustomBootInfo()903 private void analyzeCustomBootInfo() { 904 if (mBootTimePatterns.isEmpty()) return; 905 Double dmesgBootCompleteTimes; 906 TimingsLogParser parser = new TimingsLogParser(); 907 parser.addDurationPatternPair(BOOT_PHASE_1000, KERNEL_START_PATTERN, LOGCAT_BOOT_COMPLETED); 908 for (Map.Entry<String, String> pattern : mBootTimePatterns.entrySet()) { 909 CLog.d( 910 "Adding boot metric with name: %s, pattern: %s", 911 pattern.getKey(), pattern.getValue()); 912 parser.addDurationPatternPair( 913 pattern.getKey(), KERNEL_START_PATTERN, Pattern.compile(pattern.getValue())); 914 } 915 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 916 InputStream logcatStream = logcatData.createInputStream(); 917 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 918 BufferedReader br = new BufferedReader(logcatReader)) { 919 920 if (mBootIterationInfo.containsKey(DMESG_BOOT_COMPLETE_TIME)) { 921 dmesgBootCompleteTimes = mBootIterationInfo.get(DMESG_BOOT_COMPLETE_TIME); 922 } else { 923 CLog.d("Missing dmesg boot complete signals"); 924 return; 925 } 926 927 List<GenericTimingItem> items = parser.parseGenericTimingItems(br); 928 929 Map<String, GenericTimingItem> itemsMap = new HashMap<>(); 930 GenericTimingItem logcatBootCompleteItem = new GenericTimingItem(); 931 for (GenericTimingItem item : items) { 932 if (BOOT_PHASE_1000.equals(item.getName())) { 933 logcatBootCompleteItem = item; 934 } else { 935 itemsMap.put(item.getName(), item); 936 } 937 } 938 if (logcatBootCompleteItem.getName() == null) { 939 CLog.e("Missing boot complete signals from logcat"); 940 return; 941 } 942 for (Map.Entry<String, GenericTimingItem> metric : itemsMap.entrySet()) { 943 GenericTimingItem itemsForMetric = metric.getValue(); 944 if (itemsForMetric.getName().isEmpty()) { 945 CLog.e("Missing value for metric %s", metric.getKey()); 946 continue; 947 } 948 List<Double> values = mBootInfo.getOrDefault(metric.getKey(), new ArrayList<>()); 949 double duration = 950 dmesgBootCompleteTimes 951 + itemsForMetric.getEndTime() 952 - logcatBootCompleteItem.getEndTime(); 953 values.add(duration); 954 mBootInfo.put(metric.getKey(), values); 955 mBootIterationInfo.put(metric.getKey(), duration); 956 CLog.d("Added boot metric: %s with duration values: %s", metric.getKey(), values); 957 } 958 } catch (IOException e) { 959 CLog.e("Problem when parsing custom boot time info"); 960 CLog.e(e); 961 } 962 } 963 964 /** 965 * Collect the dmesg logs and parse the service info(start and end time), start time of boot 966 * stages and actions being processed, logged in the dmesg file. 967 */ parseDmesgInfo(DmesgParser dmesgLogParser)968 private void parseDmesgInfo(DmesgParser dmesgLogParser) throws DeviceNotAvailableException { 969 // Dump the dmesg logs to a file in the device 970 getDevice().executeShellCommand(DUMP_DMESG); 971 try { 972 File dmesgFile = getDevice().pullFile(DMESG_FILE); 973 BufferedReader input = 974 new BufferedReader(new InputStreamReader(new FileInputStream(dmesgFile))); 975 dmesgLogParser.parseInfo(input); 976 dmesgFile.delete(); 977 } catch (IOException ioe) { 978 CLog.e("Failed to analyze the dmesg logs", ioe); 979 } 980 } 981 982 /** 983 * Analyze the services info parsed from the dmesg logs and construct the metrics as a part of 984 * boot time data. 985 * 986 * @param serviceInfoItems contains the start time, end time and the duration of each service 987 * logged in the dmesg log file. 988 */ analyzeDmesgServiceInfo(Collection<DmesgServiceInfoItem> serviceInfoItems)989 private void analyzeDmesgServiceInfo(Collection<DmesgServiceInfoItem> serviceInfoItems) { 990 for (DmesgServiceInfoItem infoItem : serviceInfoItems) { 991 if (infoItem.getStartTime() != null) { 992 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), START_TIME); 993 if (mBootInfo.get(key) != null) { 994 mBootInfo.get(key).add(infoItem.getStartTime().doubleValue()); 995 } else { 996 List<Double> timeList = new ArrayList<Double>(); 997 timeList.add(infoItem.getStartTime().doubleValue()); 998 mBootInfo.put(key, timeList); 999 } 1000 mBootIterationInfo.put(key, infoItem.getStartTime().doubleValue()); 1001 } 1002 if (infoItem.getServiceDuration() != -1L) { 1003 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), DURATION); 1004 if (mBootInfo.get(key) != null) { 1005 mBootInfo.get(key).add(infoItem.getServiceDuration().doubleValue()); 1006 } else { 1007 List<Double> timeList = new ArrayList<Double>(); 1008 timeList.add(infoItem.getServiceDuration().doubleValue()); 1009 mBootInfo.put(key, timeList); 1010 } 1011 mBootIterationInfo.put(key, infoItem.getServiceDuration().doubleValue()); 1012 } 1013 if (infoItem.getEndTime() != null) { 1014 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), END_TIME); 1015 if (mBootInfo.get(key) != null) { 1016 mBootInfo.get(key).add(infoItem.getEndTime().doubleValue()); 1017 } else { 1018 List<Double> timeList = new ArrayList<Double>(); 1019 timeList.add(infoItem.getEndTime().doubleValue()); 1020 mBootInfo.put(key, timeList); 1021 } 1022 mBootIterationInfo.put(key, infoItem.getEndTime().doubleValue()); 1023 } 1024 } 1025 } 1026 1027 /** 1028 * Analyze the boot stages info parsed from the dmesg logs and construct the metrics as a part 1029 * of boot time data. 1030 * 1031 * @param stageInfoItems contains the start time of each stage logged in the dmesg log file. 1032 */ analyzeDmesgStageInfo(Collection<DmesgStageInfoItem> stageInfoItems)1033 private void analyzeDmesgStageInfo(Collection<DmesgStageInfoItem> stageInfoItems) { 1034 for (DmesgStageInfoItem stageInfoItem : stageInfoItems) { 1035 if (stageInfoItem.getStartTime() != null) { 1036 String key = 1037 String.format( 1038 "%s%s%s", INIT_STAGE, stageInfoItem.getStageName(), START_TIME); 1039 List<Double> values = mBootInfo.getOrDefault(key, new ArrayList<>()); 1040 values.add(stageInfoItem.getStartTime().doubleValue()); 1041 mBootInfo.put(key, values); 1042 mBootIterationInfo.put(key, stageInfoItem.getStartTime().doubleValue()); 1043 } else if (stageInfoItem.getDuration() != null) { 1044 List<Double> values = 1045 mBootInfo.getOrDefault(stageInfoItem.getStageName(), new ArrayList<>()); 1046 values.add(stageInfoItem.getDuration().doubleValue()); 1047 mBootInfo.put(stageInfoItem.getStageName(), values); 1048 mBootIterationInfo.put( 1049 stageInfoItem.getStageName(), stageInfoItem.getDuration().doubleValue()); 1050 } 1051 } 1052 } 1053 1054 /** 1055 * Analyze each action info parsed from the dmesg logs and construct the metrics as a part of 1056 * boot time data. 1057 * 1058 * @param actionInfoItems contains the start time of processing of each action logged in the 1059 * dmesg log file. 1060 */ analyzeDmesgActionInfo(Collection<DmesgActionInfoItem> actionInfoItems)1061 private void analyzeDmesgActionInfo(Collection<DmesgActionInfoItem> actionInfoItems) { 1062 boolean isFirstBootCompletedAction = true; 1063 for (DmesgActionInfoItem actionInfoItem : actionInfoItems) { 1064 if (actionInfoItem.getStartTime() != null) { 1065 if (actionInfoItem.getActionName().startsWith(BOOT_COMPLETE_ACTION) 1066 && isFirstBootCompletedAction) { 1067 CLog.i( 1068 "Using Action: %s_%s for first boot complete timestamp :%s", 1069 actionInfoItem.getActionName(), 1070 actionInfoItem.getSourceName(), 1071 actionInfoItem.getStartTime().doubleValue()); 1072 // Record the first boot complete time stamp. 1073 List<Double> dmesgBootCompleteTimes = 1074 mBootInfo.getOrDefault(DMESG_BOOT_COMPLETE_TIME, new ArrayList<>()); 1075 dmesgBootCompleteTimes.add(actionInfoItem.getStartTime().doubleValue()); 1076 mBootInfo.put(DMESG_BOOT_COMPLETE_TIME, dmesgBootCompleteTimes); 1077 mBootIterationInfo.put( 1078 DMESG_BOOT_COMPLETE_TIME, actionInfoItem.getStartTime().doubleValue()); 1079 isFirstBootCompletedAction = false; 1080 } 1081 String key = 1082 String.format( 1083 "%s%s_%s%s", 1084 ACTION, 1085 actionInfoItem.getActionName(), 1086 actionInfoItem.getSourceName() != null 1087 ? actionInfoItem.getSourceName() 1088 : "", 1089 START_TIME); 1090 List<Double> values = mBootInfo.getOrDefault(key, new ArrayList<>()); 1091 values.add(actionInfoItem.getStartTime().doubleValue()); 1092 mBootInfo.put(key, values); 1093 mBootIterationInfo.put(key, actionInfoItem.getStartTime().doubleValue()); 1094 } 1095 } 1096 } 1097 1098 /** 1099 * Analyze the time taken by different phases in boot loader by parsing the system property 1100 * ro.boot.boottime 1101 */ analyzeBootloaderTimingInfo()1102 private void analyzeBootloaderTimingInfo() throws DeviceNotAvailableException { 1103 String bootLoaderVal = getDevice().getProperty(BOOT_TIME_PROP); 1104 // Sample Output : 1BLL:89,1BLE:590,2BLL:0,2BLE:1344,SW:6734,KL:1193 1105 if (bootLoaderVal != null) { 1106 String[] bootLoaderPhases = bootLoaderVal.split(","); 1107 double bootLoaderTotalTime = 0d; 1108 for (String bootLoaderPhase : bootLoaderPhases) { 1109 String[] bootKeyVal = bootLoaderPhase.split(":"); 1110 String key = String.format("%s%s", BOOTLOADER_PREFIX, bootKeyVal[0]); 1111 if (mBootInfo.containsKey(key)) { 1112 mBootInfo.get(key).add(Double.parseDouble(bootKeyVal[1])); 1113 } else { 1114 List<Double> timeList = new ArrayList<Double>(); 1115 timeList.add(Double.parseDouble(bootKeyVal[1])); 1116 mBootInfo.put(key, timeList); 1117 } 1118 mBootIterationInfo.put(key, Double.parseDouble(bootKeyVal[1])); 1119 // SW is the time spent on the warning screen. So ignore it in 1120 // final boot time calculation. 1121 if (!BOOTLOADER_PHASE_SW.equalsIgnoreCase(bootKeyVal[0])) { 1122 bootLoaderTotalTime += Double.parseDouble(bootKeyVal[1]); 1123 } 1124 } 1125 1126 // Report bootloader time as well in the dashboard. 1127 CLog.i("Bootloader time is :%s", bootLoaderTotalTime); 1128 if (mBootInfo.containsKey(BOOTLOADER_TIME)) { 1129 mBootInfo.get(BOOTLOADER_TIME).add(bootLoaderTotalTime); 1130 } else { 1131 List<Double> timeList = new ArrayList<Double>(); 1132 timeList.add(bootLoaderTotalTime); 1133 mBootInfo.put(BOOTLOADER_TIME, timeList); 1134 } 1135 mBootIterationInfo.put(BOOTLOADER_TIME, bootLoaderTotalTime); 1136 1137 // First "action_sys.boot_completed=1_START_TIME" is parsed already from dmesg logs. 1138 // Current dmesg boot complete time should always be the last one in value list. 1139 // Calculate the sum of bootLoaderTotalTime and boot completed flag set time. 1140 List<Double> bootCompleteTimes = 1141 mBootInfo.getOrDefault(DMESG_BOOT_COMPLETE_TIME, new ArrayList<>()); 1142 double bootCompleteTime = 1143 bootCompleteTimes.isEmpty() 1144 ? 0L 1145 : bootCompleteTimes.get(bootCompleteTimes.size() - 1); 1146 double totalBootTime = bootLoaderTotalTime + bootCompleteTime; 1147 if (mBootInfo.containsKey(TOTAL_BOOT_TIME)) { 1148 mBootInfo.get(TOTAL_BOOT_TIME).add(totalBootTime); 1149 } else { 1150 List<Double> timeList = new ArrayList<Double>(); 1151 timeList.add(totalBootTime); 1152 mBootInfo.put(TOTAL_BOOT_TIME, timeList); 1153 } 1154 mBootIterationInfo.put(TOTAL_BOOT_TIME, totalBootTime); 1155 } 1156 } 1157 1158 /** 1159 * Parse the logcat file and calculate the time difference between the screen unlocked timestamp 1160 * till the Nexus launcher activity is displayed. 1161 */ analyzeUnlockBootInfo()1162 private void analyzeUnlockBootInfo() { 1163 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 1164 InputStream logcatStream = logcatData.createInputStream(); 1165 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 1166 BufferedReader br = new BufferedReader(logcatReader)) { 1167 boolean logOrderTracker = false; 1168 double unlockInMillis = 0d; 1169 String line; 1170 while ((line = br.readLine()) != null) { 1171 Matcher match = null; 1172 if ((match = matches(SCREEN_UNLOCKED, line)) != null && !isDuplicateLine(line)) { 1173 mParsedLines.add(line); 1174 Date time = parseTime(match.group(1)); 1175 unlockInMillis = time.getTime(); 1176 logOrderTracker = true; 1177 } else if ((match = matches(DISPLAYED_LAUNCHER, line)) != null 1178 && !isDuplicateLine(line) 1179 && logOrderTracker) { 1180 Date time = parseTime(match.group(1)); 1181 if (mBootInfo.containsKey(UNLOCK_TIME)) { 1182 mBootInfo.get(UNLOCK_TIME).add(time.getTime() - unlockInMillis); 1183 } else { 1184 List<Double> screenUnlockTime = new ArrayList<Double>(); 1185 screenUnlockTime.add(time.getTime() - unlockInMillis); 1186 mBootInfo.put(UNLOCK_TIME, screenUnlockTime); 1187 } 1188 mBootIterationInfo.put(UNLOCK_TIME, time.getTime() - unlockInMillis); 1189 logOrderTracker = false; 1190 } 1191 } 1192 } catch (IOException ioe) { 1193 CLog.e("Problem in parsing screen unlock delay from logcat."); 1194 CLog.e(ioe); 1195 } 1196 } 1197 1198 /** 1199 * To check if the line is duplicate entry in the log file. 1200 * 1201 * @return true if log line are duplicated 1202 */ isDuplicateLine(String currentLine)1203 private boolean isDuplicateLine(String currentLine) { 1204 if (mParsedLines.contains(currentLine)) { 1205 return true; 1206 } else { 1207 mParsedLines.add(currentLine); 1208 return false; 1209 } 1210 } 1211 1212 /** 1213 * Report the reboot time results separately under the storage specific reporting unit. 1214 * 1215 * @param results contains boot time test data 1216 */ reportStorageSpecificMetrics( ITestInvocationListener listener, Map<String, String> results)1217 private void reportStorageSpecificMetrics( 1218 ITestInvocationListener listener, Map<String, String> results) 1219 throws DeviceNotAvailableException { 1220 String storageType = getDevice().getProperty(STORAGE_TYPE); 1221 if (null != storageType && !storageType.isEmpty()) { 1222 // Construct reporting id based on UFS type 1223 // Example : DeviceBootTest.DeviceBootTest#SuccessiveBootTest-64GB 1224 TestDescription successiveStorageBootTestId = 1225 new TestDescription( 1226 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 1227 String.format("%s-%s", SUCCESSIVE_BOOT_TEST, storageType)); 1228 listener.testStarted(successiveStorageBootTestId); 1229 listener.testEnded(successiveStorageBootTestId, results); 1230 } 1231 } 1232 1233 /** Concatenate given list of values to comma separated string */ concatenateTimeValues(List<Double> timeInfo)1234 public String concatenateTimeValues(List<Double> timeInfo) { 1235 StringBuilder timeString = new StringBuilder(); 1236 for (Double time : timeInfo) { 1237 timeString.append(time); 1238 timeString.append(","); 1239 } 1240 return timeString.toString(); 1241 } 1242 1243 /** 1244 * Checks whether {@code line} matches the given {@link Pattern}. 1245 * 1246 * @return The resulting {@link Matcher} obtained by matching the {@code line} against {@code 1247 * pattern}, or null if the {@code line} does not match. 1248 */ matches(Pattern pattern, String line)1249 private static Matcher matches(Pattern pattern, String line) { 1250 Matcher ret = pattern.matcher(line); 1251 return ret.matches() ? ret : null; 1252 } 1253 1254 /** 1255 * Method to create the runner with given testName 1256 * 1257 * @return the {@link IRemoteAndroidTestRunner} to use. 1258 */ createRemoteAndroidTestRunner(String testName)1259 IRemoteAndroidTestRunner createRemoteAndroidTestRunner(String testName) 1260 throws DeviceNotAvailableException { 1261 RemoteAndroidTestRunner runner = 1262 new RemoteAndroidTestRunner(PACKAGE_NAME, RUNNER, getDevice().getIDevice()); 1263 runner.setMethodName(CLASS_NAME, testName); 1264 return runner; 1265 } 1266 1267 /** Wait until the sys.boot_completed is set */ waitForBootCompleted()1268 private void waitForBootCompleted() throws InterruptedException, DeviceNotAvailableException { 1269 for (int i = 0; i < BOOT_COMPLETE_POLL_RETRY_COUNT; i++) { 1270 if (isBootCompleted()) { 1271 return; 1272 } 1273 Thread.sleep(BOOT_COMPLETE_POLL_INTERVAL); 1274 } 1275 } 1276 1277 /** Returns true if boot completed property is set to true. */ isBootCompleted()1278 private boolean isBootCompleted() throws DeviceNotAvailableException { 1279 return BOOT_COMPLETED_VAL.equals( 1280 getDevice().executeShellCommand(BOOT_COMPLETED_PROP).trim()); 1281 } 1282 1283 /** 1284 * Parse the timestamp and return a {@link Date}. 1285 * 1286 * @param timeStr The timestamp in the format {@code MM-dd HH:mm:ss.SSS}. 1287 * @return The {@link Date}. 1288 */ parseTime(String timeStr)1289 private Date parseTime(String timeStr) { 1290 DateFormat yearFormatter = new SimpleDateFormat("yyyy"); 1291 String mYear = yearFormatter.format(new Date()); 1292 DateFormat formatter = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS"); 1293 try { 1294 return formatter.parse(String.format("%s-%s", mYear, timeStr)); 1295 } catch (ParseException e) { 1296 return null; 1297 } 1298 } 1299 1300 /** 1301 * @return the time to wait between the reboots. 1302 */ getBootDelayTime()1303 public long getBootDelayTime() { 1304 return mBootDelayTime; 1305 } 1306 createFailureFromException( String additionalMessage, Exception exception, FailureStatus defaultStatus)1307 final FailureDescription createFailureFromException( 1308 String additionalMessage, Exception exception, FailureStatus defaultStatus) { 1309 String message = exception.getMessage(); 1310 if (additionalMessage != null) { 1311 message = String.format("%s\n%s", additionalMessage, message); 1312 } 1313 FailureDescription failure = FailureDescription.create(message).setCause(exception); 1314 failure.setFailureStatus(defaultStatus); 1315 if (exception instanceof IHarnessException) { 1316 ErrorIdentifier id = ((IHarnessException) exception).getErrorId(); 1317 failure.setErrorIdentifier(id); 1318 failure.setOrigin(((IHarnessException) exception).getOrigin()); 1319 if (id != null) { 1320 failure.setFailureStatus(id.status()); 1321 } 1322 } 1323 return failure; 1324 } 1325 } 1326