דוגמה מעשית לניפוי באגים בביצועים: 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 trace slice. הפלח הזה היה בתוך הפלח MyApp:SubmitButton. הוא השתמש ב-1.48 שניות של זמן מעבד (איור 3).

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

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

כדי למצוא נקודת התחלה לחיפוש הגורם ל-ANR, מתחילים לחפש אחרי המסגרת האחרונה שנוצרה על ידי השרשור של ממשק המשתמש, שמתאימה לפלח 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) {
  // ...
}

  // ...
}

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

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

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

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