דוגמה מעשית לניפוי באגים בביצועים: 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);
}
ProfilingManagerJavaSnippets.java

אחרי שמצלמים ומעלים את הנתונים של ANR, פותחים אותם בממשק המשתמש של Perfetto.

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

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

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

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

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

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

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

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

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

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

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

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

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

ממשק המשתמש של Perfetto שמציג את מרווח הזמן הראשון של שינה בתוך פרוסת המעקב MyAppSubmitButton.
איור 6. הזמן הראשון שבו המשתמש נכנס למצב שינה בתוך `MyAppSubmitButton`.
ממשק המשתמש של Perfetto שבו מוצג מרווח השינה השני בפרוסת המעקב MyAppSubmitButton.
איור 7. הזמן השני של השינה ב-`MyAppSubmitButton`.
ממשק המשתמש של Perfetto שמציג את מרווח השינה השלישי בפלח המעקב MyAppSubmitButton.
איור 8. שעת השינה השלישית ב-MyAppSubmitButton.
ממשק המשתמש של Perfetto שבו מוצג המרווח הרביעי של מצב שינה בפלח המעקב MyAppSubmitButton.
איור 9. הזמן הרביעי של השינה בתוך רכיב `MyAppSubmitButton`.

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

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

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

כדי לוודא זאת, בודקים את הקוד שמשויך לקטע MyApp:SubmitButton trace:

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

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

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

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