הסבר על systrace

‫systrace הוא הכלי העיקרי לניתוח הביצועים של מכשירי Android. אבל למעשה מדובר בעטיפה של כלים אחרים. היא עוטפת בצד המארח את atrace, קובץ ההפעלה בצד המכשיר ששולט במעקב אחר מרחב המשתמש ומגדיר את ftrace, ומנגנון המעקב העיקרי בליבת Linux. ‏systrace משתמשת ב-atrace כדי להפעיל מעקב, ואז קוראת את המאגר של ftrace ועוטפת את הכול בכלי לצפייה ב-HTML עצמאי. (למרות שלליבות חדשות יותר יש תמיכה ב-Linux Enhanced Berkeley Packet Filter ‏ (eBPF), הדף הזה מתייחס לליבה 3.18 (ללא eFPF), כי זו הליבה שנעשה בה שימוש ב-Pixel או ב-Pixel XL).

הכלי systrace הוא בבעלות צוותי Google Android ו-Google Chrome, והוא מקור פתוח כחלק מפרויקט Catapult. בנוסף ל-systrace, ‏ Catapult כולל כלי עזר שימושיים אחרים. לדוגמה, ל-ftrace יש יותר תכונות מאלה שאפשר להפעיל ישירות באמצעות systrace או atrace, והוא כולל פונקציונליות מתקדמת שחיונית לניפוי באגים בבעיות ביצועים. (כדי להשתמש בתכונות האלה נדרשת גישת שורש, ולעתים קרובות גם ליבה חדשה).

הרצת systrace

כשמבצעים ניפוי באגים של ג'יטר ב-Pixel או ב-Pixel XL, מתחילים עם הפקודה הבאה:

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

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

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

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

דוגמה: מסגרת עבודה

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

עבור עומס עבודה עקבי ומחזורי כמו TouchLatency, צינור העיבוד בממשק המשתמש פועל לפי הרצף הבא:

1. ‫EventThread ב-SurfaceFlinger מעיר את השרשור של ממשק המשתמש של האפליקציה, ומאותת שהגיע הזמן לעבד פריים חדש.
2. האפליקציה מעבדת פריים בשרשור ממשק המשתמש, ב-RenderThread ובמשימות HWUI, באמצעות משאבי CPU ו-GPU. זהו רוב הקיבולת שמוקצה לממשק המשתמש.
3. האפליקציה שולחת את המסגרת המעובדת ל-SurfaceFlinger באמצעות binder, ואז SurfaceFlinger נכנס למצב שינה.
4. ‫EventThread שני ב-SurfaceFlinger מעיר את SurfaceFlinger כדי להפעיל את הפלט של הקומפוזיציה והתצוגה. אם SurfaceFlinger קובע שאין עבודה לבצע, הוא חוזר למצב שינה.
5. ‫SurfaceFlinger מטפל בהרכבה באמצעות Hardware Composer ‏ (HWC) או Hardware Composer 2 ‏ (HWC2) או GL. ההרכב HWC ו-HWC2 מהיר יותר וצורכת פחות חשמל, אבל יש לו מגבלות בהתאם למערכת על שבב (SoC). בדרך כלל התהליך הזה נמשך כ-4 עד 6 אלפיות השנייה, אבל הוא יכול לחפוף לשלב 2 כי אפליקציות ל-Android תמיד משתמשות בשיטת ה-triple buffering. (למרות שהאפליקציות תמיד משתמשות בזיכרון משולש, יכול להיות שיש רק פריים אחד בהמתנה ב-SurfaceFlinger, ולכן זה נראה כאילו נעשה שימוש בזיכרון כפול).
6. ‫SurfaceFlinger שולח את הפלט הסופי לתצוגה באמצעות מנהל התקן של ספק, ואז חוזר למצב שינה וממתין להפעלה של EventThread.

דוגמה לרצף פריים שמתחיל ב-15409 אלפיות השנייה:

איור 1. צינור עיבוד נתונים רגיל של ממשק המשתמש, EventThread פועל.

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

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

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

בזמן ש-EventThread פועל, ה-UI thread של TouchLatency הופך ל-runnable. כדי לראות מה הפעיל אותו, לוחצים על הקטע הכחול.

איור 2. שרשור UI עבור TouchLatency.

איור 2 מראה שהשרשור של ממשק המשתמש TouchLatency הופעל על ידי tid 6843, שמתאים ל-EventThread. ה-UI thread מתעורר, מעבד פריים ומכניס אותו לתור של SurfaceFlinger לצריכה.

איור 3. ה-UI thread מתעורר, מעבד פריים ומכניס אותו לתור כדי ש-SurfaceFlinger יצרוך אותו.

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

איור 4. עסקת Binder.

איור 4 מראה שב-15,423.65 ms‏ Binder:6832_1 ב-SurfaceFlinger הופך ל-runnable בגלל tid 9579, שהוא RenderThread של TouchLatency. אפשר גם לראות את queueBuffer בשני הצדדים של עסקת ה-binder.

במהלך queueBuffer בצד SurfaceFlinger, מספר הפריימים בהמתנה מ-TouchLatency עולה מ-1 ל-2.

איור 5. מסגרות בהמתנה: 1 עד 2.

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

זמן קצר לאחר מכן, ה-thread הראשי של SurfaceFlinger מופעל על ידי EventThread שני כדי שיוכל להציג את הפריים הישן יותר שממתין:

איור 6. ה-thread הראשי של SurfaceFlinger מופעל על ידי EventThread שני.

קודם כל, SurfaceFlinger נועל את המאגר הישן יותר שממתין, מה שגורם לירידה במספר המאגרים שממתינים מ-2 ל-1:

