קריאת דוחות איתור באגים

באגים הם מציאות בכל סוג של פיתוח, ודוחות על באגים הם קריטיים לזיהוי ולפתרון בעיות. בכל הגרסאות של Android יש תמיכה בתיעוד דוחות באגים באמצעות Android Debug Bridge‏ (adb). בגרסאות Android 4.2 ואילך יש תמיכה באפשרות למפתחים לתיעוד דוחות באגים ולשיתוף שלהם באימייל, ב-Drive וכו'.

דוחות באגים של Android מכילים נתונים של dumpsys,‏ dumpstate ו-logcat בפורמט טקסט (‎.txt), כך שתוכלו לחפש בקלות תוכן ספציפי. בקטעים הבאים מפורטים הרכיבים של דוח הבאג, מתוארות בעיות נפוצות ומופיעים טיפים שימושיים ופקודות grep למציאת יומנים שמשויכים לבאגים האלה. רוב הקטעים כוללים גם דוגמאות לפקודה grep ולפלט שלה ו/או לפלט של dumpsys.

Logcat

יומן logcat הוא קובץ dump שמכיל את כל המידע של logcat, שמבוסס על מחרוזת. החלק system מיועד למסגרת, ויש לו היסטוריה ארוכה יותר מאשר לחלק main שמכיל את כל השאר. בדרך כלל כל שורה מתחילה ב-timestamp UID PID TID log-level, אבל יכול להיות שה-UID לא יופיע בגרסאות ישנות יותר של Android.

הצגת יומן האירועים

היומן הזה מכיל ייצוגים של מחרוזות של הודעות יומן בפורמט בינארי. הוא מכיל פחות נתונים מאשר היומן logcat, אבל גם קשה יותר לקרוא אותו. כשמציגים יומני אירועים, אפשר לחפש בקטע הזה מזהה תהליך (PID) ספציפי כדי לראות מה התהליך עשה. הפורמט הבסיסי הוא: timestamp PID TID log-level log-tag tag-values.

רמות היומן כוללות את הרמות הבאות:

  • V: דרגת מלל
  • D: ניפוי באגים
  • I: מידע
  • W: אזהרה
  • E: שגיאה

 

תגים שימושיים אחרים ביומן האירועים מפורטים בקטע /services/core/java/com/android/server/EventLogTags.logtags.

מקרי ANR ונעילה מרומזת

דוחות באגים יכולים לעזור לכם לזהות את הגורם לשגיאות מסוג Application Not Responding (ANR) ולאירועי נעילה מרומזת.

זיהוי אפליקציות שלא מגיבות

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

אפשר גם להריץ grep עבור ANR in ביומן logcat, שמכיל מידע נוסף על הגורם שהשתמש ב-CPU בזמן ה-ANR.

חיפוש מעקבי ערימה

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

  • ה-thread הראשי מראה רק מה ה-thread עשה בזמן ה-ANR, ויכול להיות שהפעילות הזו תואמת לגורם האמיתי של ה-ANR ויכול להיות שלא. (יכול להיות שהסטאק בדוח הבאגים לא קשור לבעיה. יכול להיות שמשהו אחר נתקע במשך זמן רב, אבל לא מספיק זמן כדי לגרום ל-ANR, לפני שהבעיה נפתרה).
  • יכול להיות שיהיו כמה קבוצות של נתוני סטאק (VM TRACES JUST NOW ו-VM TRACES AT LAST ANR). חשוב לוודא שמוצג הקטע הנכון.

חיפוש נעילה מרומזת

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

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

כדי למצוא נעילה מרומזת, בודקים את הקטעים של מעקב ה-VM כדי למצוא תבנית של חוט A שממתין למשהו שנמצא בחזקת חוט B, וחוט B בתורו ממתין למשהו שנמצא בחזקת חוט A.

פעילויות

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

הצגת פעילויות שמתמקדות בנושא מסוים

כדי להציג את ההיסטוריה של הפעילויות במצב התמקדות, מחפשים את האפשרות am_focused_activity.

תהליך הצפייה מתחיל

כדי להציג את היסטוריית ההפעלות של התהליך, מחפשים את Start proc.

איך בודקים אם המכשיר נתון לטרחה (thrashing)

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

זיכרון

לרוב, במכשירי Android יש נפח זיכרון פיזי מוגבל, ולכן חשוב מאוד לנהל את הזיכרון הזמין (RAM). דוחות באגים מכילים כמה אינדיקטורים לזיכרון נמוך, וגם dumpstate שמספק קובץ snapshot של הזיכרון.

