systrace הוא הכלי העיקרי לניתוח ביצועי מכשירי Android. עם זאת, הוא בעצם מעטפת של כלים אחרים. זהו מעטפת בצד המארח של atrace, קובץ ההפעלה בצד המכשיר ששולט במעקב אחרי מרחב המשתמש ומגדיר את ftrace, וגם מנגנון המעקב הראשי בליבה של Linux. systrace משתמש ב-atrace כדי להפעיל מעקב, ואז קורא את מאגר ה-ftrace ומעביר את כולם לצופה HTML עצמאי. (לליבת Linux בגרסאות חדשות יותר יש תמיכה ב-Linux Enhanced Berkeley Packet Filter (eBPF), אבל המסמכים הבאים רלוונטיים לליבה 3.18 (ללא eFPF), כי זו הליבה שבה נעשה שימוש ב-Pixel/Pixel XL).
systrace נמצא בבעלות צוותי Google Android ו-Google Chrome, והוא זמין כקוד פתוח במסגרת פרויקט Catapult. בנוסף ל-systrace, Catapult כולל תוכנות שימושיות נוספות. לדוגמה, ל-ftrace יש יותר תכונות ממה שאפשר להפעיל ישירות באמצעות systrace או atrace, והוא מכיל פונקציונליות מתקדמת מסוימת שחשובה מאוד לניפוי באגים בבעיות ביצועים. (התכונות האלה דורשות הרשאת root ולרוב גם ליבה חדשה).
הרצת systrace
כשמבצעים ניפוי באגים של רעידות ב-Pixel או ב-Pixel XL, מתחילים בפקודה הבאה:
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
בשילוב עם נקודות המעקב הנוספות שנדרשות לפעילות של צינור עיבוד הנתונים של המעבד הגרפי (GPU) ושל צינור עיבוד הנתונים של המסך, אפשר לעקוב מהקלט של המשתמש ועד לפריים שמוצג במסך. מומלץ להגדיר את גודל המאגר לגודל גדול כדי למנוע אובדן אירועים (כי בלי מאגר גדול, מעבדים מסוימים לא מכילים אירועים אחרי שלב מסוים במעקב).
כשבודקים את systrace, חשוב לזכור שכל אירוע מופעל על ידי משהו במעבד (CPU).
מכיוון ש-systrace מבוסס על ftrace ו-ftrace פועל ב-CPU, צריך משהו ב-CPU שכותב את מאגר הנתונים של ftrace שמתעדים שינויים בחומרה. כלומר, אם אתם רוצים לדעת למה מחסום תצוגה שינה את המצב שלו, תוכלו לראות מה הופעל ב-CPU בנקודת המעבר המדויקת (משהו שהופעל ב-CPU גרם לשינוי הזה ביומן). המושג הזה הוא הבסיס לניתוח הביצועים באמצעות systrace.
דוגמה: מסגרת עבודה
בדוגמה הזו מתוארת ניתוח נתונים בזמן אמת של צינור עיבוד נתונים רגיל של ממשק משתמש. כדי להמשיך עם הדוגמה, מורידים את קובץ ה-zip של הטראסים (שכולל גם טראסים אחרים שצוינו בקטע הזה), פותחים את הקובץ systrace_tutorial.html בדפדפן. חשוב לדעת שהקובץ של systrace גדול מאוד. אם אתם לא משתמשים ב-systrace בעבודה היומיומית, סביר להניח שהקובץ הזה יהיה גדול יותר עם הרבה יותר מידע ממה שראיתם בעבר בקובץ מעקב יחיד.
לעומס עבודה עקבי וסדיר, כמו TouchLatency, צינור עיבוד הנתונים של ממשק המשתמש מכיל את הרכיבים הבאים:
- EventThread ב-SurfaceFlinger מעיר את שרשור ממשק המשתמש של האפליקציה, ומאותת שהגיע הזמן ליצור רגע צילום חדש.
- האפליקציה מבצעת רינדור של פריים ב-UI thread, ב-RenderThread וב-hwuiTasks, באמצעות משאבי המעבד והמעבד הגרפי. זהו עיקר הקיבולת שמופעלת בממשק המשתמש.
- האפליקציה שולחת את המסגרת שעבר רינדור ל-SurfaceFlinger באמצעות מקשר (binder), ואז SurfaceFlinger עובר למצב שינה.
- EventThread שני ב-SurfaceFlinger מעיר את SurfaceFlinger כדי להפעיל את היצירה ולהציג את הפלט. אם SurfaceFlinger קובע שאין עבודה לביצוע, הוא חוזר למצב שינה.
- SurfaceFlinger מטפל בהרכבה באמצעות Hardware Composer (HWC)/Hardware Composer 2 (HWC2) או GL. ההרכבה של HWC/HWC2 מהירה יותר וצורכת פחות חשמל, אבל יש לה מגבלות בהתאם למערכת על שבב (SoC). התהליך הזה נמשך בדרך כלל כ-4-6 אלפיות השנייה, אבל הוא עשוי לחפוף לשלב 2 כי אפליקציות ל-Android תמיד מוגנות ב-triple buffering. (אמנם תמיד יש לאפליקציות מאגר של שלושה פריימים, אבל יכול להיות שרק פריים אחד בהמתנה ב-SurfaceFlinger, כך שזה נראה כמו מאגר של שני פריימים).
- SurfaceFlinger שולח את הפלט הסופי לתצוגה באמצעות מנהל התקן של ספק, וחוזר למצב שינה בהמתנה להפעלה מחדש של EventThread.
נבחן את המסגרת החל מ-15,409 אלפיות השנייה:
תרשים 1 הוא מסגרת רגילה שמוקפת במסגרות רגילות, ולכן הוא נקודת התחלה טובה להבנת אופן הפעולה של צינור עיבוד הנתונים של ממשק המשתמש. השורה של שרשור ממשק המשתמש ל-TouchLatency כוללת צבעים שונים בזמנים שונים. העמודות מייצגות מצבים שונים של השרשור:
- אפור. שינה.
- כחול. ניתנת להפעלה (אפשר להפעיל אותה, אבל עדיין לא נבחרה להפעלה על ידי מתזמן המשימות).
- ירוק. פועלת באופן פעיל (לפי לוח הזמנים, היא פועלת).
- אדום. שינה ללא הפסקה (בדרך כלל שינה על מנעול בליבה). יכול להצביע על עומס קלט/פלט. שימושי מאוד לניפוי באגים של בעיות בביצועים.
- כתום. שינה ללא הפסקה עקב עומס קלט/פלט.
כדי לראות את הסיבה לשינה ללא הפסקה (זמינה מנקודת המעקב sched_blocked_reason), בוחרים את הפרוסה האדומה של השינה ללא הפסקה.
בזמן ש-EventThread פועל, חוט UI של TouchLatency הופך לזמין להרצה. כדי לראות מה העיר את המכשיר, לוחצים על הקטע הכחול.
באיור 2 מוצג ששרשור ממשק המשתמש של TouchLatency התעורר על ידי tid 6843, שמתאים ל-EventThread. חוט ממשק המשתמש מתעורר, מבצע עיבוד של פריים ומוסיף אותו לתור לשימוש של SurfaceFlinger.
אם התג binder_driver מופעל במעקב, אפשר לבחור עסקה של מקשר כדי להציג מידע על כל התהליכים שקשורים לעסקה הזו.
באיור 4 מוצג שב-15, 423.65 אלפיות השנייה,הקוד Binder:6832_1 ב-SurfaceFlinger הופך לקוד שניתן להריץ בגלל tid 9579, שהוא RenderThread של TouchLatency. אפשר לראות את queueBuffer גם בשני הצדדים של עסקת ה-binder.
במהלך queueBuffer בצד SurfaceFlinger, מספר הפריימים בהמתנה מ-TouchLatency עולה מ-1 ל-2.
באיור 5 מוצגת שרשור של שלוש מאגרי פריימים, שבהם יש שני פריימים שהושלמו והאפליקציה עומדת להתחיל עיבוד של השלישי. הסיבה לכך היא שכבר פספסנו כמה פריימים, ולכן האפליקציה שומרת שני פריימים בהמתנה במקום אחד כדי למנוע פסילה של פריימים נוספים.
זמן קצר לאחר מכן, EventThread שני מעיר את ה-thread הראשי של SurfaceFlinger כדי שהוא יוכל להציג במסך את המסגרת הקודמת בהמתנה:
SurfaceFlinger קודם מאחזק את המאגר הישן יותר בהמתנה, וכתוצאה מכך מספר המאגרים בהמתנה יורד מ-2 ל-1.
אחרי שמאבטחים את המאגר, SurfaceFlinger מגדיר את הקומפוזיציה ושולח את המסגרת הסופית למסך. (חלק מהקטעים האלה מופעלים כחלק מנקודת המעקב mdss, כך שיכול להיות שהם לא כלולים ב-SoC).
בשלב הבא, mdss_fb0 מתעורר ב-CPU 0. mdss_fb0 הוא חוט הליבה של צינור עיבוד הנתונים של המסך, שמפיק מסגרת עיבוד למסך.
אפשר לראות את mdss_fb0 כשורה נפרדת במעקב (צריך לגלול למטה כדי לראות אותה).
mdss_fb0 מתעורר, פועל קצרה, נכנס למצב שינה ללא הפסקה ואז מתעורר שוב.
דוגמה: מסגרת לא תקינה
בדוגמה הזו מתוארת ניתוח נתונים בזמן אמת (systrace) שמשמש לניפוי באגים של תנודות ב-Pixel/Pixel XL. כדי לפעול לפי הדוגמה, מורידים את קובץ ה-zip של המסלולים (שכולל מסלולים אחרים שצוינו בקטע הזה), מבטלים את הדחיסה של הקובץ ופותחים את הקובץ systrace_tutorial.html בדפדפן.
כשפותחים את systrace, מופיע משהו כזה:
כשמחפשים תנודות חדות, בודקים את השורה FrameMissed בקטע SurfaceFlinger.
FrameMissed הוא שיפור של איכות החיים שמסופק על ידי HWC2. כשמציגים systrace במכשירים אחרים, יכול להיות שהשורה FrameMissed לא תופיע אם המכשיר לא משתמש ב-HWC2. בכל מקרה, הערך של FrameMissed מושפע מכך ש-SurfaceFlinger החמיץ אחד מזמני הריצה הרגילים ביותר שלו ומכך שמספר המאגרים בהמתנה לא השתנה באפליקציה (com.prefabulated.touchlatency) ב-vsync.
באיור 11 מוצג פריים שהוחמצ ב-15598.29&nbps;ms. SurfaceFlinger התעורר לזמן קצר במרווח הזמן של vsync ושב לישון בלי לבצע עבודה כלשהי. כלומר, SurfaceFlinger קבע שלא כדאי לנסות לשלוח פריים נוסף למסך. למה?
כדי להבין איך צינור עיבוד הנתונים נכשל בפריים הזה, קודם צריך לעיין בדוגמה של הפריים העובד שלמעלה כדי לראות איך צינור עיבוד נתונים רגיל של ממשק משתמש מופיע ב-systrace. כשתהיו מוכנים, תוכלו לחזור לפריים שהוחמץ ולהתקדם לאחור. שימו לב ש-SurfaceFlinger מתעורר ומיד עובר למצב שינה. כשבודקים את מספר הפריימים בהמתנה מ-TouchLatency, רואים שני פריימים (זהו רמז טוב שעוזר להבין מה קורה).
יש לנו פריימים ב-SurfaceFlinger, ולכן זו לא בעיה באפליקציה. בנוסף, SurfaceFlinger מתעורר בזמן הנכון, כך שזו לא בעיה ב-SurfaceFlinger. אם SurfaceFlinger והאפליקציה נראים תקינים, סביר להניח שמדובר בבעיה בדרייבר.
מכיוון שנקבע שהנקודות mdss ו-sync יהיו פעילות, אנחנו יכולים לקבל מידע על המחסומים (ששותפים בין מנהל המסך לבין SurfaceFlinger) ששולטים במועד שליחת המסגרות למסך.
המחיצות האלה מפורטות בקטע mdss_fb0_retire, שמציין מתי מסגרת מוצגת במסך. המחסומים האלה מוצגים כחלק מקטגוריית המעקב sync. המחסומים שתואמים לאירועים מסוימים ב-SurfaceFlinger תלויים ב-SOC ובמקבץ ה-driver, לכן צריך להתייעץ עם ספק ה-SOC כדי להבין את המשמעות של קטגוריות המחסומים ב-traces.
באיור 13 מוצג פריים שהוצג למשך 33 אלפיות שנייה, ולא למשך 16.7 אלפיות שנייה כצפוי. באמצע הקטע הזה, הפריים הזה היה אמור להחליף בפריים חדש, אבל זה לא קרה. בודקים את הפריים הקודם ומחפשים משהו.
באיור 14 מוצגת מסגרת של 14.482 אלפיות השנייה. הקטע הפגום של שני הפריימים נמשך 33.6 אלפיות השנייה, וזה בערך מה שאנחנו מצפים לקבל עבור שני פריימים (אנחנו מבצעים רינדור ב-60Hz, 16.7 אלפיות השנייה לכל פריים, וזה קרוב). אבל 14.482ms לא קרוב בכלל ל-16.7ms, ומצביע על כך שמשהו לא תקין ב-display pipe.
בודקים בדיוק איפה הגדרת הגדרה מסתיימת כדי לקבוע מה שולט בה.
מאגר משימות מכיל את __vsync_retire_work_handler, שפועל כשהגדרה של הגדרה משתנה. אם בודקים את מקור הליבה, אפשר לראות שהוא חלק מנהג המסך. נראה שהיא נמצאת בנתיב הקריטי של צינור עיבוד הנתונים של רשת המדיה, ולכן היא צריכה לפעול במהירות האפשרית. אפשר להריץ אותו במשך 70 אלפיות שנייה בערך (לא עיכוב ארוך בתזמון), אבל הוא עבודה ב-workqueue ויכול להיות שהוא לא יתוזמנה בצורה מדויקת.
בודקים את המסגרת הקודמת כדי לקבוע אם היא תרמה לכך. לפעמים רעידות יכולות להצטבר לאורך זמן ולגרום בסופו של דבר לחריגה ממכסת הזמן.
השורה runnable ב-kworker לא מוצגת כי התצוגה הופכת אותה ללבנה כשהיא מסומנת, אבל הנתונים הסטטיסטיים מספרים את הסיפור: עיכוב של 2.3 אלפיות השנייה בלוח הזמנים בחלק מהנתיב הקריטי של צינור עיבוד הנתונים של התצוגה הוא רע.
לפני שממשיכים, צריך לתקן את העיכוב על ידי העברת החלק הזה של הנתיב הקריטי של צינור עיבוד הנתונים של התצוגה מ-workqueue (שפועל כ-CFS thread SCHED_OTHER) ל-kthread ייעודי SCHED_FIFO. הפונקציה הזו זקוקה להבטחות תזמון שעומדות בקריטריונים שלא ניתן לספק בעזרת תורי עבודה (והן לא מיועדות לספק).
האם זו הסיבה לתנודות? קשה לומר בוודאות. מלבד מקרים שקל לאבחן, כמו מאבקים על נעילת הליבה שגורמים לשרשור קריטי לתצוגה לעבור למצב שינה, בדרך כלל ב-traces לא מצוין מה הבעיה. האם התנודות האלה יכולות להיות הסיבה לכך שהפריים לא התקבל? בהחלט. זמני הגדרת המחסום אמורים להיות 16.7 אלפיות השנייה, אבל הם לא קרובים לכך בכלל בפריימים שמובילים לפריים שהושמט. מכיוון שצינור עיבוד הנתונים של המסך מקושר בצורה הדוקה, ייתכן שהתנודות סביב זמני הגדרת המחסום גרמו לירידה בפריים.
בדוגמה הזו, הפתרון כלל המרה של __vsync_retire_work_handler מ-workqueue ל-kthread ייעודי. כתוצאה מכך, חל שיפור ניכר בתנודות (jitter) וירידה בתנודות הלא חלקות (jank) בבדיקה של הכדור הקופץ. בשרטוטים הבאים מוצגים זמני גדר שנעים קרוב מאוד ל-16.7ms.