שימוש ב-ftrace

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

לפרטים על הפונקציונליות של מעקב מתקדם שלא זמינה מ- systrace, קראו את מסמכי התיעוד של ftrace, <kernel tree>/Documentation/trace/ftrace.txt

תיעוד אירועי ליבה באמצעות atrace

atrace (frameworks/native/cmds/atrace) משתמש באמצעות ftrace כדי לצלם אירועי ליבה (kernel). בתורו, systrace.py (או run_systrace.py בגרסאות מאוחרות יותר של Catapult) משתמשים ב-adb כדי להריץ ב-ATT במכשיר. atrace, מבצע את הפעולות הבאות:

• הגדרת מעקב במצב משתמש באמצעות הגדרת נכס (debug.atrace.tags.enableflags).
• מפעיל את פונקציונליות המעקב הרצויה על ידי כתיבה ftrace xsfs. אבל מכיוון ש-ftrace תומך בתכונות נוספות, אפשר להגדיר כמה צומתי sysfs בעצמכם ואז להשתמש ב-atrace.

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

הפעלת אירועי ftrace

צומתי ה-sysfs של ftrace נמצאים ב-/sys/kernel/tracing ובמעקב האירועים מחולקים לקטגוריות ב-/sys/kernel/tracing/events.

כדי להפעיל אירועים לכל קטגוריה, משתמשים ב:

echo 1 > /sys/kernel/tracing/events/irq/enable

כדי להפעיל אירועים לכל אירוע בנפרד, משתמשים ב:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

אם מפעילים אירועים נוספים על ידי כתיבה לצמתים של sysfs, הם: לא יאופסו על ידי atrace. דפוס נפוץ להעלאת נתוני מכשיר של Qualcomm להפעלה של kgsl (GPU) mdss (להציג צינור עיבוד נתונים) ולאחר מכן להשתמש ברצף או systrace:

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

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

1. מגדירים את מאגר הנתונים הזמני לערך גדול מספיק כדי לעקוב אחרי הנתונים:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. הפעלת המעקב:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. מריצים את הבדיקה ומשביתים את המעקב:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. מסירים את נתוני המעקב:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
   

ה-tracking_output יוצר את המעקב בצורת טקסט. כדי להמחיש את הנתונים באמצעות קאטפולט, הנה קטפולט repository מ-GitHub ומריצים את trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

כברירת מחדל, כתוב trace_file.html באותו אופן

תיאום אירועים

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

כדי למצוא אירוע ftrace מסוים מאירוע Catapult:

1. פותחים את היומן הגולמי של ftrace. עקבות בגרסאות עדכניות של systrace דחוס כברירת מחדל:
   • אם תיעדת את המערכת באמצעות --no-compress, הערך הזה הוא את קובץ ה-HTML בקטע שמתחיל ב-BEGIN TRACE.
   • אם לא, מריצים את html2trace מקובץ קטפולט עץ (tracing/bin/html2trace) כדי לבטל את דחיסת נתוני המעקב.
2. מחפשים את חותמת הזמן היחסית בתצוגה החזותית של Catapult.
3. מצאו שורה בתחילת המעקב שמכילה tracing_mark_sync הוא אמור להיראות כך:

   <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
   

   
   אם הקו הזה לא קיים (או אם השתמשת ב-ftrace ללא מרוץ), אז הזמנים יהיו יחסיים מהאירוע הראשון ביומן המעקב.
   1. מוסיפים את חותמת הזמן היחסית (באלפיות השנייה) לערך parent_ts (בשניות).
   2. מחפשים את חותמת הזמן החדשה.

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

שימוש במעקב דינמי

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

כדי להפעיל ftrace דינמי, עורכים את defconfig של הליבה:

1. מסירים את CONFIG_STRICT_MEMORY_RWX (אם קיים). אם משתמשים ב-3.18 או newer ו-arm64, הוא לא שם.
2. מוסיפים את הערכים הבאים: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y, ו-CONFIG_PREEMPT_TRACER=y
3. בנייה מחדש והפעלה של הליבה (kernel) החדשה.
4. מבצעים את הפעולות הבאות כדי לבדוק אם יש כלי מעקב זמינים:

   cat /sys/kernel/tracing/available_tracers
   

5. מוודאים שהפקודה מחזירה function, irqsoff, preemptoff ו-preemptirqsoff.
6. מריצים את הפקודה הבאה כדי לוודא שה-ftrace הדינמי פועל:

   cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
   