זיהוי מצב של זיכרון נמוך

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

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

הצגת מדדים היסטוריים

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

הצגת אינדיקטורים לטרחה

אינדיקטורים נוספים לפעילות מוגזמת של המערכת (דפים, חזרה לשימוש ישיר וכו') כוללים את מחזורי הצריכה של kswapd,‏ kworker ו-mmcqd. (חשוב לזכור שדיווח הבאגים שנאסף יכול להשפיע על מדדי הטרחה).

יומני ANR יכולים לספק תמונת מצב דומה של הזיכרון.

אחזור תמונת מצב של זיכרון

תמונת המצב של הזיכרון היא קובץ dumpstate שמכיל רשימה של תהליכי Java ותהליכים נייטיב שפועלים (פרטים נוספים זמינים במאמר הצגת הקצאות הזיכרון הכוללות). חשוב לזכור שתמונת המצב משקפת רק את המצב של המערכת ברגע נתון. יכול להיות שהמערכת הייתה במצב טוב יותר (או גרוע יותר) לפני יצירת תמונת המצב.

שידורים

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

צפייה בשידורים היסטוריים

שידורים היסטוריים הם שידורים שכבר נשלחו, והם מפורטים בסדר כרונולוגי הפוך.

הקטע summary הוא סקירה כללית של 300 השידורים האחרונים בחזית ושל 300 השידורים האחרונים ברקע.

הקטע detail מכיל מידע מלא על 50 השידורים האחרונים בחזית ו-50 השידורים האחרונים ברקע, וגם על המקלטים של כל שידור. נמענים שיש להם:

  • הרישום של הרשומה BroadcastFilter מתבצע בזמן הריצה והיא נשלחת רק לתהליכים שכבר פועלים.
  • הרשומות של ResolveInfo נרשמות באמצעות רשומות מניפסט. אם התהליך של כל ResolveInfo לא פועל, ה-ActivityManager מתחיל אותו.

הצגת שידורים פעילים

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

הצגת המאזינים לשידור

כדי להציג רשימה של מקלטים שמאזינים לשידור, בודקים את טבלת פתרון המקלטים ב-dumpsys activity broadcasts. בדוגמה הבאה מוצגים כל המקלטים שמאזינים ל-USER_PRESENT.

מעקב אחר תחרות

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

ביומן המערכת:

10-01 18:12:44.343 29761 29914 W art     : Long monitor contention event with owner method=void android.database.sqlite.SQLiteClosable.acquireReference() from SQLiteClosable.java:52 waiters=0 for 3.914s

ביומן האירועים:

10-01 18:12:44.364 29761 29914 I dvm_lock_sample: [com.google.android.youtube,0,pool-3-thread-9,3914,ScheduledTaskMaster.java,138,SQLiteClosable.java,52,100]

הידור ברקע

תהליך ה-compilation יכול להיות יקר ולטעון את המכשיר.

הדרישה עשויה להתבצע ברקע בזמן הורדת עדכונים מחנות Google Play. במקרה כזה, הודעות מאפליקציית חנות Google Play‏ (finsky) ומ-installd מופיעות לפני הודעות dex2oat.

הידור יכול להתרחש גם ברקע כשאפליקציה טוענת קובץ dex שעדיין לא עבר הידור. במקרה כזה, לא תראו רישום ביומן של finsky או installd.

סיפורית

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

סנכרון של צירי זמן

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

חותמות הזמן ביומן המערכת וביומן האירועים הן לפי אזור הזמן של המשתמש (כמו רוב חותמות הזמן האחרות). לדוגמה, כשהמשתמש מקשיב על לחצן הבית, ביומן המערכת מדווחים:

10-03 17:19:52.939  1963  2071 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0

לאותה פעולה, יומן האירועים מדווח על:

10-03 17:19:54.279  1963  2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]

ביומני הליבה (dmesg) נעשה שימוש בבסיס זמן שונה, שבו הפריטים ביומן מתויגים בשניות מאז השלמת האתחול. כדי לרשום את ציר הזמן הזה לצירי זמן אחרים, מחפשים את ההודעות suspend exit ו-suspend entry:

<6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC
…
<6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC

