Menggunakan ftrace

ftrace adalah alat debugging untuk memahami apa yang terjadi di dalam kernel Linux. Bagian berikut merinci fungsionalitas ftrace dasar, penggunaan ftrace dengan atrace (yang menangkap kejadian kernel), dan ftrace dinamis.

Untuk detail tentang fungsionalitas ftrace tingkat lanjut yang tidak tersedia dari systrace, lihat dokumentasi ftrace di <kernel tree>/Documentation/trace/ftrace.txt .

Menangkap peristiwa kernel dengan atrace

atrace ( frameworks/native/cmds/atrace ) menggunakan ftrace untuk menangkap kejadian kernel. Pada gilirannya, systrace.py (atau run_systrace.py di versi Catapult yang lebih baru) menggunakan adb untuk menjalankan atrace pada perangkat. atrace melakukan hal berikut:

• Menyiapkan penelusuran mode pengguna dengan menyetel properti ( debug.atrace.tags.enableflags ).
• Mengaktifkan fungsionalitas ftrace yang diinginkan dengan menulis ke node sysfs ftrace yang sesuai. Namun, karena ftrace mendukung lebih banyak fitur, Anda dapat mengatur sendiri beberapa node sysfs lalu menggunakan atrace.

Dengan pengecualian penelusuran waktu boot, andalkan penggunaan atrace untuk menyetel properti ke nilai yang sesuai. Properti ini adalah bitmask dan tidak ada cara yang baik untuk menentukan nilai yang benar selain melihat header yang sesuai (yang dapat berubah di antara rilis Android).

Mengaktifkan acara ftrace

Node ftrace sysfs berada di /sys/kernel/tracing dan peristiwa pelacakan dibagi ke dalam kategori di /sys/kernel/tracing/events .

Untuk mengaktifkan acara berdasarkan per kategori, gunakan:

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

Untuk mengaktifkan acara berdasarkan per acara, gunakan:

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

Jika event tambahan telah diaktifkan dengan menulis ke node sysfs, event tersebut tidak akan direset oleh atrace. Pola umum untuk menampilkan perangkat Qualcomm adalah dengan mengaktifkan tracepoint kgsl (GPU) dan mdss (display pipeline) lalu menggunakan atrace atau 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

Anda juga dapat menggunakan ftrace tanpa atrace atau systrace, yang berguna bila Anda menginginkan jejak hanya kernel (atau jika Anda meluangkan waktu untuk menulis properti penelusuran mode pengguna dengan tangan). Untuk menjalankan ftrace saja:

1. Tetapkan ukuran buffer ke nilai yang cukup besar untuk pelacakan Anda:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. Aktifkan penelusuran:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. Jalankan pengujian Anda, lalu nonaktifkan penelusuran:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. Buang jejaknya:

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

trace_output memberikan jejak dalam bentuk teks. Untuk memvisualisasikannya menggunakan Catapult, dapatkan repositori Catapult dari GitHub dan jalankan trace2html:

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

Secara default, ini menulis trace_file.html di direktori yang sama.

Peristiwa yang berkorelasi

Seringkali berguna untuk melihat visualisasi Catapult dan log ftrace secara bersamaan; misalnya, beberapa peristiwa ftrace (terutama yang khusus vendor) tidak divisualisasikan oleh Catapult. Namun, stempel waktu Catapult bersifat relatif terhadap peristiwa pertama dalam pelacakan atau stempel waktu tertentu yang dibuang oleh atrace, sedangkan stempel waktu ftrace mentah didasarkan pada sumber jam absolut tertentu di kernel Linux.

Untuk menemukan acara ftrace tertentu dari acara Catapult:

1. Buka log ftrace mentah. Jejak di systrace versi terbaru dikompresi secara default:
   • Jika Anda menangkap systrace Anda dengan --no-compress , ini ada di file html di bagian yang dimulai dengan BEGIN TRACE.
   • Jika tidak, jalankan html2trace dari pohon Catapult ( tracing/bin/html2trace ) untuk membuka kompresi jejak.
2. Temukan stempel waktu relatif dalam visualisasi Catapult.
3. Temukan baris di awal jejak yang berisi tracing_mark_sync . Seharusnya terlihat seperti ini:

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

   
   Jika baris ini tidak ada (atau jika Anda menggunakan ftrace tanpa atrace), maka waktunya akan relatif dari kejadian pertama di log ftrace.
   1. Tambahkan stempel waktu relatif (dalam milidetik) ke nilai dalam parent_ts (dalam detik).
   2. Cari stempel waktu baru.

Langkah-langkah ini akan menempatkan Anda pada (atau setidaknya sangat dekat dengan) acara tersebut.

Menggunakan ftrace dinamis

