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 if (mRebootUnlock) { 419 listener.testRunStarted(mTestRunName, mBootCount * 2 + 2); 420 } else { 421 listener.testRunStarted(mTestRunName, mBootCount + 1); 422 } 423 for (IMetricCollector collector : mCollectors) { 424 listener = collector.init(mInvocationContext, listener); 425 } 426 try { 427 try { 428 // Set the current date from the host in test device. 429 getDevice().setDate(null); 430 431 // Setup device for successive boots, e.g. dismiss SuW 432 setupDeviceForSuccessiveBoots(); 433 434 Map<String, String> successiveResult = new HashMap<>(); 435 boolean isSuccessiveBootsSuccess = true; 436 TestDescription successiveBootTestId = 437 new TestDescription( 438 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 439 SUCCESSIVE_BOOT_TEST); 440 try { 441 // Skip second boot from successive boot delay calculation 442 doSecondBoot(); 443 testSuccessiveBoots(false, listener); 444 // Reports average value of individual metrics collected 445 listener.testStarted(successiveBootTestId); 446 } catch (RuntimeException re) { 447 CLog.e(re); 448 isSuccessiveBootsSuccess = false; 449 listener.testStarted(successiveBootTestId); 450 listener.testFailed( 451 successiveBootTestId, 452 String.format("RuntimeException during successive reboots: %s", re)); 453 } catch (DeviceNotAvailableException dnae) { 454 CLog.e("Device not available after successive reboots"); 455 CLog.e(dnae); 456 isSuccessiveBootsSuccess = false; 457 listener.testStarted(successiveBootTestId); 458 listener.testFailed( 459 successiveBootTestId, 460 String.format( 461 "Device not available after successive reboots; %s", dnae)); 462 } finally { 463 if (isSuccessiveBootsSuccess) { 464 if (null != mRebootLogcatReceiver) { 465 try (InputStreamSource logcatData = 466 mRebootLogcatReceiver.getLogcatData()) { 467 listener.testLog(LOGCAT_FILE, LogDataType.TEXT, logcatData); 468 } 469 mRebootLogcatReceiver.stop(); 470 } 471 listener.testEnded(successiveBootTestId, successiveResult); 472 // Report separately the hardware Storage specific boot time results. 473 if (!successiveResult.isEmpty() && mReportStorageSuffixMetric) { 474 reportStorageSpecificMetrics(listener, successiveResult); 475 } 476 } else { 477 listener.testEnded(successiveBootTestId, successiveResult); 478 } 479 } 480 481 // Test to measure the reboot time and time from unlocking the 482 // screen using the pin 483 // till the NexusLauncherActivity is displayed. 484 if (mRebootUnlock) { 485 mBootInfo.clear(); 486 Map<String, String> successiveBootUnlockResult = new HashMap<>(); 487 TestDescription successiveBootUnlockTestId = 488 new TestDescription( 489 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 490 SUCCESSIVE_BOOT_UNLOCK_TEST); 491 try { 492 // If pin is already set skip the setup method otherwise 493 // setup the pin. 494 if (!mSkipPinSetup) { 495 mRunner = createRemoteAndroidTestRunner(SETUP_PIN_TEST); 496 getDevice() 497 .runInstrumentationTests(mRunner, new CollectingTestListener()); 498 } 499 testSuccessiveBoots(true, listener); 500 } finally { 501 if (null != mRebootLogcatReceiver) { 502 try (InputStreamSource logcatData = 503 mRebootLogcatReceiver.getLogcatData()) { 504 listener.testLog(LOGCAT_UNLOCK_FILE, LogDataType.TEXT, logcatData); 505 } 506 mRebootLogcatReceiver.stop(); 507 } 508 listener.testStarted(successiveBootUnlockTestId); 509 listener.testEnded(successiveBootUnlockTestId, successiveBootUnlockResult); 510 } 511 } 512 } finally { 513 // Finish run for boot test. Health check below will start its own test run. 514 listener.testRunEnded( 515 System.currentTimeMillis() - start, new HashMap<String, Metric>()); 516 } 517 } finally { 518 finalTearDown(listener); 519 } 520 } 521 522 /** Final optional tear down step for the Boot test. */ finalTearDown(ITestInvocationListener listener)523 public void finalTearDown(ITestInvocationListener listener) throws DeviceNotAvailableException { 524 // empty on purpose 525 } 526 527 /** 528 * Look for the perfetto trace file collected during reboot under /data/misc/perfetto-traces and 529 * copy the file under /data/local/tmp using the test iteration name and return the path to the 530 * newly copied trace file. 531 */ processPerfettoFile(String testId)532 private String processPerfettoFile(String testId) throws DeviceNotAvailableException { 533 CommandResult result = getDevice().executeShellV2Command(PERFETTO_TRACE_FILE_CHECK_CMD); 534 if (result != null) { 535 CLog.i( 536 "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s", 537 PERFETTO_TRACE_FILE_CHECK_CMD, 538 result.getStdout(), 539 result.getStderr(), 540 result.getStatus()); 541 if (CommandStatus.SUCCESS.equals(result.getStatus()) 542 && result.getStdout().contains("boottrace.perfetto-trace")) { 543 // Move the perfetto trace file to the new location and rename it using the test 544 // name. 545 String finalTraceFileLocation = 546 String.format(FINAL_PERFETTO_TRACE_LOCATION, testId); 547 CommandResult moveResult = 548 getDevice() 549 .executeShellV2Command( 550 String.format( 551 PERFETTO_TRACE_MV_CMD, finalTraceFileLocation)); 552 if (moveResult != null) { 553 CLog.i( 554 "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s", 555 PERFETTO_TRACE_MV_CMD, 556 moveResult.getStdout(), 557 moveResult.getStderr(), 558 moveResult.getStatus()); 559 if (CommandStatus.SUCCESS.equals(result.getStatus())) { 560 return finalTraceFileLocation; 561 } 562 } 563 } 564 } 565 return null; 566 } 567 setupDeviceForSuccessiveBoots()568 private void setupDeviceForSuccessiveBoots() throws DeviceNotAvailableException { 569 // Run the list of post first boot setup commands 570 for (String cmd : mDeviceSetupCommands) { 571 CommandResult result; 572 result = getDevice().executeShellV2Command(cmd); 573 if (!CommandStatus.SUCCESS.equals(result.getStatus())) { 574 CLog.w( 575 "Post boot setup cmd: '%s' failed, returned:\nstdout:%s\nstderr:%s", 576 cmd, result.getStdout(), result.getStderr()); 577 } 578 } 579 } 580 581 /** Do the second boot on the device to exclude from the successive boot time calculations */ doSecondBoot()582 private void doSecondBoot() throws DeviceNotAvailableException { 583 getDevice().nonBlockingReboot(); 584 getDevice().waitForDeviceOnline(); 585 getDevice().waitForDeviceAvailable(mDeviceBootTime); 586 } 587 588 /** 589 * Clear the existing logs and start capturing the logcat 590 * 591 * <p>It will record from all logcat buffers if user provided any custom boot time metric 592 * patterns 593 */ clearAndStartLogcat()594 private void clearAndStartLogcat() throws DeviceNotAvailableException { 595 getDevice().executeShellCommand("logcat -c"); 596 boolean allBuffers = !mBootTimePatterns.isEmpty(); 597 if (mRebootLogcatReceiver == null) { 598 mRebootLogcatReceiver = 599 new LogcatReceiver( 600 getDevice(), allBuffers ? LOGCAT_CMD_ALL : LOGCAT_CMD, LOGCAT_SIZE, 0); 601 } 602 mRebootLogcatReceiver.start(); 603 } 604 605 /** 606 * To perform the successive boot for given boot count and take the average of boot time and 607 * online time delays 608 * 609 * @param dismissPin to dismiss pin after reboot 610 */ testSuccessiveBoots(boolean dismissPin, ITestInvocationListener listener)611 private void testSuccessiveBoots(boolean dismissPin, ITestInvocationListener listener) 612 throws DeviceNotAvailableException { 613 CLog.v("Waiting for %d msecs before successive boots.", mBootDelayTime); 614 getRunUtil().sleep(mBootDelayTime); 615 for (int count = 0; count < mBootCount; count++) { 616 getDevice().enableAdbRoot(); 617 // Property used for collecting the perfetto trace file on boot. 618 getDevice().executeShellCommand("setprop persist.debug.perfetto.boottrace 1"); 619 // Attempt to shurdown F2FS if the option is enabled. 620 if (mForceF2FsShutdown) { 621 String output = getDevice().executeShellCommand(F2FS_SHUTDOWN_COMMAND).trim(); 622 if (!F2FS_SHUTDOWN_SUCCESS_OUTPUT.equalsIgnoreCase(output)) { 623 CLog.e("Unable to shutdown the F2FS."); 624 } else { 625 CLog.i("F2FS shutdown successful."); 626 } 627 } 628 629 DmesgParser dmesgLogParser = null; 630 double bootStart = INVALID_TIME_DURATION; 631 double onlineTime = INVALID_TIME_DURATION; 632 double bootTime = INVALID_TIME_DURATION; 633 String testId = String.format("%s.%s$%d", BOOTTIME_TEST, BOOTTIME_TEST, (count + 1)); 634 TestDescription successiveBootIterationTestId; 635 if (!dismissPin) { 636 successiveBootIterationTestId = 637 new TestDescription(testId, String.format("%s", SUCCESSIVE_BOOT_TEST)); 638 } else { 639 successiveBootIterationTestId = 640 new TestDescription( 641 testId, String.format("%s", SUCCESSIVE_BOOT_UNLOCK_TEST)); 642 } 643 if (mGranularBootInfo || dismissPin) { 644 clearAndStartLogcat(); 645 getRunUtil().sleep(5000); 646 } 647 getDevice().nonBlockingReboot(); 648 bootStart = System.currentTimeMillis(); 649 getDevice().waitForDeviceOnline(); 650 onlineTime = System.currentTimeMillis() - bootStart; 651 getDevice().enableAdbRoot(); 652 dmesgLogParser = new DmesgParser(); 653 if (mDmesgInfo && mDumpDmesgImmediate) { 654 // Collect the dmesg logs after device is online and 655 // after the device is boot completed to avoid losing the 656 // initial logs in some devices. 657 parseDmesgInfo(dmesgLogParser); 658 } 659 try { 660 waitForBootCompleted(); 661 } catch (InterruptedException e) { 662 CLog.e("Sleep Interrupted"); 663 CLog.e(e); 664 } catch (DeviceNotAvailableException dne) { 665 CLog.e("Device not available"); 666 CLog.e(dne); 667 } 668 bootTime = System.currentTimeMillis() - bootStart; 669 if (mDmesgInfo) { 670 // Collect the dmesg logs after device is online and 671 // after the device is boot completed to avoid losing the 672 // initial logs. 673 parseDmesgInfo(dmesgLogParser); 674 if (!dmesgLogParser.getServiceInfoItems().isEmpty()) { 675 analyzeDmesgServiceInfo(dmesgLogParser.getServiceInfoItems().values()); 676 } 677 if (!dmesgLogParser.getStageInfoItems().isEmpty()) { 678 analyzeDmesgStageInfo(dmesgLogParser.getStageInfoItems()); 679 } 680 if (!dmesgLogParser.getActionInfoItems().isEmpty()) { 681 analyzeDmesgActionInfo(dmesgLogParser.getActionInfoItems()); 682 } 683 } 684 685 // Parse logcat info 686 Map<String, String> collectLogcatInfoResult = new HashMap<>(); 687 if (mCollectLogcat) { 688 collectLogcatInfoResult.putAll(collectLogcatInfo()); 689 } 690 691 // Parse bootloader timing info 692 if (mBootloaderInfo) analyzeBootloaderTimingInfo(); 693 694 if (dismissPin) { 695 getRunUtil().sleep(2000); 696 mRunner = createRemoteAndroidTestRunner(UNLOCK_PIN_TEST); 697 getDevice().runInstrumentationTests(mRunner, new CollectingTestListener()); 698 } 699 700 if (mBootTimePerIteration) { 701 listener.testStarted(successiveBootIterationTestId); 702 } 703 704 CLog.v("Waiting for %d msecs immediately after successive boot.", mAfterBootDelayTime); 705 getRunUtil().sleep(mAfterBootDelayTime); 706 if (onlineTime != INVALID_TIME_DURATION) { 707 if (mBootInfo.containsKey(SUCCESSIVE_ONLINE)) { 708 mBootInfo.get(SUCCESSIVE_ONLINE).add(onlineTime); 709 } else { 710 List<Double> onlineDelayList = new ArrayList<Double>(); 711 onlineDelayList.add(onlineTime); 712 mBootInfo.put(SUCCESSIVE_ONLINE, onlineDelayList); 713 } 714 mBootIterationInfo.put(SUCCESSIVE_ONLINE, onlineTime); 715 } 716 if (bootTime != INVALID_TIME_DURATION) { 717 if (mBootInfo.containsKey(SUCCESSIVE_BOOT)) { 718 mBootInfo.get(SUCCESSIVE_BOOT).add(bootTime); 719 } else { 720 List<Double> bootDelayList = new ArrayList<>(); 721 bootDelayList.add(bootTime); 722 mBootInfo.put(SUCCESSIVE_BOOT, bootDelayList); 723 } 724 mBootIterationInfo.put(SUCCESSIVE_BOOT, bootTime); 725 } 726 if (mGranularBootInfo) { 727 getRunUtil().sleep(15000); 728 analyzeGranularBootInfo(); 729 analyzeCustomBootInfo(); 730 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData()) { 731 listener.testLog( 732 String.format("%s_%d", LOGCAT_FILE, (count + 1)), 733 LogDataType.TEXT, 734 logcatData); 735 } 736 if (count != (mBootCount - 1)) { 737 mRebootLogcatReceiver.stop(); 738 mRebootLogcatReceiver = null; 739 } 740 } 741 if (dismissPin) { 742 analyzeUnlockBootInfo(); 743 if (count != (mBootCount - 1)) { 744 mRebootLogcatReceiver.stop(); 745 mRebootLogcatReceiver = null; 746 } 747 } 748 749 String perfettoTraceFilePath = 750 processPerfettoFile( 751 String.format( 752 "%s_%s", 753 successiveBootIterationTestId.getClassName().replace("$", "_"), 754 successiveBootIterationTestId.getTestName())); 755 756 if (mBootTimePerIteration) { 757 Map<String, String> iterationResult = new HashMap<>(); 758 for (Map.Entry<String, Double> bootData : mBootIterationInfo.entrySet()) { 759 iterationResult.put(bootData.getKey(), bootData.getValue().toString()); 760 } 761 if (perfettoTraceFilePath != null) { 762 iterationResult.put("perfetto_file_path", perfettoTraceFilePath); 763 } 764 if (!collectLogcatInfoResult.isEmpty()) { 765 iterationResult.putAll(collectLogcatInfoResult); 766 } 767 // If metric-prefix-pattern-for-count is present, calculate the count 768 // of all metrics with the prefix pattern and add the count as a new metric to the 769 // iterationResult map. 770 if (!mMetricPrefixPatternForCount.isEmpty()) { 771 for (String metricPrefixPattern : mMetricPrefixPatternForCount) { 772 long metricCount = 773 iterationResult.entrySet().stream() 774 .filter( 775 (entry) -> 776 entry.getKey() 777 .startsWith(metricPrefixPattern)) 778 .count(); 779 iterationResult.put( 780 metricPrefixPattern + METRIC_COUNT, Long.toString(metricCount)); 781 } 782 } 783 listener.testEnded(successiveBootIterationTestId, iterationResult); 784 } 785 786 mBootIterationInfo.clear(); 787 CLog.v("Waiting for %d msecs after boot completed.", mBootDelayTime); 788 getRunUtil().sleep(mBootDelayTime); 789 } 790 } 791 792 /** Get the logcat statistics info */ collectLogcatInfo()793 private Map<String, String> collectLogcatInfo() throws DeviceNotAvailableException { 794 Map<String, String> results = new HashMap<>(); 795 // Parse logcat in global level 796 results.putAll(extractLogcatInfo("general")); 797 return results; 798 } 799 800 /** Get the logcat statistics info */ extractLogcatInfo(String processName)801 private Map<String, String> extractLogcatInfo(String processName) 802 throws DeviceNotAvailableException { 803 Map<String, String> results = new HashMap<>(); 804 String runCommand = LOGCAT_CMD_STATISTICS_ALL; 805 String output = getDevice().executeShellCommand(runCommand); 806 String[] outputList = output.split("\\n\\n"); 807 808 // General statistics 809 // Sample output for $ logcat --statistics 810 // size/num main system crash kernel Total 811 // Total 33/23 96/91 3870/4 70/1 513/41 812 // Now 92/70 4/15 0/0 13/11 33/26 813 // Logspan 5:15:15.15 11d 20:37:31.37 13:20:54.185 11d 20:40:06.816 814 // Overhead 253454 56415 255139 1330477 815 Matcher matcherHeader = LOGCAT_STATISTICS_HEADER_PATTERN.matcher(outputList[0]); 816 Matcher matcherTotal = LOGCAT_STATISTICS_TOTAL_PATTERN.matcher(outputList[0]); 817 Matcher matcherNow = LOGCAT_STATISTICS_NOW_PATTERN.matcher(outputList[0]); 818 boolean headerFound = matcherHeader.find(); 819 boolean totalFound = matcherTotal.find(); 820 boolean nowFound = matcherNow.find(); 821 if (headerFound && totalFound && nowFound) { 822 // There are 6 columns in the output, but we just want to extract column 1 to 4 823 for (int i = 1; i < 5; i++) { 824 String bufferHeader = matcherHeader.group(i).trim(); 825 results.put( 826 String.join( 827 METRIC_KEY_SEPARATOR, 828 LOGCAT_STATISTICS_SIZE, 829 bufferHeader, 830 processName), 831 matcherTotal.group(i * 2 - 1).trim()); 832 results.put( 833 String.join( 834 METRIC_KEY_SEPARATOR, 835 LOGCAT_STATISTICS_DIFF_SIZE, 836 bufferHeader, 837 processName), 838 Integer.toString( 839 Integer.valueOf(matcherTotal.group(i * 2 - 1).trim()) 840 - Integer.valueOf(matcherNow.group(i * 2 - 1).trim()))); 841 } 842 } 843 return results; 844 } 845 846 /** 847 * Parse the logcat file for granular boot info (eg different system services start time) based 848 * on the component name or full component name (i.e component_subcompname) 849 */ analyzeGranularBootInfo()850 private void analyzeGranularBootInfo() { 851 String[] compStr = new String[0]; 852 String[] fullCompStr = new String[0]; 853 boolean isFilterSet = false; 854 855 if (null != mComponentNames) { 856 compStr = mComponentNames.split(","); 857 isFilterSet = true; 858 } 859 if (null != mFullCompNames) { 860 fullCompStr = mFullCompNames.split(","); 861 isFilterSet = true; 862 } 863 864 Set<String> compSet = new HashSet<>(Arrays.asList(compStr)); 865 Set<String> fullCompSet = new HashSet<>(Arrays.asList(fullCompStr)); 866 867 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 868 InputStream logcatStream = logcatData.createInputStream(); 869 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 870 BufferedReader br = new BufferedReader(logcatReader)) { 871 872 TimingsLogParser parser = new TimingsLogParser(); 873 List<SystemServicesTimingItem> items = parser.parseSystemServicesTimingItems(br); 874 for (SystemServicesTimingItem item : items) { 875 String componentName = item.getComponent(); 876 String fullCompName = 877 String.format("%s_%s", item.getComponent(), item.getSubcomponent()); 878 // If filter not set then capture timing info for all the 879 // components otherwise 880 // only for the given component names and full component 881 // names. 882 if (!isFilterSet 883 || compSet.contains(componentName) 884 || fullCompSet.contains(fullCompName)) { 885 Double time = 886 item.getDuration() != null ? item.getDuration() : item.getStartTime(); 887 if (time == null) { 888 continue; 889 } 890 if (mBootInfo.containsKey(fullCompName)) { 891 mBootInfo.get(fullCompName).add(time); 892 } else { 893 List<Double> delayList = new ArrayList<>(); 894 delayList.add(time); 895 mBootInfo.put(fullCompName, delayList); 896 } 897 mBootIterationInfo.put(fullCompName, time); 898 } 899 } 900 } catch (IOException ioe) { 901 CLog.e("Problem in parsing the granular boot delay information"); 902 CLog.e(ioe); 903 } 904 } 905 906 /** Parse the logcat file to get boot time metrics given patterns defined by tester. */ analyzeCustomBootInfo()907 private void analyzeCustomBootInfo() { 908 if (mBootTimePatterns.isEmpty()) return; 909 Double dmesgBootCompleteTimes; 910 TimingsLogParser parser = new TimingsLogParser(); 911 parser.addDurationPatternPair(BOOT_PHASE_1000, KERNEL_START_PATTERN, LOGCAT_BOOT_COMPLETED); 912 for (Map.Entry<String, String> pattern : mBootTimePatterns.entrySet()) { 913 CLog.d( 914 "Adding boot metric with name: %s, pattern: %s", 915 pattern.getKey(), pattern.getValue()); 916 parser.addDurationPatternPair( 917 pattern.getKey(), KERNEL_START_PATTERN, Pattern.compile(pattern.getValue())); 918 } 919 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 920 InputStream logcatStream = logcatData.createInputStream(); 921 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 922 BufferedReader br = new BufferedReader(logcatReader)) { 923 924 if (mBootIterationInfo.containsKey(DMESG_BOOT_COMPLETE_TIME)) { 925 dmesgBootCompleteTimes = mBootIterationInfo.get(DMESG_BOOT_COMPLETE_TIME); 926 } else { 927 CLog.d("Missing dmesg boot complete signals"); 928 return; 929 } 930 931 List<GenericTimingItem> items = parser.parseGenericTimingItems(br); 932 933 Map<String, GenericTimingItem> itemsMap = new HashMap<>(); 934 GenericTimingItem logcatBootCompleteItem = new GenericTimingItem(); 935 for (GenericTimingItem item : items) { 936 if (BOOT_PHASE_1000.equals(item.getName())) { 937 logcatBootCompleteItem = item; 938 } else { 939 itemsMap.put(item.getName(), item); 940 } 941 } 942 if (logcatBootCompleteItem.getName() == null) { 943 CLog.e("Missing boot complete signals from logcat"); 944 return; 945 } 946 for (Map.Entry<String, GenericTimingItem> metric : itemsMap.entrySet()) { 947 GenericTimingItem itemsForMetric = metric.getValue(); 948 if (itemsForMetric.getName().isEmpty()) { 949 CLog.e("Missing value for metric %s", metric.getKey()); 950 continue; 951 } 952 List<Double> values = mBootInfo.getOrDefault(metric.getKey(), new ArrayList<>()); 953 double duration = 954 dmesgBootCompleteTimes 955 + itemsForMetric.getEndTime() 956 - logcatBootCompleteItem.getEndTime(); 957 values.add(duration); 958 mBootInfo.put(metric.getKey(), values); 959 mBootIterationInfo.put(metric.getKey(), duration); 960 CLog.d("Added boot metric: %s with duration values: %s", metric.getKey(), values); 961 } 962 } catch (IOException e) { 963 CLog.e("Problem when parsing custom boot time info"); 964 CLog.e(e); 965 } 966 } 967 968 /** 969 * Collect the dmesg logs and parse the service info(start and end time), start time of boot 970 * stages and actions being processed, logged in the dmesg file. 971 */ parseDmesgInfo(DmesgParser dmesgLogParser)972 private void parseDmesgInfo(DmesgParser dmesgLogParser) throws DeviceNotAvailableException { 973 // Dump the dmesg logs to a file in the device 974 getDevice().executeShellCommand(DUMP_DMESG); 975 try { 976 File dmesgFile = getDevice().pullFile(DMESG_FILE); 977 BufferedReader input = 978 new BufferedReader(new InputStreamReader(new FileInputStream(dmesgFile))); 979 dmesgLogParser.parseInfo(input); 980 dmesgFile.delete(); 981 } catch (IOException ioe) { 982 CLog.e("Failed to analyze the dmesg logs", ioe); 983 } 984 } 985 986 /** 987 * Analyze the services info parsed from the dmesg logs and construct the metrics as a part of 988 * boot time data. 989 * 990 * @param serviceInfoItems contains the start time, end time and the duration of each service 991 * logged in the dmesg log file. 992 */ analyzeDmesgServiceInfo(Collection<DmesgServiceInfoItem> serviceInfoItems)993 private void analyzeDmesgServiceInfo(Collection<DmesgServiceInfoItem> serviceInfoItems) { 994 for (DmesgServiceInfoItem infoItem : serviceInfoItems) { 995 if (infoItem.getStartTime() != null) { 996 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), START_TIME); 997 if (mBootInfo.get(key) != null) { 998 mBootInfo.get(key).add(infoItem.getStartTime().doubleValue()); 999 } else { 1000 List<Double> timeList = new ArrayList<Double>(); 1001 timeList.add(infoItem.getStartTime().doubleValue()); 1002 mBootInfo.put(key, timeList); 1003 } 1004 mBootIterationInfo.put(key, infoItem.getStartTime().doubleValue()); 1005 } 1006 if (infoItem.getServiceDuration() != -1L) { 1007 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), DURATION); 1008 if (mBootInfo.get(key) != null) { 1009 mBootInfo.get(key).add(infoItem.getServiceDuration().doubleValue()); 1010 } else { 1011 List<Double> timeList = new ArrayList<Double>(); 1012 timeList.add(infoItem.getServiceDuration().doubleValue()); 1013 mBootInfo.put(key, timeList); 1014 } 1015 mBootIterationInfo.put(key, infoItem.getServiceDuration().doubleValue()); 1016 } 1017 if (infoItem.getEndTime() != null) { 1018 String key = String.format("%s%s%s", INIT, infoItem.getServiceName(), END_TIME); 1019 if (mBootInfo.get(key) != null) { 1020 mBootInfo.get(key).add(infoItem.getEndTime().doubleValue()); 1021 } else { 1022 List<Double> timeList = new ArrayList<Double>(); 1023 timeList.add(infoItem.getEndTime().doubleValue()); 1024 mBootInfo.put(key, timeList); 1025 } 1026 mBootIterationInfo.put(key, infoItem.getEndTime().doubleValue()); 1027 } 1028 } 1029 } 1030 1031 /** 1032 * Analyze the boot stages info parsed from the dmesg logs and construct the metrics as a part 1033 * of boot time data. 1034 * 1035 * @param stageInfoItems contains the start time of each stage logged in the dmesg log file. 1036 */ analyzeDmesgStageInfo(Collection<DmesgStageInfoItem> stageInfoItems)1037 private void analyzeDmesgStageInfo(Collection<DmesgStageInfoItem> stageInfoItems) { 1038 for (DmesgStageInfoItem stageInfoItem : stageInfoItems) { 1039 if (stageInfoItem.getStartTime() != null) { 1040 String key = 1041 String.format( 1042 "%s%s%s", INIT_STAGE, stageInfoItem.getStageName(), START_TIME); 1043 List<Double> values = mBootInfo.getOrDefault(key, new ArrayList<>()); 1044 values.add(stageInfoItem.getStartTime().doubleValue()); 1045 mBootInfo.put(key, values); 1046 mBootIterationInfo.put(key, stageInfoItem.getStartTime().doubleValue()); 1047 } else if (stageInfoItem.getDuration() != null) { 1048 List<Double> values = 1049 mBootInfo.getOrDefault(stageInfoItem.getStageName(), new ArrayList<>()); 1050 values.add(stageInfoItem.getDuration().doubleValue()); 1051 mBootInfo.put(stageInfoItem.getStageName(), values); 1052 mBootIterationInfo.put( 1053 stageInfoItem.getStageName(), stageInfoItem.getDuration().doubleValue()); 1054 } 1055 } 1056 } 1057 1058 /** 1059 * Analyze each action info parsed from the dmesg logs and construct the metrics as a part of 1060 * boot time data. 1061 * 1062 * @param actionInfoItems contains the start time of processing of each action logged in the 1063 * dmesg log file. 1064 */ analyzeDmesgActionInfo(Collection<DmesgActionInfoItem> actionInfoItems)1065 private void analyzeDmesgActionInfo(Collection<DmesgActionInfoItem> actionInfoItems) { 1066 boolean isFirstBootCompletedAction = true; 1067 for (DmesgActionInfoItem actionInfoItem : actionInfoItems) { 1068 if (actionInfoItem.getStartTime() != null) { 1069 if (actionInfoItem.getActionName().startsWith(BOOT_COMPLETE_ACTION) 1070 && isFirstBootCompletedAction) { 1071 CLog.i( 1072 "Using Action: %s_%s for first boot complete timestamp :%s", 1073 actionInfoItem.getActionName(), 1074 actionInfoItem.getSourceName(), 1075 actionInfoItem.getStartTime().doubleValue()); 1076 // Record the first boot complete time stamp. 1077 List<Double> dmesgBootCompleteTimes = 1078 mBootInfo.getOrDefault(DMESG_BOOT_COMPLETE_TIME, new ArrayList<>()); 1079 dmesgBootCompleteTimes.add(actionInfoItem.getStartTime().doubleValue()); 1080 mBootInfo.put(DMESG_BOOT_COMPLETE_TIME, dmesgBootCompleteTimes); 1081 mBootIterationInfo.put( 1082 DMESG_BOOT_COMPLETE_TIME, actionInfoItem.getStartTime().doubleValue()); 1083 isFirstBootCompletedAction = false; 1084 } 1085 String key = 1086 String.format( 1087 "%s%s_%s%s", 1088 ACTION, 1089 actionInfoItem.getActionName(), 1090 actionInfoItem.getSourceName() != null 1091 ? actionInfoItem.getSourceName() 1092 : "", 1093 START_TIME); 1094 List<Double> values = mBootInfo.getOrDefault(key, new ArrayList<>()); 1095 values.add(actionInfoItem.getStartTime().doubleValue()); 1096 mBootInfo.put(key, values); 1097 mBootIterationInfo.put(key, actionInfoItem.getStartTime().doubleValue()); 1098 } 1099 } 1100 } 1101 1102 /** 1103 * Analyze the time taken by different phases in boot loader by parsing the system property 1104 * ro.boot.boottime 1105 */ analyzeBootloaderTimingInfo()1106 private void analyzeBootloaderTimingInfo() throws DeviceNotAvailableException { 1107 String bootLoaderVal = getDevice().getProperty(BOOT_TIME_PROP); 1108 // Sample Output : 1BLL:89,1BLE:590,2BLL:0,2BLE:1344,SW:6734,KL:1193 1109 if (bootLoaderVal != null) { 1110 String[] bootLoaderPhases = bootLoaderVal.split(","); 1111 double bootLoaderTotalTime = 0d; 1112 for (String bootLoaderPhase : bootLoaderPhases) { 1113 String[] bootKeyVal = bootLoaderPhase.split(":"); 1114 String key = String.format("%s%s", BOOTLOADER_PREFIX, bootKeyVal[0]); 1115 if (mBootInfo.containsKey(key)) { 1116 mBootInfo.get(key).add(Double.parseDouble(bootKeyVal[1])); 1117 } else { 1118 List<Double> timeList = new ArrayList<Double>(); 1119 timeList.add(Double.parseDouble(bootKeyVal[1])); 1120 mBootInfo.put(key, timeList); 1121 } 1122 mBootIterationInfo.put(key, Double.parseDouble(bootKeyVal[1])); 1123 // SW is the time spent on the warning screen. So ignore it in 1124 // final boot time calculation. 1125 if (!BOOTLOADER_PHASE_SW.equalsIgnoreCase(bootKeyVal[0])) { 1126 bootLoaderTotalTime += Double.parseDouble(bootKeyVal[1]); 1127 } 1128 } 1129 1130 // Report bootloader time as well in the dashboard. 1131 CLog.i("Bootloader time is :%s", bootLoaderTotalTime); 1132 if (mBootInfo.containsKey(BOOTLOADER_TIME)) { 1133 mBootInfo.get(BOOTLOADER_TIME).add(bootLoaderTotalTime); 1134 } else { 1135 List<Double> timeList = new ArrayList<Double>(); 1136 timeList.add(bootLoaderTotalTime); 1137 mBootInfo.put(BOOTLOADER_TIME, timeList); 1138 } 1139 mBootIterationInfo.put(BOOTLOADER_TIME, bootLoaderTotalTime); 1140 1141 // First "action_sys.boot_completed=1_START_TIME" is parsed already from dmesg logs. 1142 // Current dmesg boot complete time should always be the last one in value list. 1143 // Calculate the sum of bootLoaderTotalTime and boot completed flag set time. 1144 List<Double> bootCompleteTimes = 1145 mBootInfo.getOrDefault(DMESG_BOOT_COMPLETE_TIME, new ArrayList<>()); 1146 double bootCompleteTime = 1147 bootCompleteTimes.isEmpty() 1148 ? 0L 1149 : bootCompleteTimes.get(bootCompleteTimes.size() - 1); 1150 double totalBootTime = bootLoaderTotalTime + bootCompleteTime; 1151 if (mBootInfo.containsKey(TOTAL_BOOT_TIME)) { 1152 mBootInfo.get(TOTAL_BOOT_TIME).add(totalBootTime); 1153 } else { 1154 List<Double> timeList = new ArrayList<Double>(); 1155 timeList.add(totalBootTime); 1156 mBootInfo.put(TOTAL_BOOT_TIME, timeList); 1157 } 1158 mBootIterationInfo.put(TOTAL_BOOT_TIME, totalBootTime); 1159 } 1160 } 1161 1162 /** 1163 * Parse the logcat file and calculate the time difference between the screen unlocked timestamp 1164 * till the Nexus launcher activity is displayed. 1165 */ analyzeUnlockBootInfo()1166 private void analyzeUnlockBootInfo() { 1167 try (InputStreamSource logcatData = mRebootLogcatReceiver.getLogcatData(); 1168 InputStream logcatStream = logcatData.createInputStream(); 1169 InputStreamReader logcatReader = new InputStreamReader(logcatStream); 1170 BufferedReader br = new BufferedReader(logcatReader)) { 1171 boolean logOrderTracker = false; 1172 double unlockInMillis = 0d; 1173 String line; 1174 while ((line = br.readLine()) != null) { 1175 Matcher match = null; 1176 if ((match = matches(SCREEN_UNLOCKED, line)) != null && !isDuplicateLine(line)) { 1177 mParsedLines.add(line); 1178 Date time = parseTime(match.group(1)); 1179 unlockInMillis = time.getTime(); 1180 logOrderTracker = true; 1181 } else if ((match = matches(DISPLAYED_LAUNCHER, line)) != null 1182 && !isDuplicateLine(line) 1183 && logOrderTracker) { 1184 Date time = parseTime(match.group(1)); 1185 if (mBootInfo.containsKey(UNLOCK_TIME)) { 1186 mBootInfo.get(UNLOCK_TIME).add(time.getTime() - unlockInMillis); 1187 } else { 1188 List<Double> screenUnlockTime = new ArrayList<Double>(); 1189 screenUnlockTime.add(time.getTime() - unlockInMillis); 1190 mBootInfo.put(UNLOCK_TIME, screenUnlockTime); 1191 } 1192 mBootIterationInfo.put(UNLOCK_TIME, time.getTime() - unlockInMillis); 1193 logOrderTracker = false; 1194 } 1195 } 1196 } catch (IOException ioe) { 1197 CLog.e("Problem in parsing screen unlock delay from logcat."); 1198 CLog.e(ioe); 1199 } 1200 } 1201 1202 /** 1203 * To check if the line is duplicate entry in the log file. 1204 * 1205 * @return true if log line are duplicated 1206 */ isDuplicateLine(String currentLine)1207 private boolean isDuplicateLine(String currentLine) { 1208 if (mParsedLines.contains(currentLine)) { 1209 return true; 1210 } else { 1211 mParsedLines.add(currentLine); 1212 return false; 1213 } 1214 } 1215 1216 /** 1217 * Report the reboot time results separately under the storage specific reporting unit. 1218 * 1219 * @param results contains boot time test data 1220 */ reportStorageSpecificMetrics( ITestInvocationListener listener, Map<String, String> results)1221 private void reportStorageSpecificMetrics( 1222 ITestInvocationListener listener, Map<String, String> results) 1223 throws DeviceNotAvailableException { 1224 String storageType = getDevice().getProperty(STORAGE_TYPE); 1225 if (null != storageType && !storageType.isEmpty()) { 1226 // Construct reporting id based on UFS type 1227 // Example : DeviceBootTest.DeviceBootTest#SuccessiveBootTest-64GB 1228 TestDescription successiveStorageBootTestId = 1229 new TestDescription( 1230 String.format("%s.%s", BOOTTIME_TEST, BOOTTIME_TEST), 1231 String.format("%s-%s", SUCCESSIVE_BOOT_TEST, storageType)); 1232 listener.testStarted(successiveStorageBootTestId); 1233 listener.testEnded(successiveStorageBootTestId, results); 1234 } 1235 } 1236 1237 /** Concatenate given list of values to comma separated string */ concatenateTimeValues(List<Double> timeInfo)1238 public String concatenateTimeValues(List<Double> timeInfo) { 1239 StringBuilder timeString = new StringBuilder(); 1240 for (Double time : timeInfo) { 1241 timeString.append(time); 1242 timeString.append(","); 1243 } 1244 return timeString.toString(); 1245 } 1246 1247 /** 1248 * Checks whether {@code line} matches the given {@link Pattern}. 1249 * 1250 * @return The resulting {@link Matcher} obtained by matching the {@code line} against {@code 1251 * pattern}, or null if the {@code line} does not match. 1252 */ matches(Pattern pattern, String line)1253 private static Matcher matches(Pattern pattern, String line) { 1254 Matcher ret = pattern.matcher(line); 1255 return ret.matches() ? ret : null; 1256 } 1257 1258 /** 1259 * Method to create the runner with given testName 1260 * 1261 * @return the {@link IRemoteAndroidTestRunner} to use. 1262 */ createRemoteAndroidTestRunner(String testName)1263 IRemoteAndroidTestRunner createRemoteAndroidTestRunner(String testName) 1264 throws DeviceNotAvailableException { 1265 RemoteAndroidTestRunner runner = 1266 new RemoteAndroidTestRunner(PACKAGE_NAME, RUNNER, getDevice().getIDevice()); 1267 runner.setMethodName(CLASS_NAME, testName); 1268 return runner; 1269 } 1270 1271 /** Wait until the sys.boot_completed is set */ waitForBootCompleted()1272 private void waitForBootCompleted() throws InterruptedException, DeviceNotAvailableException { 1273 for (int i = 0; i < BOOT_COMPLETE_POLL_RETRY_COUNT; i++) { 1274 if (isBootCompleted()) { 1275 return; 1276 } 1277 Thread.sleep(BOOT_COMPLETE_POLL_INTERVAL); 1278 } 1279 } 1280 1281 /** Returns true if boot completed property is set to true. */ isBootCompleted()1282 private boolean isBootCompleted() throws DeviceNotAvailableException { 1283 return BOOT_COMPLETED_VAL.equals( 1284 getDevice().executeShellCommand(BOOT_COMPLETED_PROP).trim()); 1285 } 1286 1287 /** 1288 * Parse the timestamp and return a {@link Date}. 1289 * 1290 * @param timeStr The timestamp in the format {@code MM-dd HH:mm:ss.SSS}. 1291 * @return The {@link Date}. 1292 */ parseTime(String timeStr)1293 private Date parseTime(String timeStr) { 1294 DateFormat yearFormatter = new SimpleDateFormat("yyyy"); 1295 String mYear = yearFormatter.format(new Date()); 1296 DateFormat formatter = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS"); 1297 try { 1298 return formatter.parse(String.format("%s-%s", mYear, timeStr)); 1299 } catch (ParseException e) { 1300 return null; 1301 } 1302 } 1303 1304 /** 1305 * @return the time to wait between the reboots. 1306 */ getBootDelayTime()1307 public long getBootDelayTime() { 1308 return mBootDelayTime; 1309 } 1310 createFailureFromException( String additionalMessage, Exception exception, FailureStatus defaultStatus)1311 final FailureDescription createFailureFromException( 1312 String additionalMessage, Exception exception, FailureStatus defaultStatus) { 1313 String message = exception.getMessage(); 1314 if (additionalMessage != null) { 1315 message = String.format("%s\n%s", additionalMessage, message); 1316 } 1317 FailureDescription failure = FailureDescription.create(message).setCause(exception); 1318 failure.setFailureStatus(defaultStatus); 1319 if (exception instanceof IHarnessException) { 1320 ErrorIdentifier id = ((IHarnessException) exception).getErrorId(); 1321 failure.setErrorIdentifier(id); 1322 failure.setOrigin(((IHarnessException) exception).getOrigin()); 1323 if (id != null) { 1324 failure.setFailureStatus(id.status()); 1325 } 1326 } 1327 return failure; 1328 } 1329 } 1330