Nghiên cứu điển hình: Gỡ lỗi ANR

Trang này hướng dẫn cách gỡ lỗi Ứng dụng không phản hồi (ANR) bằng ProfilingManager thông qua một dấu vết hệ thống mẫu.

Thiết lập ứng dụng để thu thập lỗi ANR

Bắt đầu bằng cách thiết lập điều kiện kích hoạt lỗi ANR trong ứng dụng:

Kotlin

fun addANRTrigger() {
    val profilingManager =
        applicationContext.getSystemService(ProfilingManager::class.java) ?: return
    val triggers = ArrayList<ProfilingTrigger>()
    val triggerBuilder = ProfilingTrigger.Builder(ProfilingTrigger.TRIGGER_TYPE_ANR)
    triggers.add(triggerBuilder.build())
    val callbackExecutor: Executor = Executors.newSingleThreadExecutor()
    val resultCallback = Consumer<ProfilingResult> { profilingResult ->
        // Handle uploading trace to your back-end
    }
    profilingManager.registerForAllProfilingResults(callbackExecutor, resultCallback)
    profilingManager.addProfilingTriggers(triggers)
}

Java

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 callbackExecutor = Executors.newSingleThreadExecutor();
  Consumer<ProfilingResult> resultCallback =
      profilingResult -> {
        // Handle uploading trace to your back-end
      };
  profilingManager.registerForAllProfilingResults(callbackExecutor, resultCallback);
  profilingManager.addProfilingTriggers(triggers);
}

Sau khi thu thập và tải dấu vết ANR lên, bạn có thể kiểm tra dấu vết đó theo cách thủ công trong giao diện người dùng Perfetto như trong các bước sau hoặc tự động điều tra lỗi ANR bằng một tác nhân AI.

Phân tích dấu vết

Vì lỗi ANR đã kích hoạt dấu vết, nên bạn biết dấu vết đã kết thúc khi hệ thống phát hiện thấy tình trạng không phản hồi trong luồng chính của ứng dụng (hoặc khi xảy ra một lỗi hết thời gian chờ khác). Hình 1 cho thấy cách chuyển đến luồng chính của ứng dụng, được gắn thẻ tương ứng trong giao diện người dùng.

Giao diện người dùng Perfetto điều hướng đến luồng chính của ứng dụng.
Hình 1. Chuyển đến luồng chính của ứng dụng.

Phần cuối của dấu vết khớp với dấu thời gian của lỗi ANR, như trong Hình 2.

Giao diện người dùng Perfetto cho thấy phần cuối của dấu vết, làm nổi bật vị trí kích hoạt lỗi ANR.
Hình 2. Vị trí kích hoạt lỗi ANR.

Khi lỗi ANR xảy ra, luồng chính đang thực thi lát cắt handleNetworkResponse bên trong MyApp:SubmitButton, tiêu tốn 1,48 giây thời gian của CPU (Hình 3).

Giao diện người dùng Perfetto cho thấy thời gian của CPU mà quá trình thực thi handleNetworkResponse tiêu thụ tại thời điểm xảy ra lỗi ANR.
Hình 3. Thực thi tại thời điểm xảy ra lỗi ANR.

Nếu chỉ dựa vào tệp báo lỗi ngăn xếp được tạo tại thời điểm xảy ra lỗi ANR, thì có thể bạn sẽ cho rằng lỗi treo hoàn toàn là do handleNetworkResponse. Tuy nhiên, 1,48 giây không đủ dài để kích hoạt lỗi ANR, vì vậy, bạn cần kiểm tra xem điều gì đã chặn luồng chính trước đó.

