Пример отладки производительности: ошибки ANR

В этом разделе рассказывается, как отлаживать ошибки «Приложение не отвечает» (ANR) с помощью ProfilingManager на примере трассировки.

Как настроить приложение для сбора данных об ошибках 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);
}

После того как вы записали и загрузили трассировку ANR, откройте ее в Perfetto UI.

Как проанализировать трассировку

Поскольку ошибка ANR запустила трассировку, вы знаете, что она завершилась, когда система обнаружила, что основной поток приложения не отвечает. На рисунке 1 показано, как перейти к основному потоку приложения, который отмечен в интерфейсе.

Переход к основному потоку приложения в интерфейсе Perfetto.
Рисунок 1. Переход к основному потоку приложения.

Конец трассировки совпадает с временной меткой ANR, как показано на рисунке 2.

Интерфейс Perfetto, в котором показан конец трассировки и выделено местоположение триггера ANR.
Рисунок 2. Место возникновения ошибки ANR.

Трассировка также показывает операции, которые выполняло приложение, когда произошла ошибка ANR. В частности, приложение выполняло код в срезе трассировки handleNetworkResponse. Этот фрагмент находился внутри фрагмента MyApp:SubmitButton. На это было затрачено 1,48 секунды времени ЦП (рис.3).

Интерфейс Perfetto, на котором показано процессорное время, затраченное на выполнение handleNetworkResponse во время ошибки ANR.
Рисунок 3. Выполнение во время ошибки ANR.

Если при отладке вы полагаетесь только на трассировку стека в момент ошибки ANR, то можете ошибочно отнести ошибку ANR к коду, который выполняется в handleNetworkResponse фрагменте трассировки, не завершившемся к моменту окончания записи профиля. Однако 1,48 секунды недостаточно, чтобы вызвать ошибку ANR, даже несмотря на то, что это ресурсоемкая операция. Чтобы понять, что блокировало основной поток до этого метода, нужно посмотреть более ранние данные.

Чтобы найти причину ошибки ANR, мы начинаем с последнего кадра, сгенерированного потоком интерфейса, который соответствует фрагменту Choreographer#doFrame 551275. При этом до начала фрагмента MyApp:SubmitButton, который привел к ошибке ANR, нет значительных источников задержки (рис. 4).

Интерфейс Perfetto, на котором показан последний кадр, отрисованный потоком UI до ошибки ANR.
Рисунок 4. Последний кадр приложения, сгенерированный до ошибки ANR.

Чтобы понять, что именно блокирует сигнал, уменьшите масштаб и посмотрите на весь срез MyApp:SubmitButton. Обратите внимание на важную деталь в состояниях потока, как показано на рисунке 4: поток провел 75% времени (6,7 секунды) в состоянии Sleeping и только 24% времени в состоянии Running.

Интерфейс Perfetto, показывающий состояния потоков во время операции, с выделением 75 % времени сна и 24% времени выполнения.
Рисунок 5. Состояния потоков во время операции `MyApp:SubmitButton`.

Это означает, что основной причиной ошибки ANR было ожидание, а не вычисление. Проанализируйте отдельные случаи сна, чтобы найти закономерность.

Интерфейс Perfetto, на котором показан первый интервал сна в фрагменте трассировки MyAppSubmitButton.
Рисунок 6. Первое время сна в `MyAppSubmitButton`.
В Perfetto UI показан второй интервал сна в срезе трассировки MyAppSubmitButton.
Рисунок 7. Второе время сна в элементе `MyAppSubmitButton`.
Интерфейс Perfetto, в котором показан третий интервал сна в фрагменте трассировки MyAppSubmitButton.
Рисунок 8. Третий период сна в `MyAppSubmitButton`.
Интерфейс Perfetto, в котором показан четвертый интервал сна в фрагменте трассировки MyAppSubmitButton.
Рисунок 9. Четвертое время сна в элементе `MyAppSubmitButton`.

Первые три интервала сна (рис. 6–8) почти идентичны и составляют примерно по две секунды. Четвертый выброс (на рисунке 9) длится 0,7 секунды. В вычислительной среде продолжительность в точности 2 секунды редко бывает случайной. Это указывает на то, что время ожидания было задано, а не возникло случайным образом из-за конфликта ресурсов. Последнее состояние сна может быть вызвано тем, что поток завершил ожидание, поскольку операция, которую он ожидал, была выполнена успешно.

Согласно этой гипотезе, приложение несколько раз достигало заданного пользователем времени ожидания в 2 секунды, а затем успешно выполняло запрос, но с задержкой, достаточной для того, чтобы вызвать ошибку ANR.

Интерфейс Perfetto с информацией о задержках в фрагменте трассировки MyApp:SubmitButton, указывающей на несколько двухсекундных интервалов сна.
Рисунок 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) {
  // ...
}


void prepareNetworkRequest() {
  // ...
}

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

Код подтверждает эту гипотезу. Метод onClickSubmit выполняет сетевой запрос в потоке UI с жестко заданным значением NETWORK_TIMEOUT_MILLISECS, равным 2000 мс. Важно отметить, что он выполняется в цикле while, который повторяется до 10 раз.

В этом случае у пользователя, скорее всего, было плохое подключение к сети. Первые три попытки не удались, поэтому было три двухсекундных тайм-аута (всего шесть секунд). Четвертая попытка была успешной и заняла 0,7 секунды, после чего код перешел к handleNetworkResponse. Однако накопленное время ожидания уже вызвало ошибку ANR.

Чтобы избежать таких ошибок ANR, выполняйте операции, связанные с сетью и имеющие разную задержку, в фоновом потоке, а не в основном. Это позволяет интерфейсу оставаться отзывчивым даже при плохом подключении к интернету и полностью устраняет ANR этого типа.