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

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

ממשק המשתמש של Perfetto שבו מוצג הפריימ האחרון שעבר רינדור על ידי שרשור ממשק המשתמש לפני שגיאת ה-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` בחלק.

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

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

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

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