Bắt đầu bằng cách tìm khung giao diện người dùng cuối cùng được kết xuất trước khi bị treo (Choreographer#doFrame 551275), ngay trước lát cắt MyApp:SubmitButton (Hình 4).

Giao diện người dùng Perfetto cho thấy khung hình gần đây nhất được luồng giao diện người dùng kết xuất trước khi xảy ra lỗi ANR.
Hình 4. Khung hình gần đây nhất của ứng dụng được tạo trước khi xảy ra lỗi ANR.

Để hiểu rõ về tình trạng chặn, hãy thu nhỏ để kiểm tra toàn bộ lát cắt MyApp:SubmitButton. Bạn sẽ nhận thấy một chi tiết quan trọng trong trạng thái luồng cho phạm vi được chọn theo cách thủ công trong Hình 5: luồng đã dành khoảng 75% thời gian (6,7 giây) ở trạng thái Sleeping và chỉ 24% thời gian ở trạng thái Running.

Giao diện người dùng Perfetto cho thấy trạng thái luồng trong một thao tác, làm nổi bật 75% thời gian ngủ và 24% thời gian chạy.
Hình 5. Trạng thái luồng trong quá trình hoạt động của MyApp:SubmitButton.

Điều này cho thấy nguyên nhân chính gây ra lỗi ANR là do chờ đợi, chứ không phải do tính toán. Kiểm tra từng lần ngủ để tìm ra quy luật.

Giao diện người dùng Perfetto cho thấy khoảng thời gian ngủ đầu tiên trong lát cắt dấu vết MyAppSubmitButton.
Hình 6. Thời gian ngủ đầu tiên trong vòng MyApp:SubmitButton.
Giao diện người dùng Perfetto cho thấy khoảng thời gian ngủ thứ hai trong lát cắt dấu vết MyAppSubmitButton.
Hình 7. Thời gian ngủ thứ hai trong vòng MyApp:SubmitButton.
Giao diện người dùng Perfetto cho thấy khoảng thời gian ngủ thứ ba trong lát cắt dấu vết MyAppSubmitButton.
Hình 8. Thời gian ngủ thứ ba trong vòng MyApp:SubmitButton.
Giao diện người dùng Perfetto cho thấy khoảng thời gian ngủ thứ tư trong lát cắt dấu vết MyAppSubmitButton.
Hình 9. Thời gian ngủ thứ tư trong vòng MyApp:SubmitButton.

Ba khoảng thời gian ngủ đầu tiên (Hình 6 – 8) là khoảng 2 giây mỗi khoảng, và khoảng thời gian thứ tư (Hình 9) là 0,7 giây. Việc tạm dừng 2 giây lặp lại cho thấy rõ ràng thời gian chờ được lập trình đã thử lại 3 lần trước khi thành công ở lần thử thứ tư – tích luỹ đủ độ trễ để kích hoạt lỗi ANR (Hình 10).

Giao diện người dùng Perfetto cho thấy thông tin tóm tắt về độ trễ trong lát cắt dấu vết MyApp:SubmitButton, cho biết nhiều khoảng thời gian ngủ 2 giây.
Hình 10. Tóm tắt về tình trạng chậm trễ trong khoảng thời gian MyApp:SubmitButton.

Xác định nguyên nhân gốc trong mã

Để xác minh giả thuyết này, hãy kiểm tra mã liên kết với phần theo dõi MyApp:SubmitButton:

Kotlin

fun setupButtonCallback() {
    findViewById<View>(R.id.submit).setOnClickListener {
        trace("MyApp:SubmitButton") {
            onClickSubmit()
        }
    }
}

fun onClickSubmit() {
    prepareNetworkRequest()

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

    if (networkRequestSuccess) {
        handleNetworkResponse()
    }
}

fun performNetworkRequest(timeoutMilliseconds: Int): Boolean {
    // ...
}

fun prepareNetworkRequest() {
    // ...
}

fun handleNetworkResponse() {
    trace("handleNetworkResponse") {
        // ...
    }
}

companion object {
    private const val NETWORK_TIMEOUT_MILLISECS = 2000
}

Java

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();
}

Mã này xác nhận giả thuyết này. Phương thức onClickSubmit thực thi một yêu cầu mạng trên luồng giao diện người dùng với NETWORK_TIMEOUT_MILLISECS được cố định giá trị trong mã là 2000 mili giây. Điều quan trọng là hàm này chạy bên trong một vòng lặp while thử lại tối đa 10 lần.

Trong dấu vết cụ thể này, người dùng có thể có kết nối mạng kém. Ba lần thử đầu tiên không thành công, gây ra ba lần hết thời gian chờ 2 giây (tổng cộng 6 giây). Lần thử thứ tư thành công sau 0,7 giây, cho phép mã tiếp tục đến handleNetworkResponse. Tuy nhiên, thời gian chờ tích luỹ đã kích hoạt lỗi ANR.

Khắc phục lỗi ANR

Tránh loại lỗi ANR này bằng cách di chuyển các hoạt động liên quan đến mạng có độ trễ khác nhau sang một luồng trong nền thay vì thực thi các hoạt động đó trên luồng chính. Điều này giúp giao diện người dùng thích ứng ngay cả khi kết nối kém, loại bỏ lớp ANR này.

