systrace adalah alat utama untuk menganalisis performa perangkat Android. Namun, ini sebenarnya adalah wrapper di sekitar alat lain. Ini adalah wrapper sisi host di sekitar atrace, file yang dapat dieksekusi 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 buffering ftrace dan menggabungkan semuanya dalam penampil HTML mandiri. (Meskipun kernel yang lebih baru memiliki dukungan untuk Linux Enhanced Berkeley Packet Filter (eBPF), dokumentasi berikut terkait dengan kernel 3.18 (tanpa eFPF) karena itulah yang digunakan di Pixel/Pixel XL.)
systrace dimiliki oleh tim Google Android dan Google Chrome serta merupakan 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/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 tracepoint tambahan yang diperlukan untuk aktivitas pipeline GPU dan tampilan, hal ini memberi Anda kemampuan untuk melacak dari input pengguna ke frame yang ditampilkan di layar. Tetapkan ukuran buffering ke ukuran yang besar untuk menghindari hilangnya peristiwa (karena tanpa buffering yang besar, beberapa CPU tidak berisi peristiwa setelah beberapa titik dalam rekaman aktivitas).
Saat menggunakan systrace, perlu diingat bahwa setiap peristiwa dipicu oleh sesuatu di CPU.
Karena systrace dibuat di atas ftrace dan ftrace berjalan di CPU, sesuatu di CPU harus menulis buffering ftrace yang mencatat perubahan hardware. Artinya, jika Anda ingin tahu alasan status pagar tampilan berubah, Anda dapat melihat apa yang berjalan di CPU pada titik transisi yang tepat (sesuatu yang berjalan di CPU memicu perubahan tersebut dalam log). Konsep ini adalah dasar analisis performa menggunakan systrace.
Contoh: Frame kerja
Contoh ini menjelaskan systrace untuk pipeline UI normal. Untuk mengikuti
contoh, download file zip rekaman aktivitas
(yang juga menyertakan rekaman aktivitas lain yang dirujuk di bagian ini), ekstrak file,
dan buka file systrace_tutorial.html di browser Anda. Perlu diperhatikan
bahwa systrace ini adalah file berukuran besar; kecuali jika Anda menggunakan systrace dalam pekerjaan
sehari-hari, ini mungkin adalah rekaman aktivitas yang jauh lebih besar dengan informasi yang jauh lebih banyak daripada yang pernah
Anda lihat dalam satu rekaman aktivitas sebelumnya.
Untuk beban kerja berkala yang konsisten seperti TouchLatency, pipeline UI berisi hal berikut:
- EventThread di SurfaceFlinger mengaktifkan UI thread aplikasi, yang menandakan bahwa sudah waktunya merender frame baru.
- Aplikasi merender frame di UI thread, RenderThread, dan hwuiTasks, menggunakan resource CPU dan GPU. Ini adalah sebagian besar kapasitas yang digunakan untuk UI.
- Aplikasi mengirimkan frame yang dirender ke SurfaceFlinger menggunakan binder, lalu SurfaceFlinger akan tidur.
- EventThread kedua di SurfaceFlinger akan mengaktifkan SurfaceFlinger untuk memicu komposisi dan menampilkan output. Jika SurfaceFlinger menentukan bahwa tidak ada pekerjaan yang harus dilakukan, SurfaceFlinger akan kembali ke mode tidur.
- SurfaceFlinger menangani komposisi menggunakan Hardware Composer (HWC)/Hardware Composer 2 (HWC2) atau GL. Komposisi HWC/HWC2 lebih cepat dan lebih hemat daya, tetapi memiliki batasan bergantung pada sistem pada chip (SoC). Proses ini biasanya memerlukan waktu ~4-6 milidetik, tetapi dapat tumpang-tindih dengan langkah 2 karena aplikasi Android selalu memiliki buffering tiga kali. (Meskipun aplikasi selalu memiliki buffering tiga kali, mungkin hanya ada satu frame tertunda yang menunggu di SurfaceFlinger, yang membuatnya tampak identik dengan buffering ganda.)
- SurfaceFlinger mengirimkan output akhir untuk ditampilkan dengan driver vendor dan kembali ke mode tidur, menunggu pengaktifan EventThread.
Mari kita pelajari frame yang dimulai pada 15.409 milidetik:
Gambar 1 adalah frame normal yang dikelilingi oleh frame normal, sehingga merupakan titik awal yang baik untuk memahami cara kerja pipeline UI. Baris UI thread untuk TouchLatency menyertakan warna yang berbeda 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 menganggapnya berjalan).
- Merah. Tidur yang tidak dapat diganggu (biasanya tidur pada kunci di kernel). Dapat menunjukkan beban I/O. Sangat berguna untuk men-debug masalah performa.
- Oranye. Tidur yang tidak dapat diganggu karena beban I/O.
Untuk melihat alasan tidur yang tidak dapat diganggu (tersedia dari
tracepoint sched_blocked_reason), pilih slice tidur yang tidak dapat diganggu
warna merah.
Saat EventThread berjalan, UI thread untuk TouchLatency menjadi dapat dijalankan. Untuk melihat apa yang membangunkannya, klik bagian biru.
Gambar 2 menunjukkan UI thread TouchLatency diaktifkan oleh tid 6843, yang sesuai dengan EventThread. UI thread akan aktif, merender frame, dan mengantrekannya untuk 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 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 yang tertunda dari TouchLatency 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 kita telah menghapus beberapa frame, sehingga aplikasi menyimpan dua frame yang tertunda, bukan satu, untuk mencoba menghindari frame yang terhapus lebih lanjut.
Segera setelah itu, thread utama SurfaceFlinger akan diaktifkan oleh EventThread kedua sehingga dapat menghasilkan frame tertunda yang lebih lama ke layar:
SurfaceFlinger pertama-tama mengunci buffer tertunda yang lebih lama, yang menyebabkan jumlah buffer tertunda berkurang dari 2 menjadi 1.
Setelah mengikat buffer, SurfaceFlinger menyiapkan komposisi dan mengirimkan
frame akhir ke layar. (Beberapa bagian ini diaktifkan sebagai bagian dari
tracepoint mdss, sehingga mungkin tidak disertakan di SoC Anda.)
Selanjutnya, mdss_fb0 akan aktif di CPU 0. mdss_fb0 adalah
thread kernel pipeline tampilan untuk menghasilkan frame yang dirender ke layar.
Kita dapat melihat mdss_fb0 sebagai barisnya sendiri dalam rekaman aktivitas (scroll ke bawah untuk
melihat).
mdss_fb0 akan aktif, berjalan sebentar, memasuki tidur yang tidak dapat diganggu,
lalu aktif lagi.
Contoh: Frame yang tidak berfungsi
Contoh ini menjelaskan systrace yang digunakan untuk men-debug jitter Pixel/Pixel XL. Untuk
mengikuti contoh, download file ZIP rekaman aktivitas (yang mencakup rekaman aktivitas lain yang dirujuk di
bagian ini), ekstrak file, dan buka file systrace_tutorial.html di browser
Anda.
Saat membuka systrace, Anda akan melihat tampilan seperti ini:
Saat mencari jank, periksa baris FrameMissed di bagian SurfaceFlinger.
FrameMissed adalah peningkatan kualitas hidup 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-nya yang sangat reguler dan jumlah buffering yang tertunda yang tidak berubah untuk aplikasi
(com.prefabulated.touchlatency) pada vsync.
Gambar 11 menunjukkan frame yang terlewat pada 15598,29&nbps;ms. SurfaceFlinger aktif sebentar pada interval vsync dan kembali tidur tanpa melakukan pekerjaan apa pun, yang berarti SurfaceFlinger memutuskan bahwa tidak ada gunanya mencoba mengirim frame ke layar lagi. Mengapa?
Untuk memahami cara pipeline mengalami kerusakan 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 lanjutkan ke frame sebelumnya. Perhatikan bahwa SurfaceFlinger aktif dan langsung tidur. Saat melihat jumlah frame yang tertunda dari TouchLatency, ada dua frame (petunjuk yang baik untuk membantu mengetahui apa yang terjadi).
Karena kita memiliki frame di SurfaceFlinger, masalah ini bukan masalah aplikasi. Selain itu, SurfaceFlinger aktif pada waktu yang tepat, sehingga ini bukan masalah SurfaceFlinger. Jika SurfaceFlinger dan aplikasi terlihat normal, kemungkinan ini adalah masalah driver.
Karena tracepoint mdss dan sync diaktifkan,
kita bisa mendapatkan informasi tentang pagar (dibagikan antara driver tampilan dan
SurfaceFlinger) yang mengontrol kapan frame dikirim ke layar.
Pagar ini tercantum di bagian mdss_fb0_retire, yang
menunjukkan kapan frame ditampilkan. Pagar ini disediakan sebagai
bagian dari kategori rekaman aktivitas sync. Pagar mana yang sesuai dengan
peristiwa tertentu di SurfaceFlinger bergantung pada SOC dan stack driver Anda, jadi
hubungi vendor SOC Anda untuk memahami arti kategori pagar dalam
rekaman aktivitas Anda.
Gambar 13 menunjukkan frame yang ditampilkan selama 33 md, bukan 16,7 md seperti yang diharapkan. Di tengah-tengah slice tersebut, frame tersebut seharusnya diganti dengan yang baru, tetapi tidak. Lihat frame sebelumnya dan cari apa pun.
Gambar 14 menunjukkan 14,482 md per frame. Segmen dua frame yang rusak adalah 33,6 md, yang kira-kira sesuai dengan yang kita harapkan untuk dua frame (kita merender pada 60 Hz, 16,7 md per frame, yang hampir sama). Namun, 14,482 md sama sekali tidak mendekati 16,7 md, yang menunjukkan bahwa ada yang sangat salah dengan pipe tampilan.
Selidiki dengan tepat tempat pagar tersebut berakhir untuk menentukan apa yang mengontrolnya.
Workqueue berisi __vsync_retire_work_handler, yang
berjalan saat pagar berubah. Dengan melihat sumber kernel, Anda dapat melihat bahwa
ini adalah bagian dari driver layar. Tampaknya berada di jalur kritis
untuk pipeline tampilan, sehingga harus berjalan secepat mungkin. Tugas ini
dapat dijalankan selama 70 milidetik atau lebih (bukan penundaan penjadwalan yang lama), tetapi ini adalah 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 tenggat terlewati.
Baris yang dapat dijalankan di kworker tidak terlihat karena penampil mengubahnya
menjadi putih saat dipilih, tetapi statistiknya menunjukkan masalah: penundaan penjadwal
selama 2,3 milidetik untuk bagian jalur kritis pipeline tampilan buruk.
Sebelum melanjutkan, perbaiki penundaan dengan memindahkan bagian ini dari
jalur kritis pipeline tampilan dari workqueue (yang berjalan sebagai
thread CFS SCHED_OTHER) ke kthread
SCHED_FIFO khusus. Fungsi ini memerlukan jaminan pengaturan waktu yang tidak dapat (dan tidak
dimaksudkan untuk) disediakan oleh antrean kerja.
Apakah ini alasan terjadinya jank? Sulit untuk memastikannya. Selain kasus yang mudah didiagnosis seperti pertentangan kunci kernel yang menyebabkan thread kritis tampilan tidur, rekaman aktivitas biasanya tidak menentukan masalah. Apakah jitter ini dapat menyebabkan frame terputus? Tentu saja. Waktu pagar harus 16,7 md, tetapi tidak mendekati sama sekali dalam frame yang mengarah ke frame yang dihapus. Mengingat betapa erat pipeline tampilan terkait, mungkin jitter di sekitar pengaturan waktu pagar menyebabkan frame terjatuh.
Dalam contoh ini, solusinya melibatkan konversi
__vsync_retire_work_handler dari workqueue menjadi kthread
khusus. Hal ini menghasilkan peningkatan jitter yang signifikan dan mengurangi jank dalam
pengujian bola memantul. Rekaman aktivitas berikutnya menunjukkan pengaturan waktu pagar yang sangat dekat
dengan 16,7 ms.