יכול להיות שיומני הליבה לא יכללו את הזמן במצב השהיה, לכן צריך לרשום את היומן בין הודעות הכניסה והיציאה מההשהיה. בנוסף, יומני הליבה משתמשים באזור הזמן UTC, וצריך להתאים אותם לאזור הזמן של המשתמש.

זיהוי הזמן של דוח הבאג

כדי לקבוע מתי נוצר דוח הבאג, צריך לבדוק קודם את יומן המערכת (Logcat) של dumpstate: begin:

10-03 17:19:54.322 19398 19398 I dumpstate: begin

בשלב הבא, בודקים את חותמות הזמן ביומן הליבה (dmesg) כדי למצוא את ההודעה Starting service 'bugreport':

<5>[207064.285315] init: Starting service 'bugreport'...

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

כוח

יומן האירועים מכיל את סטטוס ההפעלה של המסך, כאשר 0 הוא מסך כבוי, 1 הוא מסך מופעל ו-2 הוא סיום של מסך הנעילה.

דוחות הבאגים מכילים גם נתונים סטטיסטיים על נעילת התעוררות (wake lock), מנגנון שמפתחי אפליקציות משתמשים בו כדי לציין שהאפליקציה שלהם צריכה להישאר במצב מופעל. (פרטים על חסימות מצב שינה זמינים במאמרים PowerManager.WakeLock ו-הפעלת המעבד).

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

כדי לקבל עזרה נוספת ביצירת תצוגה חזותית של סטטוס הטעינה, תוכלו להשתמש ב-Battery Historian – כלי קוד פתוח של Google לניתוח גורמים שצורכים סוללה באמצעות קובצי bugreport של Android.

חבילות

הקטע DUMP OF SERVICE package מכיל את הגרסאות של האפליקציות (ופרטים שימושיים אחרים).

תהליכים

דוחות באגים מכילים כמות עצומה של נתונים על תהליכים, כולל שעת ההתחלה והעצירה, משך זמן הריצה, השירותים המשויכים, הציון של oom_adj וכו'. למידע נוסף על האופן שבו Android מנהלת תהליכים, אפשר לעיין במאמר תהליכים וחיובים.

קביעת זמן הריצה של התהליך

הקטע procstats מכיל נתונים סטטיסטיים מלאים לגבי משך הזמן שבו התהליכים והשירותים המשויכים פועלים. כדי לקבל סיכום מהיר שקל לקריאה, מחפשים את AGGREGATED OVER כדי להציג נתונים מ-3 השעות האחרונות או מ-24 השעות האחרונות, ואז מחפשים את Summary: כדי להציג את רשימת התהליכים, את משך הזמן שבו התהליכים האלה פעלו בעדיפויות שונות ואת השימוש שלהם ב-RAM בפורמט min-average-max PSS/min-average-max USS.

סיבות לכך שתהליך פועל

בקטע dumpsys activity processes מפורטים כל התהליכים שפועלים כרגע, לפי דירוג oom_adj (מערכת Android מציינת את החשיבות של התהליך על ידי הקצאת ערך oom_adj לתהליך, ש-ActivityManager יכול לעדכן באופן דינמי). הפלט דומה לזה של snapshot של זיכרון, אבל כולל מידע נוסף על מה שגורם לתהליך לפעול. בדוגמה הבאה, הרשומות המודגשות מציינות שהתהליך gms.persistent פועל בעדיפות vis (גלויה) כי תהליך המערכת קשור ל-NetworkLocationService שלו.

סריקות

כדי לזהות אפליקציות שמבצעות סריקות Bluetooth עם צריכת אנרגיה נמוכה (BLE) באופן מוגזם:

  • חיפוש הודעות ביומן עבור BluetoothLeScanner:
    $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
    07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
    
  • מאתרים את ה-PID בהודעות ביומן. בדוגמה הזו, הערכים '24840' ו-'24851' הם PID (מזהה תהליך) ו-TID (מזהה חוט).
  • מאתרים את האפליקציה שמשויכת למזהה ה-PID:
    PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}
    

    בדוגמה הזו, שם החבילה הוא com.badapp.

  • מחפשים את שם החבילה ב-Google Play כדי לזהות את האפליקציה האחראית: https://play.google.com/store/apps/details?id=com.badapp.

הערה: במכשירים עם Android 7.0, המערכת אוספת נתונים של סריקות BLE ומשייכת את הפעילויות האלה לאפליקציה שהפעילה אותן. למידע נוסף, קראו את המאמר סקנים של Bluetooth עם צריכת אנרגיה נמוכה (LE).