Tự động hoá quy trình điều tra lỗi ANR bằng tác nhân AI

Thay vì kiểm tra thủ công dòng thời gian và khoảng thời gian ngủ trong giao diện người dùng Perfetto, bạn có thể sử dụng một tác nhân lập trình AI được định cấu hình bằng kỹ năng AI của Perfetto để truy vấn dấu vết ANR và liên kết dấu vết đó với toàn bộ mã nguồn của bạn:

Analyze the Perfetto system trace at </path/to/trace.perfetto-trace>, which
corresponds to an ANR trace, and find the root cause of the ANR using the
Perfetto AI skill. The codebase is located at </path/to/codebase>.

Tác nhân truy vấn dấu vết bằng trace_processor và đưa ra kết luận giống như khi điều tra thủ công mà không bị nhầm lẫn bởi lát cắt handleNetworkResponse chưa hoàn tất ở cuối dấu vết. Công cụ này xác định rằng MyApp:SubmitButton đã chặn luồng chính trong hơn 9,2 giây, tái cấu trúc ba lần hết thời gian chờ mạng 2 giây và lần thử thứ tư 0,7 giây trong performNetworkRequest cùng với các vòng lặp chờ bận của CPU trong prepareNetworkRequest và handleNetworkResponse, đồng thời liên kết từng giai đoạn với ProfilingManagerJavaSnippets.java kèm theo đề xuất di chuyển onClickSubmit ra khỏi luồng giao diện người dùng:

# Perfetto ANR Root-Cause Analysis Report

* **Source Code:** `ProfilingManagerJavaSnippets.java`
* **Target Process:** `com.example.sampleapp` (`pid = 32579`, `upid = 27`)
* **Blocked Thread:** Main UI thread `ample.sampleapp` (`tid = 32579`, `utid = 760`)
* **Collection Mechanism:** Android `ProfilingManager` (`ProfilingTrigger.TRIGGER_TYPE_ANR`)

---

## 1. Executive Summary

> **Important:** The ANR in `com.example.sampleapp` is caused by executing **synchronous, blocking network retry logic (`Thread.sleep`) and heavy CPU busy-wait loops (`cpuIntensiveComputation`) directly on the main UI thread** inside the submit button click listener (`MyApp:SubmitButton` -> `onClickSubmit()`).

When the user taps the submit button at `7,967.78 ms` into the trace (`ts = 80459171444519`), the main UI thread is blocked continuously for **more than `9,281.30 ms`** (still unfinished when the trace ends at `17,249.08 ms`):

1. **`prepareNetworkRequest()`** runs a CPU busy-wait loop on the main thread for **`~1,019 ms`**.
2. **`performNetworkRequest(2000)`** executes in a synchronous `while` retry loop on the main thread. Each attempt begins with **`20 ms`** of CPU busy-waiting followed by a `Thread.sleep()`. The request times out (`2,000 ms` sleep) **3 times in a row** and succeeds on the **4th attempt** (`~701 ms` sleep), blocking the main thread for **`~6,764 ms`** across the 4 attempts (`6,703.18 ms` sleeping + `~60 ms` CPU).
3. **`handleNetworkResponse()`** begins at **`+7,783.44 ms`** after the button click and runs another `2,000 ms` CPU busy-wait loop on the main thread (`1,497.86 ms` captured before the trace ends).

    [Touch UP & Click (t = +0 ms)]
      -> prepareNetworkRequest() (~1,000 ms CPU Busy-Wait)
      -> Attempt #1 (Timeout: 20 ms CPU + 2,001 ms Sleep)
      -> Attempt #2 (Timeout: 20 ms CPU + 2,001 ms Sleep)
      -> Attempt #3 (Timeout: 20 ms CPU + 2,001 ms Sleep, crosses 5s ANR threshold)
      -> Attempt #4 (Success: 20 ms CPU + 701 ms Sleep)
      -> handleNetworkResponse() (1,498 ms CPU, unfinished at trace end)
## 2. PerfettoSQL Trace Analysis

### 2.1 Open Main-Thread Slices at Trace End

Querying `thread_or_process_slice` on the main thread (`utid = 760`) around and after the touch event shows that `MyApp:SubmitButton` and its nested slice `handleNetworkResponse` both have `dur = -1` (still open when the trace completed):

