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