Jika systrace dan ftrace standar tidak mencukupi, ada satu solusi terakhir yang tersedia: ftrace dinamis . Ftrace dinamis melibatkan penulisan ulang kode kernel setelah boot, dan akibatnya kode tersebut tidak tersedia di kernel produksi karena alasan keamanan. Namun, setiap bug kinerja yang sulit pada tahun 2015 dan 2016 pada akhirnya disebabkan oleh penggunaan ftrace dinamis. Ini sangat berguna untuk men-debug tidur yang tidak pernah terputus karena Anda bisa mendapatkan jejak tumpukan di kernel setiap kali Anda menekan fungsi yang memicu tidur yang tidak pernah terputus. Anda juga dapat men-debug bagian dengan interupsi dan preemption dinonaktifkan, yang bisa sangat berguna untuk membuktikan masalah.

Untuk mengaktifkan ftrace dinamis, edit defconfig kernel Anda:

1. Hapus CONFIG_STRICT_MEMORY_RWX (jika ada). Jika Anda menggunakan 3.18 atau lebih baru dan arm64, itu tidak ada.
2. Tambahkan yang berikut: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y, dan CONFIG_PREMPT_TRACER=y
3. Bangun kembali dan boot kernel baru.
4. Jalankan perintah berikut untuk memeriksa pelacak yang tersedia:

   cat /sys/kernel/tracing/available_tracers
   

5. Konfirmasikan perintah return function , irqsoff , preemptoff , dan preemptirqsoff .
6. Jalankan perintah berikut untuk memastikan ftrace dinamis berfungsi:

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

Setelah menyelesaikan langkah-langkah ini, Anda memiliki ftrace dinamis, profiler fungsi, profiler irqsoff, dan profiler preemptoff yang tersedia. Kami sangat menyarankan untuk membaca dokumentasi ftrace tentang topik ini sebelum menggunakannya karena dokumentasi ini kuat namun rumit. irqsoff dan preemptoff terutama berguna untuk mengonfirmasi bahwa pengemudi mungkin membiarkan interupsi atau preemption dimatikan terlalu lama.

Profiler fungsi adalah pilihan terbaik untuk masalah kinerja dan sering digunakan untuk mengetahui di mana suatu fungsi dipanggil.

Tampilkan Masalah: Foto HDR + jendela bidik berputar

Dalam masalah ini, menggunakan Pixel XL untuk mengambil foto HDR+ lalu segera memutar jendela bidik menyebabkan jank setiap saat. Kami menggunakan fungsi profiler untuk men-debug masalah ini dalam waktu kurang dari satu jam. Untuk mengikuti contoh ini, unduh file zip jejak (yang juga mencakup jejak lain yang dirujuk di bagian ini), unzip file tersebut, dan buka file trace_30898724.html di browser Anda.

Jejak tersebut menunjukkan beberapa thread dalam proses server kamera yang diblokir dalam mode tidur tanpa gangguan pada ion_client_destroy . Itu adalah fungsi yang mahal, namun sebaiknya jarang dipanggil karena klien ion harus mencakup banyak alokasi. Awalnya, kesalahan jatuh pada kode Hexagon di Halide, yang memang merupakan salah satu penyebabnya (kode ini menciptakan klien baru untuk setiap alokasi ion dan menghancurkan klien tersebut ketika alokasi tersebut dibebaskan, yang mana biayanya terlalu mahal). Beralih ke klien ion tunggal untuk semua alokasi Hexagon memperbaiki situasi, namun jank belum teratasi.

Pada titik ini kita perlu mengetahui siapa yang menelepon ion_client_destroy , jadi inilah saatnya menggunakan fungsi profiler:

1. Karena fungsi terkadang diganti namanya oleh kompiler, konfirmasikan ion_client_destroy ada dengan menggunakan:

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

2. Setelah memastikannya ada, gunakan sebagai filter ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. Aktifkan profiler fungsi:

   echo function > /sys/kernel/tracing/current_tracer
   

4. Aktifkan pelacakan tumpukan setiap kali fungsi filter dipanggil:

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. Tingkatkan ukuran buffer:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. Aktifkan pelacakan:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. Jalankan tes dan dapatkan jejaknya:

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

8. Lihat jejak untuk melihat banyak sekali jejak tumpukan:

       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
    

Berdasarkan pemeriksaan driver ion, kita dapat melihat bahwa ion_client_destroy sedang di-spam oleh fungsi userspace yang menutup fd ke /dev/ion , bukan driver kernel acak. Dengan menelusuri basis kode Android \"/dev/ion\" , kami menemukan beberapa driver vendor melakukan hal yang sama seperti driver Hexagon dan membuka/menutup /dev/ion (membuat dan menghancurkan klien ion baru) setiap kali mereka membutuhkan alokasi ion baru. Mengubahnya untuk menggunakan klien ion tunggal selama proses berlangsung memperbaiki bug.