```sql
INCLUDE PERFETTO MODULE slices.with_context;

SELECT
  id,
  ts,
  (ts - trace_start()) / 1e6 AS rel_ts_ms,
  dur,
  IIF(dur = -1, trace_end() - ts, dur) / 1e6 AS effective_dur_ms,
  depth,
  name
FROM thread_or_process_slice
WHERE utid = 760 AND ts >= 80459169800000
ORDER BY ts;
```

| Slice ID | Slice Name | Start (`ts` ns) | Offset from Trace Start | Raw `dur` | Effective Duration (to trace end) | Depth |
| :--- | :--- | :--- | :--- | :--- | :--- | :--- |
| `40070` | `dispatchInputEvent MotionEvent UP` | `80459169801575` | `7,966.14 ms` | `190,633 ns` | `0.19 ms` | `0` |
| `40156` | **`MyApp:SubmitButton`** | `80459171444519` | `7,967.78 ms` | `-1` | **`9,281.30 ms`** | `0` |
| `97500` | **`handleNetworkResponse`** | `80466954886580` | `15,751.23 ms` | `-1` | **`1,497.86 ms`** | `1` |

---

### 2.2 Aggregate Main-Thread State (`thread_state`) During `MyApp:SubmitButton`

Aggregating `thread_state` for `utid = 760` from the start of `MyApp:SubmitButton` (`ts >= 80459171444519`) to the end of the trace reveals that the main thread spent **72.3%** of the time sleeping (`S`) and **27.6%** actively spinning on CPU (`Running`):

```sql
SELECT
  state,
  COUNT(*) AS cnt,
  SUM(dur) / 1e6 AS total_dur_ms,
  MIN(dur) / 1e6 AS min_dur_ms,
  MAX(dur) / 1e6 AS max_dur_ms
FROM thread_state
WHERE utid = 760 AND ts >= 80459171444519
GROUP BY state
ORDER BY total_dur_ms DESC;
```

| Thread State | Interval Count | Total Duration | Min Duration | Max Duration | Cause in Code |
| :--- | :--- | :--- | :--- | :--- | :--- |
| **`S` (Sleeping)** | `4` | **`6,703.18 ms`** | `700.78 ms` | `2,000.82 ms` | 4 `Thread.sleep()` calls in `performNetworkRequest()` |
| **`Running` (On CPU)** | `20` | **`2,559.81 ms`** | `0.00 ms` | `578.77 ms` | Busy-wait `while` loops in `cpuIntensiveComputation()` |
| **`R` (Runnable)** | `20` | **`2.11 ms`** | `0.01 ms` | `1.21 ms` | Scheduler wakeups and brief preemptions |

---

### 2.3 Phase-by-Phase Reconstruction (`thread_state` Intervals)

Querying individual `thread_state` intervals (`dur > 2 ms`) shows the exact sequence of CPU bursts and sleeps on the main thread:

```sql
SELECT
  ts,
  (ts - 80459171444519) / 1e6 AS ms_since_submit,
  dur / 1e6 AS dur_ms,
  state
FROM thread_state
WHERE utid = 760 AND ts >= 80459171444519 AND dur > 2e6
ORDER BY ts;
```

