systrace הוא הכלי העיקרי לניתוח ביצועי מכשירי אנדרואיד. עם זאת, זה באמת עטיפה סביב כלים אחרים. זה המעטפת בצד המארח סביב atrace , קובץ ההפעלה בצד המכשיר ששולט במעקב אחר שטח המשתמש ומגדיר ftrace , ומנגנון המעקב הראשי בקרנל של לינוקס. 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, והיא מכילה פונקציונליות מתקדמת שהיא קריטית לאיתור בעיות ביצועים. (תכונות אלה דורשות גישת שורש ולעיתים קרובות ליבה חדשה.)
הפעלת סיסטרס
בעת איתור באגים של ריצוד ב-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 פועל על ה-CPU, משהו ב-CPU חייב לכתוב את מאגר ה-ftrace שמתעד שינויים בחומרה. זה אומר שאם אתה סקרן לדעת מדוע גדר תצוגה שינתה את המצב, אתה יכול לראות מה רץ במעבד בנקודת המעבר המדויקת שלו (משהו שרץ במעבד הפעיל את השינוי הזה ביומן). מושג זה הוא הבסיס לניתוח ביצועים באמצעות systrace.
דוגמה: מסגרת עבודה
דוגמה זו מתארת מערכת עבור צינור ממשק משתמש רגיל. כדי לעקוב אחרי הדוגמה, הורד את קובץ ה-zip של traces (הכולל גם עקבות אחרות הנקראות בסעיף זה), פתח את הקובץ ופתח את הקובץ systrace_tutorial.html בדפדפן שלך. שימו לב שהמערכת הזו היא קובץ גדול; אלא אם כן אתה משתמש ב-systrace בעבודה היומיומית שלך, סביר להניח שזהו מעקב הרבה יותר גדול עם הרבה יותר מידע ממה שאי פעם ראית במעקב בודד בעבר.
עבור עומס עבודה עקבי ותקופתי כגון TouchLatency, צינור ממשק המשתמש מכיל את הדברים הבאים:
- EventThread ב-SurfaceFlinger מעיר את שרשור ממשק המשתמש של האפליקציה, ומסמן שהגיע הזמן לעבד מסגרת חדשה.
- האפליקציה מעבדת מסגרת בשרשור ממשק משתמש, RenderThread ו-hwuiTasks, תוך שימוש במשאבי CPU ו-GPU. זהו עיקר הקיבולת המושקעת עבור ממשק המשתמש.
- האפליקציה שולחת את המסגרת המעובדת ל- SurfaceFlinger באמצעות קלסר, ואז SurfaceFlinger הולך לישון.
- EventThread שני ב-SurfaceFlinger מעיר את SurfaceFlinger כדי להפעיל קומפוזיציה ופלט תצוגה. אם SurfaceFlinger קובע שאין עבודה לעשות, הוא חוזר לישון.
- SurfaceFlinger מטפל בקומפוזיציה באמצעות Hardware Composer (HWC)/Hardware Composer 2 (HWC2) או GL. הרכב HWC/HWC2 מהיר יותר והספק נמוך יותר, אך יש לו מגבלות בהתאם למערכת על השבב (SoC). זה בדרך כלל לוקח ~4-6 אלפיות השנייה, אבל יכול לחפוף עם שלב 2 מכיוון שאפליקציות אנדרואיד תמיד מאוצרות משולש. (בעוד שאפליקציות תמיד מאוחסנות משולשת, ייתכן שיש רק מסגרת אחת ממתינה בהמתנה ב-SurfaceFlinger, מה שגורם לה להיראות זהה לאגירה כפולה.)
- SurfaceFlinger שולח את הפלט הסופי לתצוגה עם מנהל התקן של הספק וחוזר לישון, ממתין להתעוררות של EventThread.
בואו נעבור דרך המסגרת שמתחילה ב-15409 אלפיות השנייה:
איור 1 הוא מסגרת רגילה המוקפת במסגרות רגילות, כך שזו נקודת התחלה טובה להבנת אופן פעולת הצינור של ממשק המשתמש. שורת החוט של ממשק המשתמש עבור TouchLatency כוללת צבעים שונים בזמנים שונים. פסים מציינים מצבים שונים עבור השרשור:
- אפור . יָשֵׁן.
- כְּחוֹל. ניתן להרצה (הוא יכול לפעול, אבל המתזמן עדיין לא בחר אותו לפעול).
- ירוק. פועל באופן פעיל (המתזמן חושב שהוא פועל).
- אָדוֹם. שינה ללא הפסקה (בדרך כלל שינה על מנעול בקרנל). יכול להעיד על עומס קלט/פלט. שימושי במיוחד עבור ניפוי בעיות ביצועים.
- תפוז. שינה ללא הפסקה עקב עומס קלט/פלט.
כדי להציג את הסיבה לשינה ללא הפסקה (זמינה מנקודת המעקב sched_blocked_reason ), בחר את פרוסת השינה ללא הפסקה האדומה.
בזמן ש-EventThread פועל, שרשור ממשק המשתמש עבור TouchLatency הופך לניתן להרצה. כדי לראות מה העיר אותו, לחץ על הקטע הכחול.
איור 2 מציג את שרשור ממשק המשתמש של TouchLatency התעורר על ידי tid 6843, התואם ל-EventThread. שרשרת ממשק המשתמש מתעוררת, מעבדת מסגרת ומעמידה אותה בתור לצריכה של SurfaceFlinger.
אם תג binder_driver מופעל במעקב, אתה יכול לבחור עסקת מקשר כדי להציג מידע על כל התהליכים המעורבים בעסקה זו.
איור 4 מראה שב-15,423.65 ms Binder:6832_1 ב-SurfaceFlinger הופך לניתן להרצה בגלל tid 9579, שהוא ה-RenderThread של TouchLatency. אתה יכול גם לראות את queueBuffer משני הצדדים של עסקת הקלסר.
במהלך ה-queueBuffer בצד SurfaceFlinger, מספר הפריימים הממתינים מ-TouchLatency הולך מ-1 ל-2.
איור 5 מציג חציצה משולשת, כאשר ישנן שתי פריימים שהושלמו והאפליקציה עומדת להתחיל לעבד את השלישית. הסיבה לכך היא שכבר הורדנו כמה פריימים, כך שהאפליקציה שומרת שתי פריימים ממתינים במקום אחת כדי לנסות להימנע מפריימים שנשרו עוד יותר.
זמן קצר לאחר מכן, השרשור הראשי של SurfaceFlinger מתעורר על ידי EventThread שני, כך שהוא יכול להוציא את המסגרת הממתינה הישנה יותר לתצוגה:
SurfaceFlinger תופס תחילה את המאגר הממתין הישן יותר, מה שגורם לספירת המאגר הממתינים לרדת מ-2 ל-1.
לאחר הנעילה של המאגר, SurfaceFlinger מגדיר קומפוזיציה ומגיש את המסגרת הסופית לתצוגה. (חלק מהסעיפים האלה מופעלים כחלק מנקודת המעקב mdss , כך שייתכן שהם לא ייכללו ב-SoC שלך.)
לאחר מכן, mdss_fb0 מתעורר ב-CPU 0. mdss_fb0 הוא חוט הליבה של צינור התצוגה להוצאת מסגרת מעובדת לתצוגה. אנו יכולים לראות mdss_fb0 כשורה משלו במעקב (גלול מטה לצפייה).
mdss_fb0 מתעורר, רץ לזמן קצר, נכנס לשינה בלתי פוסקת, ואז מתעורר שוב.
דוגמה: מסגרת לא עובדת
דוגמה זו מתארת מערכת הפעלה המשמשת לניפוי באגים של Pixel/Pixel XL ריצוד. כדי לעקוב אחרי הדוגמה, הורד את קובץ ה-zip של traces (הכולל עקבות אחרות הנקראות בסעיף זה), פתח את הקובץ ופתח את הקובץ 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 קבעה שלא כדאי לנסות שוב לשלוח מסגרת לתצוגה. למה?
כדי להבין כיצד התקלקל הצינור עבור מסגרת זו, עיין תחילה בדוגמה של מסגרת העבודה למעלה כדי לראות כיצד צינור UI רגיל מופיע ב-systrace. כשתהיה מוכן, חזור למסגרת החמצה ועבוד לאחור. שימו לב ש-SurfaceFlinger מתעורר ומיד הולך לישון. כאשר צופים במספר הפריימים הממתינים מ-TouchLatency, ישנן שתי פריימים (רמז טוב שיעזור להבין מה קורה).
מכיוון שיש לנו מסגרות ב-SurfaceFlinger, זו לא בעיה של אפליקציה. בנוסף, SurfaceFlinger מתעורר בזמן הנכון, כך שזו לא בעיה של SurfaceFlinger. אם SurfaceFlinger והאפליקציה שניהם נראים תקינים, כנראה שזו בעיה של מנהל ההתקן.
מכיוון ש- mdss ונקודות sync של הסינכרון מופעלים, אנו יכולים לקבל מידע על הגדרות (המשותפות בין מנהל ההתקן של התצוגה ל-SurfaceFlinger) השולטות מתי מסגרות נשלחות לתצוגה. גדרות אלו מופיעות תחת mdss_fb0_retire , המציין מתי מופיעה מסגרת בתצוגה. גדרות אלו מסופקות כחלק מקטגוריית sync . אילו גדרות מתאימות לאירועים מסוימים ב-SurfaceFlinger תלויות ב-SOC ובמחסנית הדרייברים שלך, אז עבוד עם ספק ה-SOC שלך כדי להבין את המשמעות של קטגוריות הגדר בעקבותיך.
איור 13 מציג מסגרת שהוצגה במשך 33 אלפיות השנייה, לא 16.7 אלפיות השנייה כצפוי. באמצע הפרוסה הזו, המסגרת הזו הייתה צריכה להיות מוחלפת בחדשה אבל לא הייתה. הצג את המסגרת הקודמת וחפש כל דבר.
איור 14 מציג 14.482 אלפיות השנייה למסגרת. קטע שני הפריימים השבור היה 33.6 אלפיות השנייה, שזה בערך מה שהיינו מצפים עבור שתי פריימים (אנחנו מעבדים ב-60 הרץ, 16.7 אלפיות השנייה לפריים, וזה קרוב). אבל 14.482 מילישניות זה בכלל לא קרוב ל-16.7 אלפיות השנייה, מה שמרמז שמשהו מאוד לא בסדר בצינור התצוגה.
בדוק היכן בדיוק הגדר מסתיימת כדי לקבוע מה שולט בה.
תור עבודה מכיל __vsync_retire_work_handler , שפועל כאשר הגדר משתנה. בהסתכלות דרך מקור הליבה, אתה יכול לראות שזה חלק ממנהל ההתקן של התצוגה. נראה שהוא נמצא בנתיב הקריטי עבור צינור התצוגה, ולכן הוא חייב לפעול במהירות האפשרית. זה ניתן להרצה עבור 70 או משהו כזה (לא עיכוב תזמון ארוך), אבל זה תור עבודה וייתכן שלא יתוזמן במדויק.
בדוק את המסגרת הקודמת כדי לקבוע אם זה תרם; לפעמים ריצוד יכול להצטבר עם הזמן ובסופו של דבר לגרום להחמצת מועד.
הקו הניתן להרצה ב-kworker אינו גלוי מכיוון שהצופה הופך אותו ללבן כאשר הוא נבחר, אבל הסטטיסטיקה מספרת את הסיפור: 2.3 אלפיות השנייה של עיכוב מתזמן עבור חלק מהנתיב הקריטי של צינור התצוגה הוא גרוע . לפני שתמשיך, תקן את ההשהיה שעל-ידי העברת חלק זה של צינור התצוגה הנתיב הקריטי מתור עבודה (שפועל כשרשור SCHED_OTHER CFS) ל-kthread ייעודי SCHED_FIFO . פונקציה זו זקוקה להבטחות תזמון שתורי עבודה אינם יכולים (ולא נועדו) לספק.
האם זו הסיבה לדחיקה? קשה לומר סופית. מלבד מקרים קלים לאבחון כמו טענה של נעילת ליבה הגורמת לשינה של שרשורים קריטיים לתצוגה, עקבות בדרך כלל לא מציינים את הבעיה. האם ריצוד זה יכול היה להיות הגורם להורדת המסגרת? בהחלט. זמני הגדר צריכים להיות 16.7 אלפיות השנייה, אבל הם לא קרובים לזה בכלל במסגרות המובילות למסגרת שנפלה. בהתחשב במידת הצמדות הדוקה של צינור התצוגה, יתכן שהריצוד סביב תזמוני הגדר הביא לנפילת מסגרת.
בדוגמה זו, הפתרון כלל המרת __vsync_retire_work_handler מתור עבודה ל-kthread ייעודי. זה הביא לשיפורי ריצוד ניכרים והפחתת הג'אנק במבחן הכדור המקפץ. עקבות עוקבים מראים תזמוני גדר המרחפים קרוב מאוד ל-16.7 אלפיות השנייה.