Praktyczny przykład debugowania wydajności: ANR

W tej sekcji pokazujemy, jak debugować błąd ANR (Application Not Responding) za pomocą ProfilingManager na przykładzie śladu.

Konfigurowanie aplikacji pod kątem zbierania błędów ANR

Zacznij od skonfigurowania w aplikacji reguły 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

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

Analizowanie logu czasu

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

Koniec śladu pasuje do sygnatury czasowej ANR, jak pokazano na rysunku 2.

Log czasu pokazuje też operacje, które aplikacja wykonywała w momencie wystąpienia błędu ANR. Oznacza to, że aplikacja uruchomiła kod w segmencie śledzenia handleNetworkResponse. Ten wycinek znajdował się w wycinku MyApp:SubmitButton. Wykorzystano 1,48 sekundy czasu procesora (rysunek 3).

Jeśli do debugowania używasz tylko zrzutów stosu w momencie wystąpienia błędu ANR, możesz błędnie przypisać cały błąd ANR do kodu działającego w handleNetworkResponse, który nie zakończył się w momencie zakończenia nagrywania profilu. Jednak 1,48 sekundy to za mało, aby samodzielnie wywołać błąd ANR, mimo że jest to kosztowna operacja. Aby dowiedzieć się, co blokowało główny wątek przed tą metodą, musisz cofnąć się w czasie.

Aby znaleźć przyczynę błędu ANR, zaczynamy od ostatniej klatki wygenerowanej przez wątek interfejsu, 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óźnień (rysunek 4).

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

Oznacza to, że główną przyczyną błędu ANR było oczekiwanie, a nie obliczenia. Sprawdź poszczególne okresy snu, aby znaleźć wzorzec.

Pierwsze 3 interwały snu (rysunki 6–8) są niemal identyczne i trwają około 2 sekund. Wartość odstająca czwartego snu (rysunek 9) wynosi 0,7 sekundy. Czas trwania dokładnie 2 sekund rzadko jest przypadkowy w środowisku komputerowym. Wskazuje to na zaprogramowany limit czasu, a nie na losowe konkurowanie o zasoby. Ostatnie uśpienie może być spowodowane zakończeniem oczekiwania przez wątek, ponieważ operacja, na którą czekał, zakończyła się powodzeniem.

Hipoteza ta zakłada, że aplikacja wielokrotnie osiągała zdefiniowany przez użytkownika czas oczekiwania wynoszący 2 sekundy, a ostatecznie kończyła się powodzeniem, co powodowało wystarczające opóźnienie, aby wywołać 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) {
  // ...
}

  // ...
}

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

Kod potwierdza tę hipotezę. Metoda onClickSubmit wykonuje żądanie sieciowe w wątku interfejsu z zakodowaną na stałe wartością NETWORK_TIMEOUT_MILLISECS wynoszącą 2000 ms. Co ważne, działa ona w while pętli, która ponawia próbę maksymalnie 10 razy.

W tym konkretnym śladzie użytkownik prawdopodobnie miał słabe połączenie sieciowe. Pierwsze 3 próby nie powiodły się, co spowodowało 3 dwusekundowe przekroczenia limitu czasu (łącznie 6 sekund). Czwarta próba powiodła się po 0,7 sekundy, co umożliwiło przejście do handleNetworkResponse. Jednak łączny czas oczekiwania spowodował już wywołanie błędu 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 ten rodzaj błędów ANR.