איור 7. ‫SurfaceFlinger קודם ננעל למאגר הישן יותר שממתין.

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

איור 8. ‫SurfaceFlinger מגדיר את הקומפוזיציה ושולח את הפריים הסופי.

הבא, mdss_fb0 מתעורר במעבד 0. ‫mdss_fb0 הוא שרשור הליבה של צינור העיבוד לתצוגה, שמוציא פריים שעבר רינדור לתצוגה. שימו לב ש-mdss_fb0 היא שורה נפרדת בנתוני המעקב (צריך לגלול למטה כדי לראות אותה):

איור 9. mdss_fb0 מתעורר במעבד 0.

‫mdss_fb0 מתעורר, פועל לזמן קצר, נכנס למצב שינה שאי אפשר להפריע לו ואז מתעורר שוב.

דוגמה: מסגרת לא תקינה

בדוגמה הזו מתואר systrace שמשמש לניפוי באגים של ג'יטר ב-Pixel או ב-Pixel XL. כדי לעקוב אחרי הדוגמה, מורידים את קובץ ה-ZIP של העקבות (שכולל עקבות אחרים שמוזכרים בקטע הזה), מבטלים את הדחיסה של הקובץ ופותחים את הקובץ systrace_tutorial.html בדפדפן.

כשפותחים את systrace, רואים משהו כמו באיור הבא:

איור 10. האפליקציה TouchLatency פועלת ב-Pixel XL עם רוב האפשרויות מופעלות.

באיור 10, רוב האפשרויות מופעלות, כולל נקודות מעקב mdss ו-kgsl.

כשמחפשים ג'אנק, בודקים את השורה FrameMissed בקטע SurfaceFlinger. התכונה FrameMissed היא שיפור באיכות החיים שמספקת HWC2. כשמציגים את systrace למכשירים אחרים, יכול להיות שהשורה FrameMissed לא תופיע אם המכשיר לא משתמש ב-HWC2. בכל מקרה, הערך FrameMissed מתואם למצב שבו SurfaceFlinger פספס אחת מהפעולות הרגילות שלו, ומספר המאגרים בהמתנה לא השתנה באפליקציה (com.prefabulated.touchlatency) ב-VSync.

איור 11. מתאם FrameMissed עם SurfaceFlinger.

איור 11 מציג פריימים שהוחמצו ב-15598.29 ms. ‏SurfaceFlinger התעורר לזמן קצר במרווח VSync וחזר למצב שינה בלי לבצע פעולה כלשהי, מה שאומר ש-SurfaceFlinger קבע שלא כדאי לנסות לשלוח שוב פריימים לתצוגה.

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

איור 12. ‫SurfaceFlinger מתעורר ומיד נכנס למצב שינה.

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

נקודות המעקב mdss ו-sync מופעלות, כך שתוכלו לקבל מידע על הגדרות (משותף בין מנהל התקן המסך ל-SurfaceFlinger) שקובעים מתי פריימים נשלחים למסך. הגדרות הגדרות הגידור האלה מפורטות בקטע mdss_fb0_retire, שבו מצוין מתי פריים מוצג. הגדרות הגבול האלה מסופקות כחלק מקטגוריית המעקב sync. הגדרת הגדרות ה-fence שמתאימות לאירועים מסוימים ב-SurfaceFlinger תלויה ב-SOC ובמערך מנהלי ההתקנים שלכם, ולכן כדאי לפנות לספק ה-SOC כדי להבין את המשמעות של קטגוריות ה-fence בנתוני המעקב.

איור 13. mdss_fb0_retire fences.

באיור 13 מוצג פריים שהוצג למשך 33 אלפיות השנייה, ולא למשך 16.7 אלפיות השנייה כמו שציפינו. באמצע החלק הזה, היה צריך להחליף את הפריים בפריים חדש, אבל זה לא קרה. צפייה בפריים הקודם וחיפוש של משהו.

איור 14. הפריים הקודם לפריים הפגום.

איור 14 מציג מסגרת של 14.482 ms. הקטע הפגום של שני הפריימים היה 33.6 ms, שזה בערך מה שצפוי לשני פריימים (מעובדים ב-60 Hz, ‏ 16.7 ms לכל פריים, שזה קרוב). אבל 14.482 ms לא קרוב ל-16.7 ms, מה שמצביע על בעיה בצינור התצוגה.

כדי לדעת מה שולט בגדר הזו, צריך לבדוק בדיוק איפה היא מסתיימת:

איור 15. בדיקת סיום הגדר.

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

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

איור 16. הפריים הקודם.

השורה שאפשר להריץ ב-kworker לא מוצגת כי הצופה הופך אותה ללבנה כשהיא נבחרת, אבל הנתונים הסטטיסטיים מספרים את הסיפור: עיכוב של 2.3 ms בתזמון של חלק מנתיב קריטי של צינור התצוגה הוא גרוע. לפני שממשיכים, צריך לתקן את העיכוב על ידי העברת החלק הזה של הנתיב הקריטי של צינור העיבוד של התצוגה מתור עבודה (שפועל כשרשור SCHED_OTHERCFS) ל-kthread ייעודי.SCHED_FIFO הפונקציה הזו צריכה ערבויות לגבי תזמון שלא ניתן לספק באמצעות תורי עבודה (workqueues) (ולא מיועדת לכך).

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

בדוגמה הזו, הפתרון כולל המרה של __vsync_retire_work_handler מתור עבודה ל-kthread ייעודי. כתוצאה מכך, יש שיפורים ניכרים ב-jitter ופחות תנודות בבדיקת הכדור הקופץ. במעקבים הבאים מוצגים תזמונים של גדרות שקרובים מאוד ל-16.7 אלפיות השנייה.