שימוש ב-ftrace

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

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

לכידת אירועי ליבה עם atrace

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

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

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

הפעלת אירועי 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 (תצוגה צינור) ולאחר מכן להשתמש ב-atrace או 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
   

ה-trace_output נותן את המעקב בצורת טקסט. כדי לדמיין אותו באמצעות Catapult, קבל את מאגר Catapult מ-GitHub והפעל את trace2html:

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

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

מתאם אירועים

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

כדי למצוא אירוע Ftrace נתון מאירוע Catapult:

1. פתח את יומן ה-ftrace הגולמי. העקבות בגרסאות האחרונות של systrace דחוסות כברירת מחדל:
   • אם תפסת את ה-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 ללא atrace), אז התזמונים יהיו יחסיים מהאירוע הראשון ביומן ה-ftrace.
   1. הוסף את חותמת הזמן היחסית (במילישניות) לערך ב- parent_ts (בשניות).
   2. חפש את חותמת הזמן החדשה.

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

שימוש ב-ftrace דינמי

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

כדי להפעיל Ftrace דינמי, ערוך את ה-defconfig של הליבה שלך:

1. הסר CONFIG_STRICT_MEMORY_RWX (אם הוא קיים). אם אתה על 3.18 ומעלה ו-arm64, זה לא שם.
2. הוסף את הדברים הבאים: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y ו-CONFIG_PREEMPT_TRACER=y
3. בנה מחדש ואתחל את הליבה החדשה.
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 ופרופיל ה-preemptoff. אנו ממליצים בחום לקרוא תיעוד ftrace בנושאים אלו לפני השימוש בהם, מכיוון שהם חזקים אך מורכבים. irqsoff ו-preemptoff שימושיים בעיקר לאישור שמנהלי התקנים עשויים להשאיר הפרעות או מקדימה כבויה למשך זמן רב מדי.

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

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

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

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

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

1. מכיוון ששמות של פונקציות לפעמים משנים על ידי המהדר, ודא ש- 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, אנו יכולים לראות ש- ion_client_destroy מקבל דואר זבל על ידי פונקציית מרחב משתמש שסוגרת fd ל- /dev/ion , ולא מנהל התקן ליבה אקראי. על ידי חיפוש בבסיס הקוד של אנדרואיד עבור \"/dev/ion\" , אנו מוצאים מספר מנהלי התקנים של ספקים שעושים את אותו הדבר כמו מנהל ההתקן של Hexagon ופותחים/סוגרים את /dev/ion (יוצרים והורסים לקוח יון חדש) בכל פעם שהם צריכים הקצאת יונים חדשה. שינוי אלה לשימוש בלקוח יון יחיד למשך כל חיי התהליך תיקן את הבאג.

---

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

שימוש ב-lockstat

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

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

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

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

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

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

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

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

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

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

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

• listCategories() יוצר (קטגוריות vec<TracingCategory>);
• enableCategories(vec<string> קטגוריות) יוצר (סטטוס סטטוס);
• disableAllCategories() יוצר (סטטוס סטטוס);

למידע נוסף, עיין בהגדרת HAL ויישום ברירת המחדל ב- AOSP :