systrace to podstawowe narzędzie do analizy wydajności urządzenia z systemem Android. Jednak tak naprawdę jest to opakowanie wokół innych narzędzi. Jest to wrapper po stronie hosta wokół atrace , pliku wykonywalnego po stronie urządzenia, który kontroluje śledzenie w przestrzeni użytkownika i konfiguruje ftrace , a także podstawowy mechanizm śledzenia w jądrze Linux. systrace używa atrace do włączenia śledzenia, a następnie odczytuje bufor ftrace i umieszcza go w samodzielnej przeglądarce HTML. (Podczas gdy nowsze jądra obsługują filtr Linux Enhanced Berkeley Packet Filter (eBPF), poniższa dokumentacja dotyczy jądra 3.18 (bez eFPF), ponieważ to właśnie było używane w Pixel/Pixel XL.)
Systrace jest własnością zespołów Google Android i Google Chrome i jest open source w ramach projektu Catapult . Oprócz systrace, Catapult zawiera inne przydatne narzędzia. Na przykład ftrace ma więcej funkcji niż można bezpośrednio włączyć za pomocą systrace lub atrace i zawiera pewne zaawansowane funkcje, które mają kluczowe znaczenie dla debugowania problemów z wydajnością. (Te funkcje wymagają uprawnień administratora i często nowego jądra).
System operacyjny
Debugując jitter na Pixel/Pixel XL, zacznij od następującego polecenia:
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
W połączeniu z dodatkowymi punktami śledzenia wymaganymi dla aktywności GPU i potoku wyświetlania daje to możliwość śledzenia od danych wejściowych użytkownika do klatki wyświetlanej na ekranie. Ustaw rozmiar bufora na coś dużego, aby uniknąć utraty zdarzeń (ponieważ bez dużego bufora niektóre procesory nie zawierają żadnych zdarzeń po pewnym punkcie śledzenia).
Przechodząc przez systrace, pamiętaj, że każde zdarzenie jest wywoływane przez coś na procesorze .
Ponieważ systrace jest zbudowane na ftrace, a ftrace działa na procesorze, coś na procesorze musi zapisać bufor ftrace, który rejestruje zmiany sprzętu. Oznacza to, że jeśli jesteś ciekawy, dlaczego bariera wyświetlania zmieniła stan, możesz zobaczyć, co działało na procesorze dokładnie w momencie przejścia (coś działającego na procesorze wywołało tę zmianę w dzienniku). Ta koncepcja jest podstawą analizy wydajności za pomocą systrace.
Przykład: Rama robocza
W tym przykładzie opisano systrace dla normalnego potoku interfejsu użytkownika. Aby postępować zgodnie z przykładem, pobierz plik zip ze śladami (który zawiera również inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz plik systrace_tutorial.html w przeglądarce. Ostrzegamy, że ten systrace to duży plik; chyba że używasz systrace w swojej codziennej pracy, jest to prawdopodobnie znacznie większy ślad z dużo większą ilością informacji niż kiedykolwiek widziałeś w pojedynczym śladzie.
W przypadku spójnego, okresowego obciążenia, takiego jak TouchLatency, potok interfejsu użytkownika zawiera następujące elementy:
- EventThread w SurfaceFlinger wybudza wątek interfejsu użytkownika aplikacji, sygnalizując, że nadszedł czas na renderowanie nowej klatki.
- Aplikacja renderuje klatkę w wątku interfejsu użytkownika, RenderThread i hwuiTasks przy użyciu zasobów procesora CPU i GPU. To jest większość pojemności zużywanej na interfejs użytkownika.
- Aplikacja wysyła wyrenderowaną ramkę do SurfaceFlinger za pomocą bindera, a następnie SurfaceFlinger przechodzi w stan uśpienia.
- Drugi EventThread w SurfaceFlinger budzi SurfaceFlinger, aby wyzwolić kompozycję i wyświetlanie danych wyjściowych. Jeśli SurfaceFlinger stwierdzi, że nie ma pracy do wykonania, wraca do snu.
- SurfaceFlinger obsługuje kompozycję za pomocą Hardware Composer (HWC)/Hardware Composer 2 (HWC2) lub GL. Kompozycja HWC/HWC2 jest szybsza i ma mniejszą moc, ale ma ograniczenia w zależności od systemu na chipie (SoC). Zwykle zajmuje to ~4-6 ms, ale może nakładać się na krok 2, ponieważ aplikacje na Androida są zawsze potrójnie buforowane. (Podczas gdy aplikacje są zawsze potrójnie buforowane, w SurfaceFlinger może być tylko jedna oczekująca ramka, co sprawia, że wygląda ona identycznie jak podwójne buforowanie.)
- SurfaceFlinger wysyła końcowe dane wyjściowe do wyświetlenia za pomocą sterownika dostawcy i ponownie przechodzi w stan uśpienia, czekając na przebudzenie EventThread.
Przejdźmy przez klatkę rozpoczynającą się od 15409 ms:
Rysunek 1 to normalna ramka otoczona normalnymi ramkami, więc jest to dobry punkt wyjścia do zrozumienia, jak działa potok interfejsu użytkownika. Wiersz wątku interfejsu użytkownika dla TouchLatency zawiera różne kolory w różnym czasie. Słupki oznaczają różne stany wątku:
- Szary . Spanie.
- Niebieski. Runnable (może działać, ale harmonogram nie wybrał go jeszcze do uruchomienia).
- Zielony. Aktywnie uruchomiony (program planujący myśli, że działa).
- Czerwony. Nieprzerwany sen (zwykle spanie na kłódce w jądrze). Może wskazywać na obciążenie we/wy. Niezwykle przydatne do debugowania problemów z wydajnością.
- Pomarańczowy. Nieprzerwany tryb uśpienia z powodu obciążenia we/wy.
Aby wyświetlić przyczynę nieprzerywanego uśpienia (dostępną w sched_blocked_reason ), wybierz czerwony wycinek uśpienia bezprzerwowego.
Gdy EventThread jest uruchomiony, wątek interfejsu użytkownika dla TouchLatency staje się możliwy do uruchomienia. Aby zobaczyć, co go obudziło, kliknij niebieską sekcję.
Rysunek 2 pokazuje, że wątek TouchLatency UI został obudzony przez tid 6843, co odpowiada EventThread. Wątek interfejsu użytkownika budzi się, renderuje ramkę i umieszcza ją w kolejce do wykorzystania przez SurfaceFlinger.
Jeśli tag binder_driver jest włączony w śledzeniu, możesz wybrać transakcję spinacza, aby wyświetlić informacje o wszystkich procesach zaangażowanych w tę transakcję.
Rysunek 4 pokazuje, że przy 15 423,65 ms Binder:6832_1 w SurfaceFlinger zaczyna działać z powodu tid 9579, który jest RenderThread TouchLatency. Możesz również zobaczyć queueBuffer po obu stronach transakcji spinacza.
Podczas kolejkiBuffer po stronie SurfaceFlinger liczba oczekujących ramek z TouchLatency wzrasta od 1 do 2.
Rysunek 5 pokazuje potrójne buforowanie, gdzie są dwie ukończone klatki, a aplikacja wkrótce zacznie renderować trzecią. Dzieje się tak, ponieważ porzuciliśmy już niektóre ramki, więc aplikacja zachowuje dwie oczekujące ramki zamiast jednej, aby uniknąć kolejnych pominiętych ramek.
Niedługo potem główny wątek SurfaceFlingera zostaje wybudzony przez drugi wątek EventThread, dzięki czemu może wyświetlić na wyświetlaczu starszą oczekującą ramkę:
SurfaceFlinger najpierw blokuje starszy oczekujący bufor, co powoduje zmniejszenie liczby oczekujących buforów z 2 do 1.
Po zatrzaśnięciu bufora SurfaceFlinger ustawia kompozycję i przesyła ostateczną klatkę na wyświetlacz. (Niektóre z tych sekcji są włączone jako część punktu mdss , więc mogą nie być uwzględnione w SoC).
Następnie mdss_fb0 budzi się na CPU 0. mdss_fb0 to wątek jądra potoku wyświetlania, który wysyła wyrenderowaną ramkę na wyświetlacz. Możemy zobaczyć mdss_fb0 jako własny wiersz w śladzie (przewiń w dół, aby wyświetlić).
mdss_fb0 budzi się, działa krótko, przechodzi w nieprzerwany sen, a następnie budzi się ponownie.
Przykład: Niedziałająca rama
Ten przykład opisuje systrace używane do debugowania jittera Pixel/Pixel XL. Aby postępować zgodnie z przykładem, pobierz plik zip ze śladami (który zawiera inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz plik systrace_tutorial.html w przeglądarce.
Kiedy otworzysz systrace, zobaczysz coś takiego:
Szukając dżonka, sprawdź wiersz FrameMissed pod SurfaceFlinger. FrameMissed to poprawa jakości życia zapewniana przez HWC2. Podczas przeglądania systrace dla innych urządzeń wiersz FrameMissed może nie być obecny, jeśli urządzenie nie korzysta z HWC2. W obu przypadkach FrameMissed jest skorelowany z SurfaceFlingerem, w którym brakuje jednego z jego niezwykle regularnych środowisk wykonawczych i niezmienionej liczby buforów oczekujących dla aplikacji ( com.prefabulated.touchlatency ) w vsync.
Rysunek 11 pokazuje brakującą klatkę przy 15598,29&nbps;ms. SurfaceFlinger obudził się na krótko w interwale vsync i ponownie zasnął bez wykonywania żadnej pracy, co oznacza, że SurfaceFlinger uznał, że nie warto ponownie wysyłać ramki na wyświetlacz. Czemu?
Aby zrozumieć, w jaki sposób potok uległ awarii dla tej ramki, najpierw przejrzyj powyższy przykład ramki roboczej, aby zobaczyć, jak wygląda normalny potok interfejsu użytkownika w systrace. Gdy będziesz gotowy, wróć do pominiętej klatki i pracuj do tyłu. Zauważ, że SurfaceFlinger budzi się i natychmiast zasypia. Podczas przeglądania liczby oczekujących ramek z TouchLatency są dwie ramki (dobra wskazówka, aby pomóc dowiedzieć się, co się dzieje).
Ponieważ w SurfaceFlingerze mamy ramki, nie jest to problem z aplikacją. Ponadto SurfaceFlinger budzi się we właściwym czasie, więc nie jest to problem z SurfaceFlingerem. Jeśli SurfaceFlinger i aplikacja wyglądają normalnie, prawdopodobnie jest to problem ze sterownikiem.
Ponieważ mdss i sync są włączone, możemy uzyskać informacje o ogrodzeniach (współdzielonych przez sterownik ekranu i SurfaceFlinger), które kontrolują przesyłanie ramek do ekranu. Ogrodzenia te są wymienione pod mdss_fb0_retire , co oznacza, że ramka jest wyświetlana. Te ogrodzenia są dostarczane jako część kategorii śledzenia sync . To, które ogrodzenia odpowiadają konkretnym zdarzeniom w SurfaceFlinger, zależy od Twojego SOC i stosu sterowników, więc współpracuj z dostawcą SOC, aby zrozumieć znaczenie kategorii ogrodzeń w Twoich śladach.
Rysunek 13 pokazuje klatkę, która była wyświetlana przez 33 ms, a nie 16,7 ms, jak oczekiwano. W połowie tego wycinka ta ramka powinna była zostać zastąpiona nową, ale tak się nie stało. Wyświetl poprzednią klatkę i poszukaj czegokolwiek.
Rysunek 14 pokazuje 14,482 ms na ramkę. Zepsuty dwuklatkowy segment wynosił 33,6 ms, czyli mniej więcej tyle, ile oczekiwalibyśmy dla dwóch klatek (renderujemy przy 60 Hz, 16,7 ms na klatkę, czyli blisko). Ale 14,482 ms wcale nie jest zbliżone do 16,7 ms, co sugeruje, że coś jest nie tak z rurą wyświetlającą.
Zbadaj dokładnie, gdzie kończy się to ogrodzenie, aby ustalić, co je kontroluje.
Kolejka robocza zawiera __vsync_retire_work_handler , który jest uruchomiony, gdy zmienia się ogrodzenie. Przeglądając źródła jądra, możesz zobaczyć, że jest to część sterownika ekranu. Wygląda na to, że znajduje się na krytycznej ścieżce potoku wyświetlania, więc musi działać tak szybko, jak to możliwe. Można go uruchomić przez około 70 nas (nie jest to długie opóźnienie w harmonogramie), ale jest to kolejka robocza i może nie zostać dokładnie zaplanowany.
Sprawdź poprzednią klatkę, aby ustalić, czy to się przyczyniło; czasami jitter może się sumować z czasem i ostatecznie spowodować przekroczenie terminu.
Wiersz uruchamialny w kworker jest niewidoczny, ponieważ przeglądarka zmienia kolor na biały, gdy jest zaznaczony, ale statystyki mówią prawdę: 2,3 ms opóźnienia harmonogramu dla części krytycznej ścieżki potoku wyświetlania jest złe . Przed kontynuowaniem napraw opóźnienie, które polega na przeniesieniu tej części krytycznej ścieżki potoku wyświetlania z kolejki roboczej (która działa jako wątek SCHED_OTHER CFS) do dedykowanego wątku k SCHED_FIFO . Ta funkcja wymaga gwarancji czasu, których kolejki robocze nie mogą (i nie są przeznaczone) zapewnić.
Czy to jest powód szarpnięcia? Trudno powiedzieć jednoznacznie. Poza łatwymi do zdiagnozowania przypadkami, takimi jak rywalizacja o blokadę jądra powodująca uśpienie wątków krytycznych dla wyświetlania, ślady zwykle nie określają problemu. Czy ten jitter mógł być przyczyną wypadnięcia klatki? Absolutnie. Czasy ogrodzenia powinny wynosić 16,7 ms, ale w klatkach prowadzących do opuszczonej klatki wcale nie są zbliżone. Biorąc pod uwagę, jak ściśle powiązany jest potok wyświetlania, możliwe jest, że drgania wokół taktowania ogrodzenia spowodowały utratę klatki.
W tym przykładzie rozwiązanie obejmowało konwersję __vsync_retire_work_handler z kolejki roboczej na dedykowany kthread. Spowodowało to zauważalną poprawę jittera i zmniejszenie szarpnięć w teście odbijającej się piłki. Kolejne ślady pokazują czasy ogrodzenia, które oscylują bardzo blisko 16,7 ms.