실제 성능 디버깅 예: ANR

이 섹션에서는 ProfilingManager를 사용하여 애플리케이션 응답 없음 (ANR)을 디버그하는 방법을 예시 트레이스와 함께 보여줍니다.

ANR을 수집하도록 앱 설정

먼저 앱에서 ANR 트리거를 설정합니다.

public void addANRTrigger() {
  ProfilingManager profilingManager = getApplicationContext().getSystemService(
      ProfilingManager.class);
  List<ProfilingTrigger> triggers = new ArrayList<>();
  ProfilingTrigger.Builder triggerBuilder = new ProfilingTrigger.Builder(
      ProfilingTrigger.TRIGGER_TYPE_ANR);
  triggers.add(triggerBuilder.build());
  Executor mainExecutor = Executors.newSingleThreadExecutor();
  Consumer<ProfilingResult> resultCallback =
      profilingResult -> {
        // Handle uploading trace to your back-end
      };
  profilingManager.registerForAllProfilingResults(mainExecutor, resultCallback);
  profilingManager.addProfilingTriggers(triggers);
}
ProfilingManagerJavaSnippets.java

ANR 트레이스를 캡처하고 업로드한 후 Perfetto UI에서 엽니다.

트레이스 분석

ANR이 트레이스를 트리거했으므로 시스템이 앱의 기본 스레드에서 응답 없음을 감지했을 때 트레이스가 종료되었음을 알 수 있습니다. 그림 1은 UI 내에서 적절하게 태그된 앱의 기본 스레드로 이동하는 방법을 보여줍니다.

그림 1. 앱의 기본 스레드로 이동합니다.

트레이스 끝이 ANR의 타임스탬프와 일치합니다(그림 2 참고).

그림 2. ANR 트리거 위치입니다.

트레이스에는 ANR이 발생했을 때 앱이 실행 중이던 작업도 표시됩니다. 구체적으로 앱은 handleNetworkResponse 트레이스 슬라이스에서 코드를 실행했습니다. 이 슬라이스는 MyApp:SubmitButton 슬라이드 내에 있었습니다. CPU 시간은 1.48초가 사용되었습니다 (그림 3).

그림 3. ANR 발생 시 실행

디버깅을 위해 ANR 발생 시의 스택 트레이스에만 의존하는 경우 프로파일 기록이 완료될 때 종료되지 않은 handleNetworkResponse 트레이스 슬라이스 내에서 실행되는 코드에 ANR을 완전히 잘못 귀속시킬 수 있습니다. 하지만 1.48초는 비용이 많이 드는 작업이더라도 자체적으로 ANR을 트리거하기에 충분하지 않습니다. 이 메서드 전에 기본 스레드를 차단한 요소를 이해하려면 더 이전의 시간을 살펴봐야 합니다.

도움말: 맞춤 트레이스 슬라이스를 추가하여 장기 실행 작업을 식별하고 중요한 사용자 여정을 식별하는 것이 좋습니다.

ANR의 원인을 찾기 위한 시작점을 파악하기 위해 Choreographer#doFrame 551275 슬라이스에 해당하는 UI 스레드에서 생성된 마지막 프레임 이후를 살펴봅니다. ANR로 끝난 MyApp:SubmitButton 슬라이스가 시작되기 전에 지연의 큰 원인이 없습니다 (그림 4).

그림 4. ANR 전에 생성된 마지막 앱 프레임입니다.

차단된 부분을 파악하려면 축소하여 전체 MyApp:SubmitButton 슬라이스를 검사합니다. 스레드 상태에서 중요한 세부정보를 확인할 수 있습니다(그림 4 참고). 스레드가 Sleeping 상태에서 75%(6.7초)의 시간을 보냈고 Running 상태에서는 24% 의 시간만 보냈습니다.

그림 5. `MyApp:SubmitButton` 작업 중 스레드 상태

이는 ANR의 기본 원인이 계산이 아닌 대기였음을 나타냅니다. 개별 수면 발생을 검토하여 패턴을 찾습니다.

그림 6. `MyAppSubmitButton` 내의 첫 번째 절전 모드 시간입니다.

그림 7. `MyAppSubmitButton` 내 두 번째 절전 시간

그림 8. `MyAppSubmitButton` 내 세 번째 절전 시간

그림 9. `MyAppSubmitButton` 내 네 번째 절전 시간입니다.

첫 세 수면 간격 (그림 6~8)은 거의 동일하며 각각 약 2초입니다. 이상치인 네 번째 수면 (그림 9)은 0.7초입니다. 컴퓨팅 환경에서 정확히 2초의 지속 시간은 우연인 경우가 드뭅니다. 이는 무작위 리소스 경합이 아닌 프로그래밍된 제한 시간을 강력하게 시사합니다. 마지막 절전 모드는 스레드가 대기 중인 작업이 성공했기 때문에 대기를 완료하여 발생했을 수 있습니다.

이 가설은 앱이 사용자 정의 제한 시간인 2초를 여러 번 도달한 후 결국 성공하여 ANR을 트리거할 만큼 지연이 발생했다는 것입니다.

그림 10. `MyApp:SubmitButton` 슬라이스 중 지연 요약

이를 확인하려면 MyApp:SubmitButton 추적 섹션과 연결된 코드를 검사하세요.

private static final int NETWORK_TIMEOUT_MILLISECS = 2000;
public void setupButtonCallback() {
  findViewById(R.id.submit).setOnClickListener(submitButtonView -> {
    Trace.beginSection("MyApp:SubmitButton");
    onClickSubmit();
    Trace.endSection();
  });
}

public void onClickSubmit() {
  prepareNetworkRequest();

  boolean networkRequestSuccess = false;
  int maxAttempts = 10;
  while (!networkRequestSuccess && maxAttempts > 0) {
    networkRequestSuccess = performNetworkRequest(NETWORK_TIMEOUT_MILLISECS);
    maxAttempts--;
  }

  if (networkRequestSuccess) {
    handleNetworkResponse();
  }
}

boolean performNetworkRequest(int timeoutMiliseconds) {
  // ...
}

  // ...
}

public void handleNetworkResponse() {
  Trace.beginSection("handleNetworkResponse");
  // ...
  Trace.endSection();
}
ProfilingManagerJavaSnippets.java

코드는 이 가설을 확인합니다. onClickSubmit 메서드는 하드코딩된 NETWORK_TIMEOUT_MILLISECS(2000ms)를 사용하여 UI 스레드에서 네트워크 요청을 실행합니다. 중요한 점은 최대 10번까지 다시 시도하는 while 루프 내에서 실행된다는 것입니다.

이 특정 트레이스에서 사용자는 네트워크 연결이 좋지 않았을 수 있습니다. 처음 세 번의 시도가 실패하여 2초 제한 시간이 세 번 발생했습니다 (총 6초). 네 번째 시도는 0.7초 후에 성공하여 코드가 handleNetworkResponse로 진행될 수 있었습니다. 하지만 누적된 대기 시간으로 인해 이미 ANR이 트리거되었습니다.

참고: 추적 분석을 통해 가설('네트워크 시간 초과임')이 도출되었지만 이를 증명하기에 추적 데이터가 부족한 경우 반복적 접근 방식을 사용하세요. 의심되는 로직 주변에 새 트레이스 슬라이스를 추가하고 가설을 검증하기 위해 새 필드 데이터를 수집합니다.

지연 시간이 다양한 네트워크 관련 작업을 기본 스레드에서 실행하는 대신 백그라운드 스레드에 배치하여 이러한 유형의 ANR을 방지하세요. 이렇게 하면 연결 상태가 좋지 않아도 UI가 응답성을 유지하여 이 클래스의 ANR이 완전히 제거됩니다.