Memahami systrace

systrace adalah alat utama untuk menganalisis performa perangkat Android. Namun, sebenarnya ini adalah wrapper di sekitar alat lain. Ini adalah wrapper sisi host di sekitar atrace, executable sisi perangkat yang mengontrol pelacakan ruang pengguna dan menyiapkan ftrace, serta mekanisme pelacakan utama di kernel Linux. systrace menggunakan atrace untuk mengaktifkan pelacakan, lalu membaca buffer ftrace dan membungkus semuanya dalam penampil HTML mandiri. (Meskipun kernel yang lebih baru memiliki dukungan untuk Linux Enhanced Berkeley Packet Filter (eBPF), halaman ini berkaitan dengan kernel 3.18 (tanpa eFPF) karena itulah yang digunakan di Pixel atau Pixel XL.)

systrace dimiliki oleh tim Google Android dan Google Chrome, serta merupakan project open source sebagai bagian dari project Catapult. Selain systrace, Catapult menyertakan utilitas berguna lainnya. Misalnya, ftrace memiliki lebih banyak fitur daripada yang dapat diaktifkan secara langsung oleh systrace atau atrace dan berisi beberapa fungsi lanjutan yang penting untuk men-debug masalah performa. (Fitur ini memerlukan akses root dan sering kali kernel baru.)

Menjalankan systrace

Saat men-debug jitter di Pixel atau Pixel XL, mulai dengan perintah berikut:

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

Jika digabungkan dengan titik pelacakan tambahan yang diperlukan untuk aktivitas pipeline GPU dan layar, Anda dapat melacak dari input pengguna hingga frame yang ditampilkan di layar. Setel ukuran buffer ke sesuatu yang besar untuk menghindari hilangnya peristiwa (karena tanpa buffer besar, beberapa CPU tidak berisi peristiwa setelah beberapa titik dalam rekaman aktivitas).

Saat memeriksa systrace, perlu diingat bahwa setiap peristiwa dipicu oleh sesuatu di CPU.

Karena systrace dibangun di atas ftrace dan ftrace berjalan di CPU, sesuatu di CPU harus menulis buffer ftrace yang mencatat perubahan hardware. Artinya, jika Anda ingin tahu alasan perubahan status pagar tampilan, Anda dapat melihat apa yang berjalan di CPU pada titik transisinya (sesuatu yang berjalan di CPU memicu perubahan tersebut dalam log). Konsep ini adalah dasar untuk menganalisis performa menggunakan systrace.

Contoh: Bingkai kerja

Contoh ini menjelaskan systrace untuk pipeline UI normal. Untuk mengikuti contoh, download file zip rekaman aktivitas (yang juga mencakup rekaman aktivitas lain yang dirujuk di bagian ini), ekstrak file, dan buka file systrace_tutorial.html di browser Anda.

Untuk workload berkala yang konsisten seperti TouchLatency, pipeline UI mengikuti urutan berikut:

1. EventThread di SurfaceFlinger mengaktifkan thread UI aplikasi, menandakan bahwa sudah waktunya merender frame baru.
2. Aplikasi merender frame dalam tugas UI thread, RenderThread, dan HWUI, menggunakan resource CPU dan GPU. Ini adalah sebagian besar kapasitas yang digunakan untuk UI.
3. Aplikasi mengirimkan frame yang dirender ke SurfaceFlinger menggunakan binder, lalu SurfaceFlinger akan memasuki mode tidur.
4. EventThread kedua di SurfaceFlinger mengaktifkan SurfaceFlinger untuk memicu komposisi dan output tampilan. Jika SurfaceFlinger menentukan bahwa tidak ada pekerjaan yang harus dilakukan, SurfaceFlinger akan kembali ke mode tidur.
5. SurfaceFlinger menangani komposisi menggunakan Hardware Composer (HWC) atau Hardware Composer 2 (HWC2) atau GL. Komposisi HWC dan HWC2 lebih cepat dan menggunakan daya lebih rendah, tetapi memiliki batasan bergantung pada system on a chip (SoC). Proses ini biasanya memerlukan waktu sekitar 4 hingga 6 md, tetapi dapat tumpang-tindih dengan langkah 2 karena aplikasi Android selalu di-buffer tiga kali. (Meskipun aplikasi selalu memiliki buffer tiga kali lipat, mungkin hanya ada satu frame tertunda yang menunggu di SurfaceFlinger, sehingga tampak identik dengan buffer dua kali lipat.)
6. SurfaceFlinger mengirimkan output akhir ke layar dengan driver vendor dan kembali ke mode tidur, menunggu EventThread diaktifkan.

Berikut contoh urutan frame yang dimulai pada 15409 md:

Gambar 1. Pipeline UI normal, EventThread berjalan.

Gambar 1 adalah frame normal yang dikelilingi oleh frame normal, sehingga merupakan titik awal yang baik untuk memahami cara kerja pipeline UI. Baris thread UI untuk TouchLatency mencakup warna yang berbeda pada waktu yang berbeda. Batang menunjukkan status yang berbeda untuk thread:

• Abu-abu. Tidur.
• Biru. Dapat dijalankan (dapat dijalankan, tetapi penjadwal belum memilihnya untuk dijalankan).
• Hijau. Berjalan aktif (penjadwal menganggapnya sedang berjalan).
• Merah. Tidur tanpa gangguan (biasanya tidur dengan kunci di kernel). Dapat menunjukkan beban I/O. Sangat berguna untuk men-debug masalah performa.
• Oranye. Tidur tanpa gangguan karena beban I/O.

Untuk melihat alasan tidur tanpa gangguan (tersedia dari titik pelacakan sched_blocked_reason), pilih irisan tidur tanpa gangguan berwarna merah.

Saat EventThread berjalan, UI thread untuk TouchLatency menjadi dapat dijalankan. Untuk melihat apa yang mengaktifkannya, klik bagian biru.

Gambar 2. UI thread untuk TouchLatency.

Gambar 2 menunjukkan bahwa thread UI TouchLatency diaktifkan oleh tid 6843, yang sesuai dengan EventThread. Thread UI aktif, merender frame, dan memasukkannya ke dalam antrean agar digunakan oleh SurfaceFlinger.

Gambar 3. Thread UI aktif, merender frame, dan memasukkannya ke dalam antrean agar digunakan oleh SurfaceFlinger.

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

Gambar 4. Transaksi binder.

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

Selama queueBuffer di sisi SurfaceFlinger, jumlah frame tertunda dari TouchLatency berubah dari 1 menjadi 2.

Gambar 5. Frame yang menunggu keputusan berkisar dari 1 hingga 2.

Gambar 5 menunjukkan buffering tiga kali, dengan dua frame yang telah selesai dan aplikasi akan mulai merender frame ketiga. Hal ini karena kami telah menghilangkan beberapa frame, sehingga aplikasi menyimpan dua frame yang tertunda, bukan satu, untuk mencoba menghindari frame yang hilang lebih lanjut.

Segera setelah itu, thread utama SurfaceFlinger diaktifkan oleh EventThread kedua sehingga dapat menampilkan frame tertunda yang lebih lama ke layar:

Gambar 6. Thread utama SurfaceFlinger diaktifkan oleh EventThread kedua.

SurfaceFlinger pertama-tama mengunci buffer tertunda yang lebih lama, yang menyebabkan jumlah buffer tertunda berkurang dari 2 menjadi 1:

Gambar 7. SurfaceFlinger pertama-tama mengunci buffer tertunda yang lebih lama.

Setelah mengaitkan buffer, SurfaceFlinger menyiapkan komposisi dan mengirimkan frame akhir ke layar. (Beberapa bagian ini diaktifkan sebagai bagian dari mdss titik rekaman aktivitas, sehingga mungkin tidak disertakan di SoC Anda.)

Gambar 8. SurfaceFlinger menyiapkan komposisi dan mengirimkan frame akhir.

Selanjutnya, mdss_fb0 aktif di CPU 0. mdss_fb0 adalah thread kernel pipeline tampilan untuk menghasilkan frame yang dirender ke layar. Perhatikan bahwa mdss_fb0 memiliki barisnya sendiri dalam rekaman aktivitas (scroll ke bawah untuk melihat):

Gambar 9. mdss_fb0 aktif di CPU 0.

mdss_fb0 bangun, berjalan sebentar, memasuki mode tidur yang tidak dapat diinterupsi, lalu bangun lagi.

Contoh: Frame yang tidak berfungsi

Contoh ini menjelaskan systrace yang digunakan untuk men-debug jitter Pixel atau Pixel XL. Untuk mengikuti contoh, download file zip rekaman aktivitas (yang mencakup rekaman aktivitas lain yang dirujuk dalam bagian ini), ekstrak file, dan buka file systrace_tutorial.html di browser Anda.

Saat membuka systrace, Anda akan melihat sesuatu seperti gambar berikut:

Gambar 10. TouchLatency berjalan di Pixel XL dengan sebagian besar opsi diaktifkan.

Pada gambar 10, sebagian besar opsi diaktifkan, termasuk titik rekaman aktivitas mdss dan kgsl.

Saat mencari jank, periksa baris FrameMissed di bagian SurfaceFlinger. FrameMissed adalah peningkatan kualitas pengalaman yang disediakan oleh HWC2. Saat melihat systrace untuk perangkat lain, baris FrameMissed mungkin tidak ada jika perangkat tidak menggunakan HWC2. Dalam kedua kasus tersebut, FrameMissed berkorelasi dengan SurfaceFlinger yang kehilangan salah satu runtime regulernya dan jumlah buffer tertunda yang tidak berubah untuk aplikasi (com.prefabulated.touchlatency) pada VSync.

Gambar 11. Korelasi FrameMissed dengan SurfaceFlinger.

Gambar 11 menunjukkan frame yang terlewat pada 15598,29 md. SurfaceFlinger bangun sebentar pada interval VSync dan kembali tidur tanpa melakukan pekerjaan apa pun, yang berarti SurfaceFlinger menentukan bahwa tidak ada gunanya mencoba mengirim frame ke layar lagi.

Untuk memahami alasan pipeline rusak untuk frame ini, tinjau terlebih dahulu contoh frame yang berfungsi di atas untuk melihat tampilan pipeline UI normal di systrace. Jika sudah siap, kembali ke frame yang terlewat dan kerjakan mundur. Perhatikan bahwa SurfaceFlinger aktif dan langsung tidur. Saat melihat jumlah frame yang tertunda dari TouchLatency, ada dua frame (petunjuk yang baik untuk membantu menentukan apa yang sedang terjadi).

Gambar 12. SurfaceFlinger aktif dan langsung tidur.

Karena ada frame di SurfaceFlinger, ini bukan masalah aplikasi. Selain itu, SurfaceFlinger aktif pada waktu yang tepat, jadi ini bukan masalah SurfaceFlinger. Jika SurfaceFlinger dan aplikasi terlihat normal, kemungkinan masalahnya adalah driver.

Karena titik pelacakan mdss dan sync diaktifkan, Anda bisa mendapatkan informasi tentang pagar (dibagikan antara driver tampilan dan SurfaceFlinger) yang mengontrol kapan frame dikirimkan ke layar. Penghalang ini tercantum di bagian mdss_fb0_retire, yang menunjukkan kapan frame berada di layar. Pembatas ini disediakan sebagai bagian dari kategori rekaman aktivitas sync. Penghalang mana yang sesuai dengan peristiwa tertentu di SurfaceFlinger bergantung pada SOC dan stack driver Anda, jadi bekerjasamalah dengan vendor SOC Anda untuk memahami arti kategori penghalang dalam rekaman aktivitas Anda.

Gambar 13. mdss_fb0_retire fences.

Gambar 13 menunjukkan frame yang ditampilkan selama 33 md, bukan 16,7 md seperti yang diharapkan. Di tengah irisan tersebut, frame itu seharusnya diganti dengan frame baru, tetapi tidak. Lihat frame sebelumnya dan cari sesuatu.

Gambar 14. Frame sebelumnya ke frame yang rusak.

Gambar 14 menunjukkan frame 14.482 md. Segmen dua frame yang rusak adalah 33,6 md, yang kira-kira sesuai dengan yang diharapkan untuk dua frame (dirender pada 60 Hz, 16,7 md per frame, yang hampir sama). Namun, 14.482 md tidak mendekati 16,7 md, yang menunjukkan bahwa ada yang salah dengan jalur tampilan.

Selidiki dengan tepat di mana pagar itu berakhir untuk menentukan apa yang mengontrolnya:

Gambar 15. Periksa ujung pagar.

Workqueue berisi __vsync_retire_work_handler, yang berjalan saat pagar berubah. Dengan melihat kode sumber kernel, Anda dapat melihat bahwa kode tersebut adalah bagian dari driver layar. Tampaknya berada di jalur penting untuk pipeline tampilan, sehingga harus berjalan secepat mungkin. Dapat dijalankan selama sekitar 70 μs (bukan penundaan penjadwalan yang lama), tetapi merupakan workqueue dan mungkin tidak dijadwalkan secara akurat.

Periksa frame sebelumnya untuk menentukan apakah hal itu berkontribusi; terkadang jitter dapat bertambah seiring waktu dan akhirnya menyebabkan batas waktu terlewat:

Gambar 16. Frame sebelumnya.

Baris yang dapat dijalankan di kworker tidak terlihat karena penampil mengubahnya menjadi putih saat dipilih, tetapi statistik menceritakan kisahnya: 2,3 mdetik penundaan penjadwal untuk sebagian jalur kritis pipeline tampilan adalah buruk. Sebelum melanjutkan, perbaiki penundaan dengan memindahkan bagian jalur kritis pipeline tampilan ini dari workqueue (yang berjalan sebagai thread SCHED_OTHER CFS) ke kthread SCHED_FIFO khusus. Fungsi ini memerlukan jaminan pengaturan waktu yang tidak dapat (dan tidak dimaksudkan untuk) diberikan oleh workqueue.

Tidak jelas apakah ini adalah alasan terjadinya jank. Di luar kasus yang mudah didiagnosis seperti pertentangan penguncian kernel yang menyebabkan thread penting untuk tampilan tidak aktif, rekaman aktivitas biasanya tidak menentukan masalahnya. Jitter ini mungkin menjadi penyebab frame yang terputus. Waktu pembatas harus 16,7 md, tetapi tidak mendekati angka tersebut sama sekali dalam frame yang menyebabkan frame terputus. Mengingat betapa eratnya keterikatan pipeline tampilan, kemungkinan jitter di sekitar waktu sinkronisasi menyebabkan frame terputus.

Dalam contoh ini, solusinya melibatkan konversi __vsync_retire_work_handler dari workqueue ke kthread khusus. Hal ini menghasilkan peningkatan jitter yang terlihat jelas dan mengurangi jank dalam uji bola memantul. Rekaman aktivitas berikutnya menunjukkan waktu pembatasan yang sangat mendekati 16,7 md.