| Phase | Offset from Submit (`ms_since_submit`) | State | Duration (`dur_ms`) | Corresponding Code Execution |
| :--- | :--- | :--- | :--- | :--- |
| **1. Request Prep + Attempt #1 CPU** | `+0.63 ms` -> `+1,019.36 ms` | `Running` | **`1,018.68 ms`** *(across 5 slices)* | `prepareNetworkRequest()` (`1,000 ms` CPU) + Attempt #1 `cpuIntensiveComputation(20)` |
| **2. Network Attempt #1 (Timeout)** | `+1,019.36 ms` -> `+3,020.18 ms` | `S` (Sleep) | **`2,000.82 ms`** | `performNetworkRequest(2000)` -> `Thread.sleep(2000)` (`return false`) |
| **3. Network Attempt #2 (CPU)** | `+3,020.23 ms` -> `+3,040.24 ms` | `Running` | **`20.00 ms`** | Attempt #2 `cpuIntensiveComputation(20)` |
| **4. Network Attempt #2 (Timeout)** | `+3,040.24 ms` -> `+5,041.01 ms` | `S` (Sleep) | **`2,000.78 ms`** | `performNetworkRequest(2000)` -> `Thread.sleep(2000)` (`return false`) -- **5s input ANR threshold crossed** |
| **5. Network Attempt #3 (CPU)** | `+5,041.06 ms` -> `+5,061.30 ms` | `Running` | **`20.11 ms`** *(8.05 + 7.93 + 4.14 ms)* | Attempt #3 `cpuIntensiveComputation(20)` |
| **6. Network Attempt #3 (Timeout)** | `+5,061.30 ms` -> `+7,062.09 ms` | `S` (Sleep) | **`2,000.80 ms`** | `performNetworkRequest(2000)` -> `Thread.sleep(2000)` (`return false`) |
| **7. Network Attempt #4 (CPU)** | `+7,062.15 ms` -> `+7,082.38 ms` | `Running` | **`20.22 ms`** | Attempt #4 `cpuIntensiveComputation(20)` |
| **8. Network Attempt #4 (Success)** | `+7,082.38 ms` -> `+7,783.16 ms` | `S` (Sleep) | **`700.78 ms`** | `performNetworkRequest(2000)` hits `Math.random() < 0.2`, sleeps `~700 ms`, `return true` |
| **9. Handle Response (CPU)** | `+7,783.21 ms` -> `+9,281.30 ms` | `Running` | **`1,479.68 ms`** *(across 6 slices)* | `handleNetworkResponse()` (`Trace.beginSection("handleNetworkResponse")` at `+7,783.44 ms`) runs `cpuIntensiveComputation(2000)` until trace ends |

---

## 3. Code Mapping (`ProfilingManagerJavaSnippets.java`)

In `ProfilingManagerJavaSnippets.java` (lines `38` and `158-221`), the `OnClickListener` for `R.id.submit` runs `onClickSubmit()` directly on the main UI thread:

```java
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() {
  // 1. Blocks main thread on CPU for 1,000 ms
  prepareNetworkRequest();

  // 2. Synchronous retry loop on main thread (up to 10 attempts * 2,020 ms = 20.2 seconds!)
  boolean networkRequestSuccess = false;
  int maxAttempts = 10;
  while (!networkRequestSuccess && maxAttempts > 0) {
    networkRequestSuccess = performNetworkRequest(NETWORK_TIMEOUT_MILLISECS);
    maxAttempts--;
  }

  // 3. Blocks main thread on CPU for another 2,000 ms
  if (networkRequestSuccess) {
    handleNetworkResponse();
  }
}

boolean performNetworkRequest(int timeoutMilliseconds) {
  cpuIntensiveComputation(20);
  try {
    if (Math.random() < 0.2) {
      // Simulate performing a network request by waiting a random period of time
      int networkRequestTimeMs = (int) (Math.random() * timeoutMilliseconds);
      Thread.sleep(networkRequestTimeMs);
      return true;
    } else {
      // Simulate a timeout
      Thread.sleep(timeoutMilliseconds);
    }
  } catch (InterruptedException e) {
  }
  return false;
}

void cpuIntensiveComputation(int durationMs) {
  long start = System.currentTimeMillis();
  while (System.currentTimeMillis() - start < durationMs) {
  }
}

void prepareNetworkRequest() {
  cpuIntensiveComputation(1000);
}

public void handleNetworkResponse() {
  Trace.beginSection("handleNetworkResponse");
  cpuIntensiveComputation(2000);
  Trace.endSection();
}
```

---

## 4. Recommended Remediation

> **Tip:** Never perform network I/O, `Thread.sleep()`, or multi-hundred-millisecond CPU computations on the Android main UI thread.

1. **Offload `onClickSubmit()` to a Background Thread / Coroutine:**
   * In Java, dispatch `prepareNetworkRequest()`, the `performNetworkRequest()` retry loop, and heavy response processing in `handleNetworkResponse()` to a background `ExecutorService` (e.g., `Executors.newSingleThreadExecutor()`), then marshal only lightweight UI updates back to the main thread via `runOnUiThread(...)` or `View.post(...)`.
   * In Kotlin, use `lifecycleScope.launch(Dispatchers.IO)` (for network waiting) and `withContext(Dispatchers.Default)` (for CPU-intensive preparation/parsing).
2. **Use Non-Blocking / Asynchronous Retries with Backoff:**
   * Avoid holding threads with `Thread.sleep()` inside tight retry loops; use asynchronous HTTP client timeouts/retries or `WorkManager` for deferrable background network tasks.