Menggunakan ftrace

{i>ftrace<i} adalah alat {i>debugging<i} untuk memahami apa yang terjadi di dalam {i>kernel<i} Linux. Bagian berikut menjelaskan fungsi ftrace dasar, ftrace dengan atrace (yang merekam kejadian {i>kernel<i}), dan ftrace dinamis.

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

Mencatat peristiwa kernel dengan atrace

atrace (frameworks/native/cmds/atrace) menggunakan ftrace untuk menangkap peristiwa {i>kernel<i}. Selanjutnya, systrace.py (atau run_systrace.py di versi yang lebih baru dari Catapult) menggunakan adb untuk menjalankan atrace di perangkat. atrace melakukan hal berikut:

  • Menyiapkan pelacakan mode pengguna dengan menyiapkan properti (debug.atrace.tags.enableflags).
  • Mengaktifkan fungsi ftrace yang diinginkan dengan menulis ke {i>ftrace sysfs<i}. Namun, karena ftrace mendukung lebih banyak fitur, Anda mungkin mengatur beberapa {i>node<i} {i>sysfs<i} sendiri kemudian menggunakan {i>atrace<i}.

Dengan pengecualian pelacakan waktu booting, andalkan penggunaan atrace untuk mengatur ke nilai yang sesuai. Properti ini adalah bitmask dan tidak berguna untuk menentukan nilai yang benar selain melihat {i>header<i} yang sesuai (yang dapat berubah antar-rilis Android).

Mengaktifkan peristiwa ftrace

Node sysfs ftrace berada di /sys/kernel/tracing dan melacak peristiwa dibagi menjadi beberapa kategori di /sys/kernel/tracing/events.

Untuk mengaktifkan peristiwa per kategori, gunakan: 

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

Untuk mengaktifkan peristiwa per peristiwa, gunakan: 

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

Jika peristiwa tambahan diaktifkan dengan menulis ke {i>node sysfs<i}, peristiwa itu akan tidak direset oleh atrace. Pola umum untuk memunculkan perangkat Qualcomm adalah dengan mengaktifkan kgsl (GPU) dan mdss (pipeline tampilan) tracepoint, lalu gunakan 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 bisa menggunakan ftrace tanpa atrace atau systrace, yaitu berguna saat Anda menginginkan rekaman aktivitas khusus kernel (atau jika Anda telah meluangkan waktu untuk menulis properti pelacakan mode pengguna secara manual). Untuk menjalankan ftrace saja:

  1. Setel ukuran buffer ke nilai yang cukup besar untuk trace Anda: 
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
  2. Aktifkan pelacakan: 
    echo 1 > /sys/kernel/tracing/tracing_on
  3. Jalankan pengujian, lalu nonaktifkan perekaman aktivitas: 
    echo 0 > /sys/kernel/tracing/tracing_on
  4. Membuang rekaman aktivitas: 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output

Trace_output memberikan trace dalam bentuk teks. Untuk memvisualisasikannya menggunakan Ketapel, dapatkan Ketapel repositori dari GitHub dan jalankan trace2html:

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

Secara default, ini menulis trace_file.html dalam saat ini.

Mengaitkan peristiwa

Sering kali berguna untuk melihat visualisasi Catapult dan ftrace mencatat secara bersamaan; misalnya, beberapa peristiwa ftrace (terutama peristiwa khusus vendor satu) tidak divisualisasikan oleh Catapult. Namun, stempel waktu Catapult relatif terhadap peristiwa pertama dalam rekaman aktivitas atau dengan stempel waktu tertentu dibuang oleh atrace, sedangkan stempel waktu ftrace mentah didasarkan pada merupakan sumber jam absolut pada {i>kernel<i} Linux.

Untuk menemukan peristiwa ftrace tertentu dari peristiwa Catapult:

  1. Buka log ftrace mentah. Rekaman aktivitas di systrace versi terbaru adalah dikompresi secara default:
    • Jika Anda menguasai systrace dengan --no-compress, berarti {i>file<i} html di bagian yang dimulai dengan MULAI PERJALANAN.
    • Jika tidak, jalankan html2trace dari Ketapel hierarki (tracing/bin/html2trace) untuk membatalkan kompresi rekaman aktivitas.
  2. Temukan stempel waktu relatif dalam visualisasi Catapult.
  3. Temukan garis di awal rekaman aktivitas yang berisi tracing_mark_sync. Ini akan terlihat seperti berikut: 
    <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 waktu akan relatif dari peristiwa pertama di log ftrace.
    1. Tambahkan stempel waktu relatif (dalam milidetik) ke nilai dalam parent_ts (dalam detik).
    2. Telusuri stempel waktu baru.

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

