1 /* 2 * Copyright (C) 2022 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package com.android.internal.os.anr; 18 19 import static android.os.Trace.TRACE_TAG_ACTIVITY_MANAGER; 20 21 import static com.android.internal.os.TimeoutRecord.TimeoutKind; 22 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__BROADCAST_OF_INTENT; 23 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__CONTENT_PROVIDER_NOT_RESPONDING; 24 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__EXECUTING_SERVICE; 25 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__INPUT_DISPATCHING_TIMEOUT; 26 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__INPUT_DISPATCHING_TIMEOUT_NO_FOCUSED_WINDOW; 27 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__JOB_SERVICE; 28 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__SHORT_FGS_TIMEOUT; 29 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__START_FOREGROUND_SERVICE; 30 import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__UNKNOWN_ANR_TYPE; 31 32 import android.annotation.IntDef; 33 import android.os.SystemClock; 34 import android.os.Trace; 35 36 import com.android.internal.annotations.VisibleForTesting; 37 import com.android.internal.util.FrameworkStatsLog; 38 39 import java.lang.annotation.Retention; 40 import java.lang.annotation.RetentionPolicy; 41 import java.util.concurrent.atomic.AtomicInteger; 42 43 /** 44 * Store different latencies from the ANR flow and trace functions, it records latency breakdown 45 * for key methods, lock acquisition and other potentially expensive operations in the ANR 46 * reporting flow and exports the data as comma separated text on calling 47 * dumpAsCommaSeparatedArrayWithHeader and as an atom to statsd on being closed. 48 */ 49 public class AnrLatencyTracker implements AutoCloseable { 50 51 /** Status of the early dumped pid. */ 52 @IntDef(value = { 53 EarlyDumpStatus.UNKNOWN, 54 EarlyDumpStatus.SUCCEEDED, 55 EarlyDumpStatus.FAILED_TO_CREATE_FILE, 56 EarlyDumpStatus.TIMED_OUT 57 }) 58 59 @Retention(RetentionPolicy.SOURCE) 60 private @interface EarlyDumpStatus { 61 int UNKNOWN = 1; 62 int SUCCEEDED = 2; 63 int FAILED_TO_CREATE_FILE = 3; 64 int TIMED_OUT = 4; 65 } 66 67 private static final AtomicInteger sNextAnrRecordPlacedOnQueueCookieGenerator = 68 new AtomicInteger(); 69 70 private long mAnrTriggerUptime; 71 private long mEndUptime; 72 73 private long mAppNotRespondingStartUptime; 74 private long mAnrRecordPlacedOnQueueUptime; 75 private long mAnrProcessingStartedUptime; 76 private long mDumpStackTracesStartUptime; 77 78 private long mUpdateCpuStatsNowLastCallUptime; 79 private long mUpdateCpuStatsNowTotalLatency = 0; 80 private long mCurrentPsiStateLastCallUptime; 81 private long mCurrentPsiStateTotalLatency = 0; 82 private long mProcessCpuTrackerMethodsLastCallUptime; 83 private long mProcessCpuTrackerMethodsTotalLatency = 0; 84 private long mCriticalEventLoglastCallUptime; 85 private long mCriticalEventLogTotalLatency = 0; 86 87 private long mGlobalLockLastTryAcquireStart; 88 private long mGlobalLockTotalContention = 0; 89 private long mPidLockLastTryAcquireStart; 90 private long mPidLockTotalContention = 0; 91 private long mAMSLockLastTryAcquireStart; 92 private long mAMSLockTotalContention = 0; 93 private long mProcLockLastTryAcquireStart; 94 private long mProcLockTotalContention = 0; 95 private long mAnrRecordLastTryAcquireStart; 96 private long mAnrRecordLockTotalContention = 0; 97 98 private int mAnrQueueSize; 99 private int mAnrType; 100 private final AtomicInteger mDumpedProcessesCount = new AtomicInteger(0); 101 102 private volatile @EarlyDumpStatus int mEarlyDumpStatus = 103 EarlyDumpStatus.UNKNOWN; 104 private volatile long mTempFileDumpingStartUptime; 105 private volatile long mTempFileDumpingDuration = 0; 106 private long mCopyingFirstPidStartUptime; 107 private long mCopyingFirstPidDuration = 0; 108 private long mEarlyDumpRequestSubmissionUptime = 0; 109 private long mEarlyDumpExecutorPidCount = 0; 110 111 private long mFirstPidsDumpingStartUptime; 112 private long mFirstPidsDumpingDuration = 0; 113 private long mNativePidsDumpingStartUptime; 114 private long mNativePidsDumpingDuration = 0; 115 private long mExtraPidsDumpingStartUptime; 116 private long mExtraPidsDumpingDuration = 0; 117 118 private boolean mIsPushed = false; 119 private boolean mIsSkipped = false; 120 private boolean mCopyingFirstPidSucceeded = false; 121 122 private long mPreDumpIfLockTooSlowStartUptime; 123 private long mPreDumpIfLockTooSlowDuration = 0; 124 private long mNotifyAppUnresponsiveStartUptime; 125 private long mNotifyAppUnresponsiveDuration = 0; 126 private long mNotifyWindowUnresponsiveStartUptime; 127 private long mNotifyWindowUnresponsiveDuration = 0; 128 129 private final int mAnrRecordPlacedOnQueueCookie = 130 sNextAnrRecordPlacedOnQueueCookieGenerator.incrementAndGet(); 131 AnrLatencyTracker(@imeoutKind int timeoutKind, long anrTriggerUptime)132 public AnrLatencyTracker(@TimeoutKind int timeoutKind, long anrTriggerUptime) { 133 mAnrTriggerUptime = anrTriggerUptime; 134 mAnrType = timeoutKindToAnrType(timeoutKind); 135 136 } 137 138 /** Records the start of AnrHelper#appNotResponding. */ appNotRespondingStarted()139 public void appNotRespondingStarted() { 140 mAppNotRespondingStartUptime = getUptimeMillis(); 141 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, 142 "AnrHelper#appNotResponding()"); 143 } 144 145 /** Records the end of AnrHelper#appNotResponding. */ appNotRespondingEnded()146 public void appNotRespondingEnded() { 147 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 148 } 149 150 /** 151 * Records the number of processes we are currently early-dumping, this number includes the 152 * current ANR's main process. 153 */ earlyDumpRequestSubmittedWithSize(int currentProcessedPidCount)154 public void earlyDumpRequestSubmittedWithSize(int currentProcessedPidCount) { 155 mEarlyDumpRequestSubmissionUptime = getUptimeMillis(); 156 mEarlyDumpExecutorPidCount = currentProcessedPidCount; 157 } 158 159 /** Records the placing of the AnrHelper.AnrRecord instance on the processing queue. */ anrRecordPlacingOnQueueWithSize(int queueSize)160 public void anrRecordPlacingOnQueueWithSize(int queueSize) { 161 mAnrRecordPlacedOnQueueUptime = getUptimeMillis(); 162 Trace.asyncTraceBegin(TRACE_TAG_ACTIVITY_MANAGER, 163 "anrRecordPlacedOnQueue", mAnrRecordPlacedOnQueueCookie); 164 mAnrQueueSize = queueSize; 165 // Since we are recording the anr record queue size after pushing the current 166 // record, we need to increment the current queue size by 1 167 Trace.traceCounter(TRACE_TAG_ACTIVITY_MANAGER, "anrRecordsQueueSize", queueSize + 1); 168 } 169 170 /** Records the start of ProcessErrorStateRecord#appNotResponding. */ anrProcessingStarted()171 public void anrProcessingStarted() { 172 mAnrProcessingStartedUptime = getUptimeMillis(); 173 Trace.asyncTraceEnd(TRACE_TAG_ACTIVITY_MANAGER, 174 "anrRecordPlacedOnQueue", mAnrRecordPlacedOnQueueCookie); 175 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, 176 "anrProcessing"); 177 } 178 179 /** Records the end of ProcessErrorStateRecord#appNotResponding, the tracker is closed here. */ anrProcessingEnded()180 public void anrProcessingEnded() { 181 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 182 close(); 183 } 184 185 /** Records the start of StackTracesDumpHelper#dumpStackTraces. */ dumpStackTracesStarted()186 public void dumpStackTracesStarted() { 187 mDumpStackTracesStartUptime = getUptimeMillis(); 188 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, 189 "dumpStackTraces()"); 190 } 191 192 /** Records the end of StackTracesDumpHelper#dumpStackTraces. */ dumpStackTracesEnded()193 public void dumpStackTracesEnded() { 194 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 195 } 196 197 /** Records the start of ActivityManagerService#updateCpuStatsNow. */ updateCpuStatsNowCalled()198 public void updateCpuStatsNowCalled() { 199 mUpdateCpuStatsNowLastCallUptime = getUptimeMillis(); 200 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "updateCpuStatsNow()"); 201 } 202 203 /** Records the return of ActivityManagerService#updateCpuStatsNow. */ updateCpuStatsNowReturned()204 public void updateCpuStatsNowReturned() { 205 mUpdateCpuStatsNowTotalLatency += 206 getUptimeMillis() - mUpdateCpuStatsNowLastCallUptime; 207 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 208 } 209 210 /** Records the start of ResourcePressureUtil#currentPsiState. */ currentPsiStateCalled()211 public void currentPsiStateCalled() { 212 mCurrentPsiStateLastCallUptime = getUptimeMillis(); 213 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "currentPsiState()"); 214 } 215 216 /** Records the return of ResourcePressureUtil#currentPsiState. */ currentPsiStateReturned()217 public void currentPsiStateReturned() { 218 mCurrentPsiStateTotalLatency += getUptimeMillis() - mCurrentPsiStateLastCallUptime; 219 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 220 } 221 222 /** Records the start of ProcessCpuTracker methods. */ processCpuTrackerMethodsCalled()223 public void processCpuTrackerMethodsCalled() { 224 mProcessCpuTrackerMethodsLastCallUptime = getUptimeMillis(); 225 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "processCpuTracker"); 226 } 227 228 /** Records the return of ProcessCpuTracker methods. */ processCpuTrackerMethodsReturned()229 public void processCpuTrackerMethodsReturned() { 230 mProcessCpuTrackerMethodsTotalLatency += 231 getUptimeMillis() - mProcessCpuTrackerMethodsLastCallUptime; 232 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 233 } 234 235 /** Records the start of ANR headers dumping to file (subject and criticalEventSection). */ criticalEventLogStarted()236 public void criticalEventLogStarted() { 237 mCriticalEventLoglastCallUptime = getUptimeMillis(); 238 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "criticalEventLog"); 239 } 240 241 /** Records the end of ANR headers dumping to file (subject and criticalEventSection). */ criticalEventLogEnded()242 public void criticalEventLogEnded() { 243 mCriticalEventLogTotalLatency += 244 getUptimeMillis() - mCriticalEventLoglastCallUptime; 245 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 246 } 247 248 /** Records the start of native pid collection. */ nativePidCollectionStarted()249 public void nativePidCollectionStarted() { 250 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "nativePidCollection"); 251 } 252 253 /** Records the end of native pid collection. */ nativePidCollectionEnded()254 public void nativePidCollectionEnded() { 255 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 256 } 257 258 /** Records the start of pid dumping to file. */ dumpingPidStarted(int pid)259 public void dumpingPidStarted(int pid) { 260 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingPid#" + pid); 261 } 262 263 /** Records the end of pid dumping to file. */ dumpingPidEnded()264 public void dumpingPidEnded() { 265 mDumpedProcessesCount.incrementAndGet(); 266 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 267 } 268 269 /** Records the start of first pids dumping to file. */ dumpingFirstPidsStarted()270 public void dumpingFirstPidsStarted() { 271 mFirstPidsDumpingStartUptime = getUptimeMillis(); 272 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingFirstPids"); 273 } 274 275 /** Records the end of first pids dumping to file. */ dumpingFirstPidsEnded()276 public void dumpingFirstPidsEnded() { 277 mFirstPidsDumpingDuration = getUptimeMillis() - mFirstPidsDumpingStartUptime; 278 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 279 } 280 281 282 /** Records the start of the copying of the pre-dumped first pid. */ copyingFirstPidStarted()283 public void copyingFirstPidStarted() { 284 mCopyingFirstPidStartUptime = getUptimeMillis(); 285 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "copyingFirstPid"); 286 } 287 288 /** Records the end of the copying of the pre-dumped first pid. */ copyingFirstPidEnded(boolean copySucceeded)289 public void copyingFirstPidEnded(boolean copySucceeded) { 290 mCopyingFirstPidDuration = getUptimeMillis() - mCopyingFirstPidStartUptime; 291 mCopyingFirstPidSucceeded = copySucceeded; 292 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 293 } 294 295 /** Records the start of pre-dumping. */ dumpStackTracesTempFileStarted()296 public void dumpStackTracesTempFileStarted() { 297 mTempFileDumpingStartUptime = getUptimeMillis(); 298 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFile"); 299 } 300 301 /** Records the end of pre-dumping. */ dumpStackTracesTempFileEnded()302 public void dumpStackTracesTempFileEnded() { 303 mTempFileDumpingDuration = getUptimeMillis() - mTempFileDumpingStartUptime; 304 if (mEarlyDumpStatus == EarlyDumpStatus.UNKNOWN) { 305 mEarlyDumpStatus = EarlyDumpStatus.SUCCEEDED; 306 } 307 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 308 } 309 310 /** Records file creation failure events in dumpStackTracesTempFile. */ dumpStackTracesTempFileCreationFailed()311 public void dumpStackTracesTempFileCreationFailed() { 312 mEarlyDumpStatus = EarlyDumpStatus.FAILED_TO_CREATE_FILE; 313 Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileCreationFailed"); 314 } 315 316 /** Records timeout events in dumpStackTracesTempFile. */ dumpStackTracesTempFileTimedOut()317 public void dumpStackTracesTempFileTimedOut() { 318 mEarlyDumpStatus = EarlyDumpStatus.TIMED_OUT; 319 Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileTimedOut"); 320 } 321 322 /** Records the start of native pids dumping to file. */ dumpingNativePidsStarted()323 public void dumpingNativePidsStarted() { 324 mNativePidsDumpingStartUptime = getUptimeMillis(); 325 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingNativePids"); 326 } 327 328 /** Records the end of native pids dumping to file . */ dumpingNativePidsEnded()329 public void dumpingNativePidsEnded() { 330 mNativePidsDumpingDuration = getUptimeMillis() - mNativePidsDumpingStartUptime; 331 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 332 } 333 334 /** Records the start of extra pids dumping to file. */ dumpingExtraPidsStarted()335 public void dumpingExtraPidsStarted() { 336 mExtraPidsDumpingStartUptime = getUptimeMillis(); 337 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingExtraPids"); 338 } 339 340 /** Records the end of extra pids dumping to file. */ dumpingExtraPidsEnded()341 public void dumpingExtraPidsEnded() { 342 mExtraPidsDumpingDuration = getUptimeMillis() - mExtraPidsDumpingStartUptime; 343 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 344 } 345 346 /** Records the start of contention on ActivityManagerService.mGlobalLock. */ waitingOnGlobalLockStarted()347 public void waitingOnGlobalLockStarted() { 348 mGlobalLockLastTryAcquireStart = getUptimeMillis(); 349 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "globalLock"); 350 } 351 352 /** Records the end of contention on ActivityManagerService.mGlobalLock. */ waitingOnGlobalLockEnded()353 public void waitingOnGlobalLockEnded() { 354 mGlobalLockTotalContention += getUptimeMillis() - mGlobalLockLastTryAcquireStart; 355 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 356 } 357 358 /** Records the start of contention on ActivityManagerService.mPidsSelfLocked. */ waitingOnPidLockStarted()359 public void waitingOnPidLockStarted() { 360 mPidLockLastTryAcquireStart = getUptimeMillis(); 361 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "pidLockContention"); 362 } 363 364 /** Records the end of contention on ActivityManagerService.mPidsSelfLocked. */ waitingOnPidLockEnded()365 public void waitingOnPidLockEnded() { 366 mPidLockTotalContention += getUptimeMillis() - mPidLockLastTryAcquireStart; 367 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 368 } 369 370 /** Records the start of contention on ActivityManagerService. */ waitingOnAMSLockStarted()371 public void waitingOnAMSLockStarted() { 372 mAMSLockLastTryAcquireStart = getUptimeMillis(); 373 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "AMSLockContention"); 374 } 375 376 /** Records the end of contention on ActivityManagerService. */ waitingOnAMSLockEnded()377 public void waitingOnAMSLockEnded() { 378 mAMSLockTotalContention += getUptimeMillis() - mAMSLockLastTryAcquireStart; 379 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 380 } 381 382 /** Records the start of contention on ActivityManagerService.mProcLock. */ waitingOnProcLockStarted()383 public void waitingOnProcLockStarted() { 384 mProcLockLastTryAcquireStart = getUptimeMillis(); 385 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "procLockContention"); 386 } 387 388 /** Records the start of contention on ActivityManagerService.mProcLock. */ waitingOnProcLockEnded()389 public void waitingOnProcLockEnded() { 390 mProcLockTotalContention += getUptimeMillis() - mProcLockLastTryAcquireStart; 391 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 392 } 393 394 /** Records the start of contention on AnrHelper.mAnrRecords. */ waitingOnAnrRecordLockStarted()395 public void waitingOnAnrRecordLockStarted() { 396 mAnrRecordLastTryAcquireStart = getUptimeMillis(); 397 Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "anrRecordLockContention"); 398 } 399 400 /** Records the end of contention on AnrHelper.mAnrRecords. */ waitingOnAnrRecordLockEnded()401 public void waitingOnAnrRecordLockEnded() { 402 mAnrRecordLockTotalContention += 403 getUptimeMillis() - mAnrRecordLastTryAcquireStart; 404 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 405 } 406 407 /** Counts the number of records in the records queue when the ANR record is popped. */ anrRecordsQueueSizeWhenPopped(int queueSize)408 public void anrRecordsQueueSizeWhenPopped(int queueSize) { 409 Trace.traceCounter(TRACE_TAG_ACTIVITY_MANAGER, "anrRecordsQueueSize", queueSize); 410 } 411 412 /** Records the start of AnrController#preDumpIfLockTooSlow. */ preDumpIfLockTooSlowStarted()413 public void preDumpIfLockTooSlowStarted() { 414 mPreDumpIfLockTooSlowStartUptime = getUptimeMillis(); 415 } 416 417 /** Records the end of AnrController#preDumpIfLockTooSlow. */ preDumpIfLockTooSlowEnded()418 public void preDumpIfLockTooSlowEnded() { 419 mPreDumpIfLockTooSlowDuration += 420 getUptimeMillis() - mPreDumpIfLockTooSlowStartUptime; 421 } 422 423 /** Records a skipped ANR in ProcessErrorStateRecord#appNotResponding. */ anrSkippedProcessErrorStateRecordAppNotResponding()424 public void anrSkippedProcessErrorStateRecordAppNotResponding() { 425 anrSkipped("appNotResponding"); 426 } 427 428 /** Records a skipped ANR in StackTracesDumpHelper#dumpStackTraces. */ anrSkippedDumpStackTraces()429 public void anrSkippedDumpStackTraces() { 430 anrSkipped("dumpStackTraces"); 431 } 432 433 /** Records the start of AnrController#notifyAppUnresponsive. */ notifyAppUnresponsiveStarted()434 public void notifyAppUnresponsiveStarted() { 435 mNotifyAppUnresponsiveStartUptime = getUptimeMillis(); 436 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "notifyAppUnresponsive()"); 437 } 438 439 /** Records the end of AnrController#notifyAppUnresponsive. */ notifyAppUnresponsiveEnded()440 public void notifyAppUnresponsiveEnded() { 441 mNotifyAppUnresponsiveDuration = getUptimeMillis() - mNotifyAppUnresponsiveStartUptime; 442 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 443 } 444 445 /** Records the start of AnrController#notifyWindowUnresponsive. */ notifyWindowUnresponsiveStarted()446 public void notifyWindowUnresponsiveStarted() { 447 mNotifyWindowUnresponsiveStartUptime = getUptimeMillis(); 448 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "notifyWindowUnresponsive()"); 449 } 450 451 /** Records the end of AnrController#notifyWindowUnresponsive. */ notifyWindowUnresponsiveEnded()452 public void notifyWindowUnresponsiveEnded() { 453 mNotifyWindowUnresponsiveDuration = getUptimeMillis() 454 - mNotifyWindowUnresponsiveStartUptime; 455 Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); 456 } 457 458 /** 459 * Returns latency data as a comma separated value string for inclusion in ANR report. 460 */ dumpAsCommaSeparatedArrayWithHeader()461 public String dumpAsCommaSeparatedArrayWithHeader() { 462 return "DurationsV5: " + mAnrTriggerUptime 463 /* triggering_to_app_not_responding_duration = */ 464 + "," + (mAppNotRespondingStartUptime - mAnrTriggerUptime) 465 /* app_not_responding_duration = */ 466 + "," + (mAnrRecordPlacedOnQueueUptime - mAppNotRespondingStartUptime) 467 /* anr_record_placed_on_queue_duration = */ 468 + "," + (mAnrProcessingStartedUptime - mAnrRecordPlacedOnQueueUptime) 469 /* anr_processing_duration = */ 470 + "," + (mDumpStackTracesStartUptime - mAnrProcessingStartedUptime) 471 472 /* update_cpu_stats_now_total_duration = */ 473 + "," + mUpdateCpuStatsNowTotalLatency 474 /* current_psi_state_total_duration = */ 475 + "," + mCurrentPsiStateTotalLatency 476 /* process_cpu_tracker_methods_total_duration = */ 477 + "," + mProcessCpuTrackerMethodsTotalLatency 478 /* critical_event_log_duration = */ 479 + "," + mCriticalEventLogTotalLatency 480 481 /* global_lock_total_contention = */ 482 + "," + mGlobalLockTotalContention 483 /* pid_lock_total_contention = */ 484 + "," + mPidLockTotalContention 485 /* ams_lock_total_contention = */ 486 + "," + mAMSLockTotalContention 487 /* proc_lock_total_contention = */ 488 + "," + mProcLockTotalContention 489 /* anr_record_lock_total_contention = */ 490 + "," + mAnrRecordLockTotalContention 491 492 /* anr_queue_size_when_pushed = */ 493 + "," + mAnrQueueSize 494 /* dump_stack_traces_io_time = */ 495 // We use copyingFirstPidUptime if we're dumping the durations list before the 496 // first pids ie after copying the early dump stacks. 497 + "," + ((mFirstPidsDumpingStartUptime > 0 ? mFirstPidsDumpingStartUptime 498 : mCopyingFirstPidStartUptime) - mDumpStackTracesStartUptime) 499 /* temp_file_dump_duration = */ 500 + "," + mTempFileDumpingDuration 501 /* temp_dump_request_on_queue_duration = */ 502 + "," + (mTempFileDumpingStartUptime - mEarlyDumpRequestSubmissionUptime) 503 /* temp_dump_pid_count_when_pushed = */ 504 + "," + mEarlyDumpExecutorPidCount 505 /* first_pid_copying_time = */ 506 + "," + mCopyingFirstPidDuration 507 /* early_dump_status = */ 508 + "," + mEarlyDumpStatus 509 /* copying_first_pid_succeeded = */ 510 + "," + (mCopyingFirstPidSucceeded ? 1 : 0) 511 /* preDumpIfLockTooSlow_duration = */ 512 + "," + mPreDumpIfLockTooSlowDuration 513 /* notifyAppUnresponsive_duration = */ 514 + "," + mNotifyAppUnresponsiveDuration 515 /* notifyWindowUnresponsive_duration = */ 516 + "," + mNotifyWindowUnresponsiveDuration 517 + "\n\n"; 518 519 } 520 521 /** 522 * Closes the ANR latency instance by writing the atom to statsd, this method is idempotent. 523 */ 524 @Override close()525 public void close() { 526 if (!mIsSkipped && !mIsPushed) { 527 mEndUptime = getUptimeMillis(); 528 pushAtom(); 529 mIsPushed = true; 530 } 531 } 532 timeoutKindToAnrType(@imeoutKind int timeoutKind)533 private static int timeoutKindToAnrType(@TimeoutKind int timeoutKind) { 534 switch (timeoutKind) { 535 case TimeoutKind.INPUT_DISPATCH_NO_FOCUSED_WINDOW: 536 return ANRLATENCY_REPORTED__ANR_TYPE__INPUT_DISPATCHING_TIMEOUT_NO_FOCUSED_WINDOW; 537 case TimeoutKind.INPUT_DISPATCH_WINDOW_UNRESPONSIVE: 538 return ANRLATENCY_REPORTED__ANR_TYPE__INPUT_DISPATCHING_TIMEOUT; 539 case TimeoutKind.BROADCAST_RECEIVER: 540 return ANRLATENCY_REPORTED__ANR_TYPE__BROADCAST_OF_INTENT; 541 case TimeoutKind.SERVICE_START: 542 return ANRLATENCY_REPORTED__ANR_TYPE__START_FOREGROUND_SERVICE; 543 case TimeoutKind.SERVICE_EXEC: 544 return ANRLATENCY_REPORTED__ANR_TYPE__EXECUTING_SERVICE; 545 case TimeoutKind.CONTENT_PROVIDER: 546 return ANRLATENCY_REPORTED__ANR_TYPE__CONTENT_PROVIDER_NOT_RESPONDING; 547 case TimeoutKind.SHORT_FGS_TIMEOUT: 548 return ANRLATENCY_REPORTED__ANR_TYPE__SHORT_FGS_TIMEOUT; 549 case TimeoutKind.JOB_SERVICE: 550 return ANRLATENCY_REPORTED__ANR_TYPE__JOB_SERVICE; 551 default: 552 return ANRLATENCY_REPORTED__ANR_TYPE__UNKNOWN_ANR_TYPE; 553 } 554 } 555 556 /** @hide */ 557 @VisibleForTesting getUptimeMillis()558 public long getUptimeMillis() { 559 return SystemClock.uptimeMillis(); 560 } 561 562 /** @hide */ 563 @VisibleForTesting pushAtom()564 public void pushAtom() { 565 FrameworkStatsLog.write( 566 FrameworkStatsLog.ANR_LATENCY_REPORTED, 567 568 /* total_duration = */ mEndUptime - mAnrTriggerUptime, 569 /* triggering_to_stack_dump_duration = */ 570 mFirstPidsDumpingStartUptime - mAnrTriggerUptime, 571 /* triggering_to_app_not_responding_duration = */ 572 mAppNotRespondingStartUptime - mAnrTriggerUptime, 573 /* app_not_responding_duration = */ 574 mAnrRecordPlacedOnQueueUptime - mAppNotRespondingStartUptime, 575 /* anr_record_placed_on_queue_duration = */ 576 mAnrProcessingStartedUptime - mAnrRecordPlacedOnQueueUptime, 577 /* anr_processing_duration = */ 578 mDumpStackTracesStartUptime - mAnrProcessingStartedUptime, 579 /* dump_stack_traces_duration = */ mFirstPidsDumpingDuration 580 + mNativePidsDumpingDuration 581 + mExtraPidsDumpingDuration, 582 583 /* update_cpu_stats_now_total_duration = */ mUpdateCpuStatsNowTotalLatency, 584 /* current_psi_state_total_duration = */ mCurrentPsiStateTotalLatency, 585 /* process_cpu_tracker_methods_total_duration = */ 586 mProcessCpuTrackerMethodsTotalLatency, 587 /* critical_event_log_duration = */ mCriticalEventLogTotalLatency, 588 589 /* global_lock_total_contention = */ mGlobalLockTotalContention, 590 /* pid_lock_total_contention = */ mPidLockTotalContention, 591 /* ams_lock_total_contention = */ mAMSLockTotalContention, 592 /* proc_lock_total_contention = */ mProcLockTotalContention, 593 /* anr_record_lock_total_contention = */ mAnrRecordLockTotalContention, 594 595 /* anr_queue_size_when_pushed = */ mAnrQueueSize, 596 /* anr_type = */ mAnrType, 597 /* dumped_processes_count = */ mDumpedProcessesCount.get()); 598 } 599 anrSkipped(String method)600 private void anrSkipped(String method) { 601 Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "AnrSkipped@" + method); 602 mIsSkipped = true; 603 } 604 } 605