דוגמה מעשית לניפוי באגים בביצועים: 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 מראה איך לנווט אל השרשור הראשי של האפליקציה, שתויג בהתאם בממשק המשתמש.

ניווט בממשק המשתמש של 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: השרשור בילה 75% מהזמן (6.7 שניות) בסטטוס Sleeping ורק 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` בחלק.

כדי לוודא זאת, בודקים את הקוד שמשויך לקטע 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 מבצעת בקשת רשת בשרשור של ממשק המשתמש עם NETWORK_TIMEOUT_MILLISECS שמוגדר מראש כ-2,000ms. חשוב לציין שהיא פועלת בתוך לולאת while שמנסה לבצע את הפעולה עד 10 פעמים.

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

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