Gunakan ftrace dinamis

Jika systrace dan ftrace standar tidak mencukupi, ada satu yang terakhir tersedia solusi lain: ftrace dinamis. Ftrace dinamis melibatkan penulisan ulang kode kernel setelah booting, dan akibatnya tidak tersedia dalam produksi {i>kernel<i} untuk alasan keamanan. Namun, setiap {i>bug<i} kinerja yang sulit di Tahun 2015 dan 2016 pada akhirnya disebabkan oleh penggunaan ftrace dinamis. Terutama canggih untuk men-debug mode tidur tanpa gangguan karena Anda bisa mendapatkan pelacakan tumpukan di {i>kernel<i} setiap kali Anda menekan fungsi yang akan memicu tidur tanpa gangguan. Anda juga bisa men-debug bagian dengan interupsi dan preemption dinonaktifkan, yang dapat akan sangat berguna untuk membuktikan masalah.

Untuk mengaktifkan ftrace dinamis, edit defconfig kernel Anda:

  1. Hapus CONFIG_STRICT_MEMORY_RWX (jika ada). Jika Anda menggunakan versi 3.18 atau lebih baru dan ARM64, itu tidak ada.
  2. Tambahkan hal berikut: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y, dan CONFIG_PREEMPT_TRACER=y
  3. Build ulang dan booting kernel baru.
  4. Jalankan perintah berikut untuk memeriksa tracer yang tersedia: 
    cat /sys/kernel/tracing/available_tracers
  5. Pastikan perintah menampilkan 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 {i> dynamic ftrace<i}, {i>function profiler<i}, profiler irqsoff, dan profiler {i>preemptoff<i} yang tersedia. Kami sangat sebaiknya baca dokumentasi ftrace terkait topik ini sebelum menggunakannya mereka karena mereka kuat tetapi juga kompleks. irqsoff dan preemptoff terutama berguna untuk mengonfirmasi bahwa pengemudi mungkin meninggalkan interupsi atau preemption mati terlalu lama.

Profiler fungsi adalah opsi terbaik untuk masalah performa dan sering kali yang digunakan untuk mengetahui di mana suatu fungsi dipanggil.

Dalam masalah ini, menggunakan Pixel XL untuk mengambil foto HDR+ langsung memutar jendela bidik setiap kali menyebabkan jank. Kita menggunakan {i>function profiler<i} untuk men-debug masalah dalam waktu kurang dari satu jam. Untuk mengikuti contoh ini, mendownload file zip rekaman aktivitas (yang juga menyertakan trace lain yang dirujuk di bagian ini), ekstrak file, lalu buka trace_30898724.html di browser.

Rekaman aktivitas ini menunjukkan beberapa thread dalam proses server kamera yang diblokir di mode tidur tanpa gangguan di ion_client_destroy. Itu mahal fungsi, tetapi harus jarang dipanggil karena klien ion seharusnya mencakup banyak alokasi. Awalnya, kesalahan jatuh pada kode Hexagon di Halide, yang memang merupakan salah satu penyebabnya (membuat klien baru untuk setiap alokasi ion dan menghancurkan klien itu ketika alokasi dibebaskan, yang terlalu mahal). Berpindah ke klien ion tunggal untuk semua Hexagon alokasi memperbaiki situasi, tetapi jank tidak dapat diperbaiki.

Pada tahap ini, kita perlu mengetahui siapa yang memanggil ion_client_destroy, jadi saatnya menggunakan profiler fungsi:

  1. Karena fungsi terkadang diganti namanya oleh compiler, konfirmasi ion_client_destroy hadir dengan menggunakan: 
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
  2. Setelah memastikannya, gunakan 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. Meningkatkan ukuran buffer: 
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
  6. Mengaktifkan perekaman aktivitas: 
    echo 1 > /sys/kernel/tracing/trace_on
  7. Jalankan pengujian dan dapatkan rekaman aktivitas: 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Lihat rekaman aktivitas untuk melihat banyak sekali pelacakan 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 {i>driver<i} ion, kita dapat melihat bahwa ion_client_destroy dikirimi spam oleh penutupan fungsi userspace fd ke /dev/ion, bukan driver {i>kernel<i} acak. Dengan menelusuri Codebase Android untuk \"/dev/ion\", kami menemukan beberapa driver vendor melakukan hal yang sama seperti pengemudi Hexagon dan membuka/menutup /dev/ion (membuat dan menghancurkan klien ion baru) setiap kali mereka membutuhkan alokasi ion baru. Mengubah mereka menjadi penggunaan klien ion tunggal selama proses memperbaiki bug.