אחרי שתשלימו את השלבים האלה, יש לכם ftrace דינמי, הכלי לניתוח ביצועי הפונקציה, אפשר להשתמש ב-irqsoff profiler, וב-preemptoff profiler. אנחנו מאוד מומלץ לקרוא את המסמכים של ftrace לפי הנושאים האלה לפני שמשתמשים כי הם עוצמתיים אבל מורכבים. irqsoff ו-preemptoff הם בעיקר שימושית כדי לאשר שנהגים משאירים הפרעות או מבצעים מראש הושבת למשך זמן רב מדי.

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

הצגת הבעיה: תמונת HDR + עינית מסתובבת

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

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

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

1. מאחר שהמהדר (compiler) משנה לפעמים שמות של פונקציות, צריך לאשר ion_client_destroy מגיע לשם באמצעות:

   cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
   

2. אחרי שמוודאים שהיא קיימת, משתמשים בה כמסנן ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. מפעילים את הכלי לניתוח ביצועים של פונקציות:

   echo function > /sys/kernel/tracing/current_tracer
   

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

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. הגדלת מאגר הנתונים הזמני:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. הפעלת המעקב:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. מריצים את הבדיקה ומקבלים את נתוני המעקב:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace
   

8. תוכלו לעיין בדוח כדי לראות הרבה דוחות של קריסות:

       cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
       cameraserver-643   [003] ...1    94.192997: <stack trace>
    => ftrace_ops_no_ops
    => ftrace_graph_call
    => ion_client_destroy
    => ion_release
    => __fput
    => ____fput
    => task_work_run
    => do_notify_resume
    => work_pending
    

לאחר בדיקה של נהג היונים, אפשר לראות השירות ion_client_destroy מבצע ספאם על ידי סגירה של פונקציה במרחב המשתמשים fd ל-/dev/ion, לא מנהל ליבה אקראי. על ידי חיפוש Codebase של Android עבור \"/dev/ion\", מצאנו כמה מנהלי התקנים של ספקים עושה את אותן הפעולות כמו הנהג המשושה ופתיחה/סגירה /dev/ion (יצירה והשמדה של לקוח יון חדש) בכל פעם צריכים הקצאת יונים חדשה. שינוי ל- להשתמש לקוח יון יחיד בכל משך החיים של התהליך תיק את הבאג.

---

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

שימוש ב-lockstat

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

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

הצגת בעיה: נתקעת בליבות של SCHED_FIFO כשיש ליבות בעומס מקסימלי בלי קשר ל-SCHED_FIFO

בבעיה הזו, ה-thread SCHED_FIFO נעצר כשכל הליבות היו באורך מקסימלי נטענות עם שרשורים שאינם SCHED_FIFO. היו מעקבים אחר נעילה משמעותית תחרות על FD באפליקציות VR, אבל לא הצלחנו לזהות בקלות איזה FD נמצא בשימוש. כדי לעקוב אחר הדוגמה, צריך להוריד את קובץ ה-zip של עקבות (שכולל גם עקבות אחרים המוזכרים כאן ), מחלצים את הקובץ ופותחים את הקובץ trace_30905547.html בדפדפן.

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

לא הצלחנו להשתמש ב-ftrace לניפוי באגים, לכן עבדנו על LOCK_STAT לאחר מכן השביתו את כל שאר נתוני המעקב מהאפליקציה. בתוצאות הוצגו המנעול התחרות נבעה מ-fter, כי אף אחת מהתחרות לא הופיעה מעקב הנעילה כש-ftrace לא פעל.

---

אם ניתן לאתחל ליבה באמצעות אפשרות ההגדרה, מעקב הנעילה דומה ל- ftrace:

1. הפעלת המעקב:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. מריצים את הבדיקה.
3. השבתת המעקב:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. מוחקים את נתוני המעקב:

   cat /proc/lock_stat > /data/local/tmp/lock_stat
   

לקבלת עזרה בפירוש הפלט שמתקבל, עיינו במסמכי התיעוד של lockstat בשעה <kernel>/Documentation/locking/lockstat.txt.

שימוש בנקודות מעקב של ספקים

קודם כדאי להשתמש בנקודות מעקב (trackingpoint) ב-upstream, אבל לפעמים תצטרכו להשתמש בנקודות מעקב של הספק:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

ניתן להרחיב את נקודות המעקב באמצעות שירות HAL, וכך להוסיף נתוני מעקב ספציפיים למכשיר נקודות/קטגוריות. נקודות מעקב משולבות עם Perfetto, Atrace/systrace והמערכת במכשיר אפליקציית מעקב.

ממשקי ה-API להטמעה של נקודות מעקב/קטגוריות הם:

• listcategories()generates (vec<TracingCategory> קטגוריות);
• EnableCategory(vec<string> categories) יוצר (סטטוס סטטוס);
• disabledAllCategory() יוצר (סטטוס סטטוס);

מידע נוסף זמין במאמר על הגדרת HAL והטמעת ברירת המחדל AOSP: