מקרה לדוגמה: ניפוי באגים של ANR

בדף הזה מוסבר איך לנפות באגים בשגיאה מסוג האפליקציה לא מגיבה (ANR) באמצעות ProfilingManager, עם דוגמה לעקבות המערכת.

הגדרת האפליקציה לאיסוף אירועי ANR

כדי להתחיל, מגדירים טריגר של ANR באפליקציה:

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

אחרי שמתעדים ומעלים דוח מעקב של ANR, אפשר לבדוק אותו ידנית בממשק המשתמש של Perfetto, כמו שמתואר בשלבים הבאים, או להפוך את חקירת ה-ANR לאוטומטית באמצעות סוכן AI.

ניתוח נתוני המעקב

מכיוון ששגיאת ה-ANR הפעילה את המעקב, אתם יודעים שהמעקב הסתיים כשהמערכת זיהתה חוסר תגובה בשרשור הראשי של האפליקציה (או כשחלף הזמן הקצוב לתפוגה). באיור 1 מוצג איך לנווט לשרשור הראשי של האפליקציה, שמתויג בהתאם בממשק המשתמש.

ניווט בממשק המשתמש של Perfetto ל-thread הראשי של האפליקציה.
איור 1. ניווט ל-thread הראשי של האפליקציה.

סוף המעקב תואם לחותמת הזמן של ה-ANR, כפי שמוצג באיור 2.

ממשק המשתמש של Perfetto שבו רואים את הסוף של המעקב, ומדגיש את המיקום של הטריגר של ה-ANR.
איור 2. המיקום שבו הופעל ה-ANR.

כשהתרחש ה-ANR, השרשור הראשי הריץ את הפרוסה handleNetworkResponse בתוך MyApp:SubmitButton, שצרכה 1.48 שניות של זמן מעבד (איור 3).

ממשק המשתמש של Perfetto שמציג את זמן ה-CPU שנוצל על ידי הפעלת handleNetworkResponse בזמן ה-ANR.
איור 3. ההרצה בזמן ה-ANR.

אם מסתמכים רק על דוח קריסות שנוצר ברגע שבו התרחשה שגיאת ה-ANR, יכול להיות שהקיפאון ייוחס בטעות ל-handleNetworkResponse. עם זאת, 1.48 שניות לא מספיקות כדי להפעיל ANR, אז צריך לבדוק מה חסם את ה-thread הראשי לפני כן.

קודם כל, מאתרים את הפריים האחרון של ממשק המשתמש שעבר רינדור לפני ההקפאה (Choreographer#doFrame 551275), שמופיע מיד לפני הפרוסה MyApp:SubmitButton (איור 4).

ממשק המשתמש של Perfetto שבו מוצג הפריים האחרון שעבר רינדור על ידי שרשור ה-UI לפני ה-ANR.
איור 4. הפריים האחרון של האפליקציה שנוצר לפני ה-ANR.

כדי להבין את החסימה, מקטינים את התצוגה כדי לבדוק את כל הפרוסה של MyApp:SubmitButton. שימו לב לפרט חשוב במצבי ה-thread בטווח שנבחר ידנית באיור 5: ה-thread היה בערך 75% מהזמן (6.7 שניות) במצב Sleeping ורק 24% מהזמן במצב Running.

ממשק המשתמש של Perfetto שמציג מצבי שרשורים במהלך פעולה, ומדגיש 75% זמן שינה ו-24% זמן ריצה.
איור 5. מצבי השרשור במהלך הפעולה MyApp:SubmitButton.

זה מצביע על כך שהסיבה העיקרית ל-ANR הייתה המתנה, ולא חישוב. בודקים את מופעי השינה הספציפיים כדי לזהות דפוס.

ממשק המשתמש של Perfetto שמציג את מרווח השינה הראשון בתוך פרוסת המעקב MyAppSubmitButton.
איור 6. שעת השינה הראשונה בטווח של MyApp:SubmitButton.
ממשק המשתמש של Perfetto שמציג את מרווח השינה השני בתוך פרוסת המעקב MyAppSubmitButton.
איור 7. זמן השינה השני בתוך MyApp:SubmitButton.
ממשק המשתמש של Perfetto שמציג את מרווח השינה השלישי בתוך פרוסת המעקב MyAppSubmitButton.
איור 8. פרק השינה השלישי בתוך MyApp:SubmitButton.
ממשק המשתמש של Perfetto שמציג את מרווח הזמן הרביעי של מצב השינה בתוך פרוסת המעקב MyAppSubmitButton.
תרשים 9. זמן השינה הרביעי בתוך MyApp:SubmitButton.

שלושת מרווחי השינה הראשונים (איורים 6-8) הם של כ-2 שניות כל אחד, והמרווח הרביעי (איור 9) הוא של 0.7 שניות. הפסקות חוזרות של 2 שניות מצביעות על כך שזמן קצוב לתפוגה שתוכנת ניסה שוב שלוש פעמים לפני שהצליח בניסיון הרביעי – והצטבר מספיק עיכוב כדי להפעיל ANR (איור 10).

ממשק המשתמש של Perfetto מציג סיכום של העיכובים במהלך פרוסת המעקב MyApp:SubmitButton, ומציין כמה מרווחי שינה של 2 שניות.
איור 10. סיכום העיכובים במהלך פרוסת MyApp:SubmitButton.

זיהוי שורש הבעיה בקוד

כדי לאמת את ההשערה הזו, בודקים את הקוד שמשויך לקטע המעקב 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();
}

הקוד מאשר את ההשערה הזו. ה-method‏ onClickSubmit מפעילה בקשה לאחזור מהרשת בשרשור ה-UI עם NETWORK_TIMEOUT_MILLISECS בקידוד קשיח של 2,000 אלפיות השנייה. חשוב לציין שהיא פועלת בתוך לולאת while שמנסה שוב עד 10 פעמים.

במעקב הספציפי הזה, סביר להניח שהחיבור של המשתמש לרשת היה חלש. שלושת הניסיונות הראשונים נכשלו, וגרמו לשלושה פסקי זמן של 2 שניות (סה"כ 6 שניות). הניסיון הרביעי הצליח אחרי 0.7 שניות, והקוד המשיך ל-handleNetworkResponse. עם זאת, זמן ההמתנה המצטבר כבר הפעיל את ה-ANR.

תיקון ה-ANR

כדי להימנע מסוג כזה של ANR, צריך להעביר פעולות שקשורות לרשת עם זמני אחזור משתנים ל-thread ברקע, במקום להפעיל אותן ב-thread הראשי. כך ממשק המשתמש נשאר רספונסיבי גם כשהקישוריות איטית, ואין יותר שגיאות ANR מהסוג הזה.

אוטומציה של חקירת שגיאות ANR באמצעות סוכן AI

במקום לבדוק באופן ידני את צירי הזמן ואת מרווחי הזמן של השינה בממשק המשתמש של Perfetto, אתם יכולים להשתמש בסוכן תכנות מבוסס-AI שמוגדר עם מיומנות ה-AI של Perfetto כדי לשלוח שאילתה לגבי המעקב אחרי ה-ANR ולקשר אותו לבסיס הקוד שלכם:

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>.

הסוכן שולח שאילתה לגבי המעקב באמצעות trace_processor ומגיע לאותה מסקנה כמו בבדיקה הידנית – בלי שהפרוסה הלא גמורה של handleNetworkResponse בסוף המעקב תטעה אותו. הוא מזהה ש-MyApp:SubmitButton חסם את השרשור הראשי למשך יותר מ-9.2 שניות, משחזר את שלושת פסקי הזמן הקצובים של הרשת למשך 2 שניות ואת הניסיון הרביעי למשך 0.7 שניות ב-performNetworkRequest לצד לולאות ההמתנה הפעילה של המעבד (CPU) ב-prepareNetworkRequest וב-handleNetworkResponse, וממפה כל שלב ל-ProfilingManagerJavaSnippets.java עם המלצה להעביר את onClickSubmit מחוץ לשרשור ה-UI:

# 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.