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

באגים הם חלק בלתי נפרד מכל סוג של פיתוח, ודוחות באגים הם חיוניים לזיהוי בעיות ולפתרון שלהן. כל הגרסאות של 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: verbose
  • D: ניפוי באגים
  • I: information
  • W: warning
  • E: error

 

תגים שימושיים נוספים של יומן האירועים מופיעים בכתובת /services/core/java/com/android/server/EventLogTags.logtags.

מקרי ANR וקיפאון

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

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

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

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

חיפוש דוחות קריסות

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

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

חיפוש מצבי קיפאון

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

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

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

פעילויות

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

צפייה בפעילויות שבהן מתמקדים

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

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

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

קביעה אם המכשיר מבצע פעולות שגורמות לשימוש מוגזם בזיכרון

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

זיכרון

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

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

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

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

צפייה בנתונים היסטוריים

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

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

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

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

איך מקבלים תמונת מצב של זיכרון

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

שידורים

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

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

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

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

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

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

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

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

צפייה במאזינים לשידור

כדי לראות רשימה של מקלטים שמקשיבים לשידור, בודקים את הטבלה ReceiverResolver ב-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]

קומפילציה ברקע

קומפילציה יכולה להיות יקרה ולעומס על המכשיר.

יכול להיות שהקומפילציה תתבצע ברקע בזמן ההורדה של עדכונים מחנות 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 מציין שהושלמה הפעולה של keyguard.

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

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

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

חבילות

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

תהליכים

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

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

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

הסיבות להרצת תהליך

בקטע dumpsys activity processes מפורטים כל התהליכים שפועלים כרגע, לפי סדר הניקוד oom_adj (מערכת Android מציינת את חשיבות התהליך על ידי הקצאת ערך oom_adj לתהליך, שאפשר לעדכן אותו באופן דינמי באמצעות ActivityManager). הפלט דומה לזה של תמונת מצב של הזיכרון, אבל הוא כולל מידע נוסף על הגורם להרצת התהליך. בדוגמה שלמטה, הערכים המודגשים מציינים שתהליך 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 #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).