---

Jika data dari profiler fungsi tidak cukup spesifik, Anda dapat menggabungkan titik jejak ftrace dengan profiler fungsi. Acara ftrace dapat diaktifkan dengan cara yang persis sama seperti biasanya, dan acara tersebut akan disisipkan dengan jejak Anda. Ini bagus jika sesekali terjadi tidur panjang tanpa gangguan pada fungsi tertentu yang ingin Anda debug: atur filter ftrace ke fungsi yang Anda inginkan, aktifkan titik jejak, ambil jejak. Anda dapat mengurai jejak yang dihasilkan dengan trace2html , menemukan peristiwa yang Anda inginkan, lalu mendapatkan jejak tumpukan terdekat di jejak mentah.

Menggunakan lockstat

Terkadang, ftrace saja tidak cukup dan Anda benar-benar perlu men-debug apa yang tampaknya merupakan pertentangan kunci kernel. Ada satu lagi opsi kernel yang patut dicoba: CONFIG_LOCK_STAT . Ini adalah pilihan terakhir karena sangat sulit untuk bekerja pada perangkat Android karena ukuran kernelnya membengkak melebihi kemampuan sebagian besar perangkat.

Namun, lockstat menggunakan infrastruktur penguncian debug, yang berguna untuk banyak aplikasi lain. Setiap orang yang bekerja pada perbaikan perangkat harus mencari cara agar opsi tersebut berfungsi pada setiap perangkat karena akan ada saatnya Anda berpikir "Kalau saja saya dapat mengaktifkan LOCK_STAT , saya dapat mengonfirmasi atau menyangkal ini sebagai masalah dalam lima menit, bukannya Lima hari."

Tampilkan Masalah: Berhenti di SCHED_FIFO ketika inti pada beban maksimal dengan non-SCHED_FIFO

Dalam masalah ini, thread SCHED_FIFO terhenti ketika semua inti berada pada beban maksimum dengan thread non-SCHED_FIFO. Kami memiliki jejak yang menunjukkan pertentangan kunci yang signifikan pada fd di aplikasi VR, namun kami tidak dapat dengan mudah mengidentifikasi fd yang digunakan. Untuk mengikuti contoh ini, unduh file zip jejak (yang juga mencakup jejak lain yang dirujuk di bagian ini), unzip file tersebut, dan buka file trace_30905547.html di browser Anda.

Kami berhipotesis bahwa ftrace sendiri adalah sumber pertikaian kunci, ketika thread berprioritas rendah akan mulai menulis ke pipa ftrace dan kemudian didahului sebelum dapat melepaskan kunci. Ini adalah skenario terburuk yang diperburuk oleh campuran thread berprioritas sangat rendah yang menulis ke penanda ftrace bersama dengan beberapa thread berprioritas lebih tinggi yang berputar pada CPU untuk mensimulasikan perangkat yang terisi penuh.

Karena kami tidak dapat menggunakan ftrace untuk melakukan debug, kami membuat LOCK_STAT berfungsi lalu mematikan semua penelusuran lainnya dari aplikasi. Hasil penelitian menunjukkan pertikaian lock sebenarnya dari ftrace karena tidak ada pertikaian yang muncul di lock trace ketika ftrace tidak berjalan.

---

Jika Anda dapat mem-boot kernel dengan opsi konfigurasi, pelacakan kunci mirip dengan ftrace:

1. Aktifkan pelacakan:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. Jalankan pengujian Anda.
3. Nonaktifkan pelacakan:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. Buang jejak Anda:

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

Untuk bantuan menafsirkan keluaran yang dihasilkan, lihat dokumentasi lockstat di <kernel>/Documentation/locking/lockstat.txt .

Menggunakan titik jejak vendor

Gunakan titik jejak hulu terlebih dahulu, namun terkadang Anda perlu menggunakan titik jejak vendor:

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

Titik penelusuran dapat diperluas dengan layanan HAL yang memungkinkan Anda menambahkan titik/kategori penelusuran khusus perangkat. Tracepoint terintegrasi dengan perfetto, atrace/systrace, dan aplikasi penelusuran sistem pada perangkat.

API untuk mengimplementasikan titik jejak/kategori adalah:

• listCategories()menghasilkan (vec<TracingCategory> kategori);
• aktifkanKategori(vec<string> kategori) menghasilkan (Status status);
• nonaktifkanAllCategories() menghasilkan (Status status);

Untuk informasi lebih lanjut, lihat definisi HAL dan implementasi default di AOSP :