Практический пример отладки производительности: 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 .

Проанализируйте трассировку

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

Навигация Perfetto UI к основному потоку приложения.
Рисунок 1. Навигация к основному потоку приложения.

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

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

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

Интерфейс Perfetto UI отображает время работы процессора, затраченное на выполнение функции 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 UI отображает состояние потоков во время операции, выделяя 75% времени ожидания и 24% времени выполнения.
Рисунок 5. Состояния потоков во время операции `MyApp:SubmitButton`.

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

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

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

Эта гипотеза заключается в том, что приложение неоднократно достигало заданного пользователем таймаута в 2 секунды , в конечном итоге успешно выполняя операцию, что вызывало достаточную задержку для запуска ANR (Active No Reduction).

Perfetto UI отображает сводку задержек во время выполнения трассировки MyApp:SubmitButton, указывая на несколько 2-секундных интервалов ожидания.
Рисунок 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();
}

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

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

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