Jika data dari profiler fungsi tidak cukup spesifik, Anda dapat menggabungkan tracepoint ftrace dengan profiler fungsi. Peristiwa ftrace dapat diaktifkan di persis dengan cara yang sama seperti biasanya, dan mereka akan disisipi dengan rekaman aktivitas Anda. Hal ini sangat bagus jika sesekali muncul mode tidur panjang tanpa gangguan dalam yang ingin Anda debug: atur filter ftrace ke fungsi yang Anda inginkan, mengaktifkan tracepoint, merekam pelacakan. Anda bisa mengurai pelacakan yang dihasilkan dengan trace2html, temukan peristiwa yang Anda inginkan, lalu dapatkan pelacakan tumpukan di sekitar pelacakan mentah.

Menggunakan lockstat

Terkadang, {i>ftrace<i} tidak cukup dan Anda benar-benar perlu men-debug apa yang tampaknya adalah pertentangan kunci {i>kernel<i}. Ada satu opsi {i>kernel<i} lagi yang patut dicoba: CONFIG_LOCK_STAT. Ini adalah pilihan terakhir karena sangat sulit untuk bekerja pada perangkat Android karena menggelembungkan ukuran {i>kernel<i} melebihi apa yang dapat ditangani oleh sebagian besar perangkat.

Namun, lockstat menggunakan debug mengunci infrastruktur, yang berguna untuk banyak aplikasi lainnya. Siapa saja mengerjakan penampilan perangkat harus mencari cara agar opsi tersebut berfungsi di setiap perangkat karena akan ada saatnya Anda berpikir "Kalau saja saya bisa mengaktifkan LOCK_STAT, saya bisa mengonfirmasi atau menyangkalnya masalah dalam lima menit, bukan lima hari."

Dalam masalah ini, thread SCHED_FIFO terhenti saat semua core sudah mencapai batas maksimum memuat dengan thread non-SCHED_FIFO. Kami memiliki rekaman aktivitas yang menunjukkan kunci yang signifikan pertentangan pada fd dalam aplikasi VR, tetapi kami tidak dapat dengan mudah mengidentifikasi fd yang digunakan. Untuk mengikuti contoh, unduh file zip rekaman aktivitas (yang juga mencakup rekaman aktivitas lain yang disebut ), ekstrak file, dan buka file trace_30905547.html di browser Anda.

Kami berhipotesis bahwa ftrace itu sendiri adalah sumber pertentangan, ketika sebuah thread prioritas rendah akan mulai menulis ke pipa ftrace dan kemudian mendapatkan di-preempt sebelum kuncinya dapat dilepas. Ini adalah skenario terburuk yang diperburuk oleh campuran utas prioritas sangat rendah yang menulis ke penanda ftrace beserta beberapa thread dengan prioritas lebih tinggi yang berputar di CPU untuk melakukan simulasi perangkat yang terisi penuh.

Karena kami tidak dapat menggunakan ftrace untuk men-debug, kami membuat LOCK_STAT berfungsi kemudian menonaktifkan semua pelacakan lain dari aplikasi. Hasilnya menunjukkan kunci pertentangan itu sebenarnya dari ftrace karena tidak ada pertentangan yang muncul di pelacakan kunci saat {i>ftrace<i} tidak berjalan.

Jika Anda dapat mem-{i>booting<i} {i>kernel<i} dengan opsi konfigurasi, pelacakan kunci mirip dengan ftrace:

  1. Aktifkan pelacakan: 
    echo 1 > /proc/sys/kernel/lock_stat
  2. Jalankan pengujian.
  3. Nonaktifkan perekaman aktivitas: 
    echo 0 > /proc/sys/kernel/lock_stat
  4. Membuang rekaman aktivitas Anda: 
    cat /proc/lock_stat > /data/local/tmp/lock_stat

Untuk bantuan dalam menafsirkan output yang dihasilkan, lihat dokumentasi lockstat pukul <kernel>/Documentation/locking/lockstat.txt.

Menggunakan tracepoint vendor

Gunakan tracepoint upstream terlebih dahulu, tetapi terkadang Anda harus menggunakan tracepoint vendor:

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

Tracepoint dapat diperluas oleh layanan HAL memungkinkan Anda menambahkan pelacakan khusus perangkat poin/kategori. Tracepoint terintegrasi dengan perfetto, atrace/systrace, dan sistem di perangkat aplikasi pelacakan.

API untuk mengimplementasikan tracepoint/kategori adalah:

  • listKategori()menghasilkan (kategori vec<TracingCategory>);
  • enableKategori(vec<string> kategori) dihasilkan (Status status);
  • nonaktifkanAllKategori() menghasilkan (Status status);
Untuk informasi lebih lanjut, lihat definisi HAL dan implementasi {i>default<i} di AOSP: