Memahami systrace

systrace adalah alat utama untuk menganalisis performa perangkat Android. Namun, sebenarnya itu adalah wrapper di antara alat-alat lain. Ini adalah wrapper sisi host seputar atrace, file yang dapat dieksekusi sisi perangkat yang mengontrol ruang pengguna pelacakan dan menyiapkan ftrace, serta mekanisme pelacakan utama di Linux {i>kernel<i}. systrace menggunakan atrace untuk mengaktifkan pelacakan, lalu membaca buffer ftrace dan menggabungkan semuanya dalam penampil HTML yang lengkap. (Meskipun {i>kernel<i} yang lebih baru memiliki dukungan untuk Linux Enhanced Berkeley Packet Filter (eBPF), dokumentasi berikut berkaitan dengan kernel 3.18 (tanpa eFPF) karena itulah yang digunakan pada Pixel/Pixel XL.)

systrace dimiliki oleh tim Google Android dan Google Chrome dan open source sebagai bagian dari Project Catapult. Di beberapa selain systrace, Catapult mencakup utilitas berguna lainnya. Misalnya, ftrace memiliki lebih banyak fitur daripada yang bisa diaktifkan secara langsung oleh systrace atau atrace dan berisi beberapa fungsi lanjutan yang penting untuk performa proses debug menyelesaikan semua jenis permasalahan. (Fitur ini memerlukan akses root dan sering kali merupakan kernel baru.)

Menjalankan systrace

Saat melakukan proses debug jitter di Pixel/Pixel XL, mulailah dengan hal berikut berikut:

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

Jika dikombinasikan dengan tracepoint tambahan yang diperlukan untuk GPU dan tampilan aktivitas pipeline, hal ini memberi Anda kemampuan untuk melacak dari input pengguna ke frame yang ditampilkan di layar. Setel ukuran buffer ke ukuran yang besar untuk menghindari hilangnya (karena tanpa {i>buffer<i} besar, beberapa CPU tidak berisikan kejadian setelah beberapa titik dalam trace).

Saat membahas systrace, perlu diingat bahwa setiap peristiwa dipicu oleh sesuatu pada CPU.

Karena systrace dibuat berdasarkan ftrace dan ftrace berjalan pada CPU, sesuatu di CPU harus menulis {i>buffer <i} ftrace yang mencatat perubahan perangkat keras. Artinya, jika Anda penasaran mengapa {i> display fence <i}mengubah status, Anda dapat melihat apa yang berjalan pada CPU pada titik yang tepat dari transisinya (sesuatu yang berjalan di CPU memicu perubahan tersebut di log). Ini adalah dasar menganalisis performa menggunakan systrace.

Contoh: Working frame

Contoh ini menjelaskan systrace untuk pipeline UI normal. Untuk mengikuti dengan contoh, mendownload file zip rekaman aktivitas (yang juga mencakup trace lain yang dirujuk di bagian ini), ekstrak file, dan buka file systrace_tutorial.html di browser Anda. Hati-hati bahwa systrace ini adalah file besar; kecuali jika Anda menggunakan systrace dalam sehari-hari kemungkinan besar merupakan jejak yang jauh lebih besar dengan lebih banyak informasi daripada yang Anda dalam satu pelacakan sebelumnya.

Untuk beban kerja yang konsisten dan berkala seperti TouchLatensi, pipeline UI berisi hal berikut:

1. EventThread di SurfaceFlinger mengaktifkan UI thread aplikasi, yang menandakan bahwa sudah waktunya untuk merender frame baru.
2. Aplikasi merender frame di UI thread, RenderThread, dan hwuiTasks, menggunakan CPU dan resource GPU. Ini adalah sebagian besar kapasitas yang dihabiskan untuk UI.
3. Aplikasi mengirimkan frame yang dirender ke SurfaceFlinger menggunakan binder, lalu SurfaceFlinger tidur.
4. EventThread kedua di SurfaceFlinger mengaktifkan SurfaceFlinger untuk dipicu komposisi, dan output tampilan. Jika SurfaceFlinger menentukan bahwa tidak ada tugas yang selesai, ia akan kembali tidur.
5. SurfaceFlinger menangani komposisi menggunakan Hardware Composer (HWC)/Hardware Composer 2 (HWC2) atau GL. Komposisi HWC/HWC2 lebih cepat dan daya lebih rendah tetapi memiliki batasan tergantung pada sistem pada {i>chip<i} (SoC). Proses ini biasanya memerlukan waktu ~4–6 md, tetapi dapat tumpang-tindih dengan langkah 2 karena Android aplikasi selalu di-buffer tiga kali. (Meskipun aplikasi selalu di-buffer tiga kali, ada mungkin hanya satu frame tertunda yang menunggu di SurfaceFlinger, yang membuatnya muncul identik dengan buffering ganda.)
6. SurfaceFlinger mengirim {i>output<i} akhir untuk ditampilkan dengan {i>driver<i} vendor dan mulai kembali ke tidur, menunggu pengaktifan {i>EventThread<i}.

Mari kita telusuri frame yang dimulai dari 15.409 md:

Gambar 1 adalah bingkai normal yang dikelilingi oleh bingkai normal, jadi itu bagus untuk memahami cara kerja pipeline UI. Baris UI thread untuk TouchLatensi menyertakan berbagai warna pada waktu yang berbeda. Batang menunjukkan status yang berbeda untuk thread:

• Abu-abu. Tidur.
• Biru. Dapat dijalankan (dapat berjalan, tetapi penjadwal belum memilih untuk menjalankannya).
• Hijau. Berjalan secara aktif (penjadwal berpikir sedang berjalan).
• Merah. Tidur tanpa gangguan (umumnya tidur saat terkunci di kernel). Dapat menjadi indikasi beban I/O. Amat sangat berguna untuk proses debug masalah performa.
• Oranye. Tidur tanpa gangguan karena beban I/O.

Untuk melihat alasan tidur tanpa gangguan (tersedia dari sched_blocked_reason tracepoint), pilih elemen merah yang tidak dapat diinterupsi irisan tidur.

Saat EventThread berjalan, UI thread untuk TouchLatensi menjadi dapat dijalankan. Untuk melihat apa yang membangunkannya, klik bagian berwarna biru.

Gambar 2 menunjukkan thread UI TouchLatensi diaktifkan oleh tid 6843, yang sesuai dengan EventThread. UI thread mengaktifkan, merender frame, dan mengantrekan untuk digunakan oleh SurfaceFlinger.

Jika tag binder_driver diaktifkan di rekaman aktivitas, Anda dapat memilih transaksi binder untuk melihat informasi tentang semua proses yang terlibat di dalamnya transaksi.

Gambar 4 menunjukkan bahwa, pada 15.423,65 md Binder:6832_1 di SurfaceFlinger menjadi dapat dijalankan karena tid 9579, yang merupakan RenderThread TouchLatensi. Anda juga dapat lihat queueBuffer di kedua sisi transaksi binder.

Selama queueBuffer di sisi SurfaceFlinger, jumlah frame dari TouchLatensi bervariasi dari 1 hingga 2.

Gambar 5 menunjukkan tiga buffering, di mana ada dua {i>frame<i} yang telah selesai dan aplikasi akan mulai merender sepertiganya. Hal ini karena kita sudah meletakkan beberapa {i>frame<i}, sehingga aplikasi menyimpan dua {i>frame<i} yang tertunda, bukan satu frame, untuk menghindari {i>frame<i} yang dilepas lebih lanjut.

Segera setelah itu, thread utama SurfaceFlinger dibangunkan oleh {i>EventThread <i}kedua jadi hal itu dapat menghasilkan frame tertunda yang lebih lama ke layar:

SurfaceFlinger terlebih dahulu mengait buffer tertunda yang lama, sehingga menyebabkan jumlah buffer tertunda berkurang dari 2 menjadi 1.

Setelah menempel buffer, SurfaceFlinger menyiapkan komposisi dan mengirimkan {i>frame<i} terakhir ke layar. (Beberapa bagian ini diaktifkan sebagai bagian dari mdss, sehingga mungkin tidak disertakan di SoC Anda.)

Selanjutnya, mdss_fb0 akan aktif di CPU 0. mdss_fb0 adalah menampilkan thread kernel pipeline untuk menghasilkan output dari frame yang dirender ke tampilan. Kita dapat melihat mdss_fb0 sebagai barisnya sendiri dalam rekaman aktivitas (scroll ke bawah untuk ).

mdss_fb0 aktif, berjalan sebentar, memasuki mode tidur tanpa gangguan, lalu bangun kembali.

Contoh: Frame tidak berfungsi

Contoh ini menjelaskan systrace yang digunakan untuk men-debug jitter Pixel/Pixel XL. Kepada ikuti contoh, unduh file zip rekaman aktivitas (yang mencakup rekaman aktivitas lain yang disebut ), ekstrak file tersebut, dan buka file systrace_tutorial.html di browser.

Saat membuka systrace, Anda akan melihat sesuatu seperti ini:

Saat mencari jank, periksa baris FrameMissing di bagian SurfaceFlinger. FrameMissing adalah peningkatan kualitas hidup yang disediakan oleh HWC2. Saat melihat systrace untuk perangkat lain, baris FrameMissing mungkin tidak ada jika perangkat tidak menggunakan HWC2. Pada , FrameMissing berkorelasi dengan SurfaceFlinger yang kehilangan salah satu runtime yang sangat teratur dan jumlah buffer tertunda yang tidak berubah untuk aplikasi (com.prefabulated.touchlatency) pada vsync.

Gambar 11 menunjukkan frame yang terlewat pada 15598,29&nbps;ms. SurfaceFlinger terbangun sebentar pada interval {i>vsync<i} dan kembali tidur tanpa melakukan pekerjaan apa pun, yang berarti SurfaceFlinger menentukan bahwa tidak layak mencoba mengirim frame ke layar untuk mencoba lagi perintah. Mengapa?

Untuk memahami bagaimana {i>pipelines<i} untuk {i>frame<i} ini, pertama-tama tinjau contoh frame kerja di atas untuk melihat bagaimana pipeline UI normal muncul di systrace. Jika sudah siap, kembali ke frame yang terlewat dan lanjutkan ke belakang. Perhatikan bahwa SurfaceFlinger bangun dan segera tidur. Saat melihat jumlah frame yang tertunda dari TouchLatensi, ada dua frame (petunjuk yang bagus untuk mencari tahu apa yang sedang terjadi).

Karena kita memiliki frame di SurfaceFlinger, ini bukan masalah aplikasi. Selain itu, SurfaceFlinger aktif pada waktu yang tepat, jadi itu bukan SurfaceFlinger masalah performa. Jika SurfaceFlinger dan aplikasi terlihat normal, mungkin itu masalah {i>driver<i}.

Karena tracepoint mdss dan sync diaktifkan, kita bisa mendapatkan informasi tentang {i>fence<i} (dibagikan antara {i>driver<i} layar dan SurfaceFlinger) yang mengontrol kapan frame dikirim ke layar. Pagar ini tercantum dalam mdss_fb0_retire, yang menunjukkan kapan {i>frame<i} muncul di layar. Pagar ini disediakan sebagai bagian dari kategori rekaman aktivitas sync. Pagar yang sesuai dengan peristiwa tertentu di SurfaceFlinger bergantung pada SOC dan stack driver Anda, jadi bekerja sama dengan vendor SOC Anda untuk memahami arti kategori fence di rekaman aktivitas.

Gambar 13 menunjukkan frame yang ditampilkan selama 33 md, bukan 16,7 md seperti yang diharapkan. Setengah melewati irisan itu, bingkai itu seharusnya diganti dengan yang baru tapi ternyata tidak. Lihat frame sebelumnya dan cari apa pun.

Gambar 14 menunjukkan frame 14,482 md. Segmen dua frame yang rusak adalah 33,6 md, yang kurang lebih sama dengan yang kita harapkan untuk dua frame (kita merender pada 60 Hz, 16,7 md per {i>frame<i}, yang mendekati). Namun, 14,482 md sama sekali tidak mendekati 16,7 md, menunjukkan bahwa ada sesuatu yang salah dengan pipa tampilan.

Menyelidiki persis di mana fence itu berakhir untuk menentukan apa yang mengontrolnya.

Antrean kerja berisi __vsync_retire_work_handler, yang berjalan saat {i>fence<i} berubah. Melihat melalui sumber {i>kernel<i}, Anda dapat melihat bahwa itu adalah bagian dari {i>driver<i} tampilan. Hal ini tampaknya berada di untuk pipeline tampilan, sehingga harus berjalan secepat mungkin. Penting dapat dijalankan untuk sekitar 70 kita (bukan penundaan penjadwalan yang lama), tetapi ini adalah antrean kerja dan mungkin tidak dijadwalkan secara akurat.

Periksa {i>frame<i} sebelumnya untuk menentukan apakah itu berkontribusi; terkadang jitter dapat bertambah seiring waktu dan pada akhirnya menyebabkan hilangnya tenggat waktu.

Garis yang dapat dijalankan di kworker tidak terlihat karena penampil mengubahnya berwarna putih jika dipilih, tetapi data statistik: 2,3 md penjadwal keterlambatan pada sebagian jalur kritis pipeline tampilan adalah buruk. Sebelum melanjutkan, perbaiki penundaan tersebut dengan memindahkan bagian jalur kritis pipeline display dari workqueue (yang berjalan sebagai SCHED_OTHER thread CFS) ke SCHED_FIFO khusus kthread. Fungsi ini memerlukan jaminan waktu sehingga workqueue tidak dapat (dan tidak dimaksudkan untuk) disediakan.

Apakah ini penyebab jank? Sulit untuk mengatakan secara pasti. Di luar kasus yang mudah didiagnosis seperti pertentangan kunci kernel yang menyebabkan masalah penting ke mode tidur, rekaman aktivitas biasanya tidak menyebutkan masalahnya. Mungkin jitter ini menjadi penyebab penurunan frame? Tentu saja. Tujuan waktu fence seharusnya 16,7 md, tetapi waktu ini tidak mendekati waktu itu sama sekali dalam frame yang mengarah ke penurunan frame. Mengingat seberapa erat hubungan pipeline tampilan ada kemungkinan jitter di sekitar pengaturan waktu fence menyebabkan penurunan {i>frame<i}.

Di contoh ini, solusi yang diperlukan adalah mengonversi __vsync_retire_work_handler dari antrean kerja ke antrean khusus kthread. Hasilnya adalah peningkatan jitter yang kentara dan berkurangnya jank dalam pengujian bola memantul. Rekaman aktivitas berikutnya menunjukkan pengaturan waktu fence yang melayang sangat dekat menjadi 16,7 md.