Praktyczny przykład debugowania wydajności: ANR

W tej sekcji pokazujemy, jak debugować błąd „Aplikacja nie odpowiada” (ANR) za pomocą ProfilingManager na przykładzie śledzenia.

Konfigurowanie aplikacji do zbierania błędów ANR

Zacznij od skonfigurowania wyzwalacza ANR w aplikacji:

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

Po przechwyceniu i przesłaniu śladu ANR otwórz go w Perfetto UI.

Analizowanie śladu

Ponieważ ślad został wywołany przez błąd ANR, wiesz, że ślad zakończył się, gdy system wykrył brak odpowiedzi w wątku głównym aplikacji. Na ilustracji 1 pokazujemy, jak przejść do wątku głównego aplikacji, który jest odpowiednio oznaczony w interfejsie.

Koniec śladu odpowiada sygnaturze czasowej ANR, jak pokazano na ilustracji 2.

Ślad pokazuje też operacje, które aplikacja wykonywała, gdy wystąpił błąd ANR. W szczególności aplikacja uruchomiła kod w wycinku śladu handleNetworkResponse. Ten wycinek znajdował się w wycinku MyApp:SubmitButton. Wykorzystał 1,48 sekundy czasu procesora (ilustracja 3).

Jeśli do debugowania używasz tylko śladów stosu w momencie wystąpienia błędu ANR, możesz błędnie przypisać błąd ANR w całości do kodu działającego w wycinku śladu handleNetworkResponse, który nie został zakończony, gdy profilowanie się skończyło. Jednak 1,48 sekundy to za mało, aby samodzielnie wywołać błąd ANR, nawet jeśli jest to kosztowna operacja. Aby zrozumieć, co zablokowało wątek główny przed tą metodą, musisz cofnąć się w czasie.

Aby znaleźć punkt początkowy do poszukiwania przyczyny błędu ANR, zaczynamy od ostatniej ramki wygenerowanej przez wątek UI, która odpowiada wycinkowi Choreographer#doFrame 551275. Przed rozpoczęciem wycinka MyApp:SubmitButton, który zakończył się błędem ANR, nie ma dużych źródeł opóźnienia (ilustracja 4).

Aby zrozumieć blokadę, pomniejsz widok, aby sprawdzić cały wycinek MyApp:SubmitButton. Zauważysz ważny szczegół w stanach wątku, jak pokazano na ilustracji 4: wątek spędził 75% czasu (6,7 sekundy) w stanie Sleeping i tylko 24% czasu w stanie Running .

Wskazuje to, że główną przyczyną błędu ANR było oczekiwanie, a nie obliczenia. Aby znaleźć wzorzec, sprawdź poszczególne wystąpienia stanu uśpienia.

Pierwsze 3 interwały uśpienia (ilustracje 6–8) są prawie identyczne i wynoszą około 2 sekund. Czwarty czas uśpienia (ilustracja 9) wynosi 0,7 sekundy. Czas trwania dokładnie 2 sekund rzadko jest przypadkiem w środowisku komputerowym. Wskazuje to na zaprogramowany limit czasu, a nie na losową rywalizację o zasoby. Ostatni czas uśpienia może być spowodowany tym, że wątek zakończył oczekiwanie, ponieważ operacja, na którą czekał, zakończyła się powodzeniem.

Hipoteza jest taka, że aplikacja wielokrotnie osiągała zdefiniowany przez użytkownika limit czasu wynoszący 2 sekundy i ostatecznie kończyła się powodzeniem, co powodowało wystarczające opóźnienie, aby wywołać błąd ANR.

Aby to sprawdzić, przejrzyj kod powiązany z sekcją śladu 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) {
  // ...
}


void prepareNetworkRequest() {
  // ...
}

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

Kod potwierdza tę hipotezę. Metoda onClickSubmit wykonuje żądanie sieciowe w wątku UI z zakodowanym na stałe NETWORK_TIMEOUT_MILLISECS wynoszącym 2000 ms. Co najważniejsze, działa w pętli while, która ponawia próbę do 10 razy.

W tym konkretnym śladzie użytkownik prawdopodobnie miał słabe połączenie z siecią. Pierwsze 3 próby nie powiodły się, co spowodowało 3 limity czasu po 2 sekundy (łącznie 6 sekund). Czwarta próba zakończyła się powodzeniem po 0,7 sekundy, co umożliwiło przejście kodu do handleNetworkResponse. Jednak skumulowany czas oczekiwania spowodował już błąd ANR.

Aby uniknąć tego typu błędów ANR, umieść operacje związane z siecią, które mają różne opóźnienia, w wątku w tle zamiast wykonywać je w wątku głównym. Dzięki temu interfejs użytkownika pozostaje responsywny nawet przy słabym połączeniu, co całkowicie eliminuje tę klasę błędów ANR.