systrace to podstawowe narzędzie do analizy wydajności urządzeń z systemem Android. Jednak tak naprawdę jest to opakowanie na inne narzędzia. Jest to opakowanie atrace po stronie hosta, plik wykonywalny po stronie urządzenia, który kontroluje śledzenie przestrzeni użytkownika i konfiguruje ftrace oraz główny mechanizm śledzenia w jądrze Linuksa. systrace używa atrace do włączenia śledzenia, następnie odczytuje bufor ftrace i pakuje wszystko w samodzielną przeglądarkę HTML. (Chociaż nowsze jądra obsługują Linux Enhanced Berkeley Packet Filter (eBPF), poniższa dokumentacja dotyczy jądra 3.18 (bez eFPF), ponieważ tego właśnie używano w Pixel/Pixel XL.)
systrace jest własnością zespołów Google Android i Google Chrome i jest oprogramowaniem typu open source będącym częścią 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 są krytyczne do debugowania problemów z wydajnością. (Te funkcje wymagają dostępu do konta root i często nowego jądra.)
Uruchamianie systemu
Podczas debugowania drgań w 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 procesora graficznego 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 duży, aby uniknąć utraty zdarzeń (ponieważ bez dużego bufora niektóre procesory nie zawierają żadnych zdarzeń po pewnym momencie śledzenia).
Podczas przeglądania systrace należy pamiętać, że każde zdarzenie jest wyzwalane przez coś w procesorze .
Ponieważ systrace jest zbudowane na bazie ftrace i ftrace działa na procesorze, coś w procesorze musi zapisać bufor ftrace, który rejestruje zmiany sprzętu. Oznacza to, że jeśli ciekawi Cię, dlaczego bariera wyświetlacza zmieniła stan, możesz zobaczyć, co działo się na procesorze dokładnie w momencie przejścia (coś uruchomionego na procesorze spowodowało tę zmianę w dzienniku). Koncepcja ta jest podstawą analizy wydajności przy użyciu systrace.
Przykład: Rama robocza
Ten przykład opisuje systrace dla normalnego potoku interfejsu użytkownika. Aby podążać za przykładem, pobierz plik ZIP zawierający ślady (który zawiera również inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz plik systrace_tutorial.html w swojej przeglądarce. Ostrzegamy, że ten plik systrace jest dużym plikiem; jeśli nie używasz systrace w swojej codziennej pracy, jest to prawdopodobnie znacznie większy ślad zawierający znacznie więcej informacji niż kiedykolwiek wcześniej 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 budzi wątek interfejsu użytkownika aplikacji, sygnalizując, że nadszedł czas na wyrenderowanie nowej klatki.
- Aplikacja renderuje klatkę w wątku interfejsu użytkownika, RenderThread i hwuiTasks, korzystając z zasobów procesora i karty graficznej. Jest to większość pojemności wydanej na interfejs użytkownika.
- Aplikacja wysyła wyrenderowaną ramkę do SurfaceFlinger za pomocą spoiwa, a następnie SurfaceFlinger przechodzi w stan uśpienia.
- Drugi wątek EventThread w SurfaceFlinger budzi SurfaceFlinger, aby wyzwolić kompozycję i wyświetlić dane wyjściowe. Jeśli SurfaceFlinger stwierdzi, że nie ma nic do wykonania, ponownie przechodzi w tryb uśpienia.
- SurfaceFlinger obsługuje kompozycję przy użyciu Hardware Composer (HWC)/Hardware Composer 2 (HWC2) lub GL. Kompozycja HWC/HWC2 jest szybsza i zużywa mniej energii, ale ma ograniczenia w zależności od systemu na chipie (SoC). Zwykle zajmuje to ~4–6 ms, ale może pokrywać się z krokiem 2, ponieważ aplikacje na Androida są zawsze potrójnie buforowane. (Chociaż aplikacje są zawsze potrójnie buforowane, w SurfaceFlingerze może znajdować się tylko jedna oczekująca ramka, co sprawia, że wygląda to identycznie jak w przypadku podwójnego buforowania).
- SurfaceFlinger wysyła końcowe dane wyjściowe do wyświetlenia za pomocą sterownika dostawcy i ponownie zasypia, czekając na wybudzenie EventThread.
Przejdźmy przez klatkę zaczynającą się od 15409 ms:
Rysunek 1 przedstawia zwykłą ramkę otoczoną normalnymi ramkami, więc jest to dobry punkt wyjścia do zrozumienia działania potoku interfejsu użytkownika. Wiersz wątku interfejsu użytkownika dla TouchLatency zawiera różne kolory w różnych momentach. Słupki oznaczają różne stany gwintu:
- Szary . Spanie.
- Niebieski. Uruchamialny (może działać, ale program planujący nie wybrał jeszcze go do uruchomienia).
- Zielony. Aktywnie działa (program planujący myśli, że działa).
- Czerwony. Nieprzerwany sen (zazwyczaj spanie na zamku w jądrze). Może wskazywać obciążenie we/wy. Niezwykle przydatny do debugowania problemów z wydajnością.
- Pomarańczowy. Nieprzerwany tryb uśpienia ze względu na obciążenie we/wy.
Aby wyświetlić przyczynę nieprzerwanego snu (dostępną w punkcie śledzenia sched_blocked_reason ), wybierz czerwony wycinek nieprzerwanego snu.
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 interfejsu użytkownika TouchLatency został obudzony przez tid 6843, który odpowiada EventThread. Wątek interfejsu użytkownika budzi się, renderuje ramkę i umieszcza ją w kolejce do wykorzystania przez SurfaceFlinger.
Jeśli w śledzeniu włączono znacznik binder_driver , można wybrać transakcję segregatora, aby wyświetlić informacje o wszystkich procesach zaangażowanych w tę transakcję.
Rysunek 4 pokazuje, że przy czasie 15 423,65 ms Binder:6832_1 w SurfaceFlinger staje się możliwy do uruchomienia ze względu na tid 9579, który jest RenderThread TouchLatency. Możesz także zobaczyć bufor kolejki po obu stronach transakcji segregatora.
Podczas buforowania kolejki po stronie SurfaceFlinger liczba oczekujących ramek z TouchLatency wzrasta z 1 do 2.
Rysunek 5 przedstawia potrójne buforowanie, w którym ukończone są dwie klatki, a aplikacja wkrótce rozpocznie renderowanie trzeciej. Dzieje się tak, ponieważ usunęliśmy już niektóre klatki, więc aplikacja przechowuje dwie oczekujące klatki zamiast jednej, aby uniknąć kolejnych porzuconych klatek.
Niedługo potem główny wątek SurfaceFlingera zostaje obudzony przez drugi 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 zablokowaniu bufora SurfaceFlinger konfiguruje kompozycję i przesyła ostateczną klatkę do wyświetlacza. (Niektóre z tych sekcji są włączone jako część punktu śledzenia mdss , więc mogą nie zostać uwzględnione w Twoim SoC.)
Następnie mdss_fb0 budzi się na CPU 0. mdss_fb0 jest wątkiem jądra potoku wyświetlania, służącym do wysyłania wyrenderowanej ramki na wyświetlacz. Widzimy mdss_fb0 jako osobny wiersz w śladzie (przewiń w dół, aby wyświetlić).
mdss_fb0 budzi się, działa przez chwilę, przechodzi w nieprzerwany sen, a następnie budzi się ponownie.
Przykład: Niedziałająca rama
Ten przykład opisuje systrace używaną do debugowania jittera Pixel/Pixel XL. Aby postępować zgodnie z przykładem, pobierz plik ZIP zawierający ślady (który zawiera inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz plik systrace_tutorial.html w swojej przeglądarce.
Po otwarciu systrace zobaczysz coś takiego:
Szukając Janka, sprawdź wiersz FrameMissed w obszarze 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 brakiem jednego z niezwykle regularnych uruchomień SurfaceFlingera i niezmienioną liczbą oczekujących buforów dla aplikacji ( com.prefabulated.touchlatency ) przy vsync.
Rysunek 11 przedstawia brakującą ramkę przy 15598,29&nbps;ms. SurfaceFlinger obudził się na chwilę w odstępie vsync i ponownie zapadł w sen, nie wykonując żadnej pracy, co oznacza, że SurfaceFlinger stwierdził, że nie warto próbować ponownie wysyłać ramki na wyświetlacz. Dlaczego?
Aby zrozumieć, w jaki sposób potok działa dla tej ramki, najpierw przejrzyj powyższy przykład ramki roboczej, aby zobaczyć, jak normalny potok interfejsu użytkownika wygląda w systrace. Gdy będziesz gotowy, wróć do pominiętej klatki i cofaj się. Zauważ, że SurfaceFlinger budzi się i natychmiast zasypia. Podczas przeglądania liczby oczekujących ramek z TouchLatency widoczne są dwie klatki (dobra wskazówka pomagająca zrozumieć, co się dzieje).
Ponieważ w SurfaceFlingerze mamy ramki, nie jest to problem aplikacji. Ponadto SurfaceFlinger budzi się we właściwym czasie, więc nie jest to problem SurfaceFlingera. Jeśli SurfaceFlinger i aplikacja wyglądają normalnie, prawdopodobnie jest to problem ze sterownikiem.
Ponieważ włączone są punkty śledzenia mdss i sync , możemy uzyskać informacje o ogrodzeniach (współdzielonych między sterownikiem ekranu i SurfaceFlingerem), które kontrolują przesyłanie klatek na wyświetlacz. Te ogrodzenia są wymienione w mdss_fb0_retire , co oznacza, kiedy na wyświetlaczu pojawia się ramka. Te ogrodzenia są częścią kategorii śledzenia sync . To, które ogrodzenia odpowiadają konkretnym zdarzeniom w SurfaceFlinger, zależy od SOC i stosu sterowników, dlatego należy współpracować z dostawcą SOC, aby zrozumieć znaczenie kategorii ogrodzeń w śladach.
Rysunek 13 przedstawia klatkę wyświetlaną przez 33 ms, a nie 16,7 ms, jak oczekiwano. W połowie tego wycinka rama powinna była zostać wymieniona na nową, ale tak się nie stało. Zobacz poprzednią klatkę i poszukaj czegokolwiek.
Rysunek 14 pokazuje 14,482 ms na ramkę. Uszkodzony segment składający się z dwóch klatek wyniósł 33,6 ms, czyli mniej więcej tyle, czego można by się spodziewać w przypadku dwóch klatek (renderujemy przy częstotliwości 60 Hz, 16,7 ms na klatkę, czyli blisko). Ale 14,482 ms wcale nie jest bliskie 16,7 ms, co sugeruje, że coś jest bardzo nie tak z rurą wyświetlającą.
Zbadaj dokładnie, gdzie kończy się to ogrodzenie, aby ustalić, co nim steruje.
Kolejka robocza zawiera __vsync_retire_work_handler , który jest uruchamiany w przypadku zmiany ogrodzenia. Przeglądając źródła jądra, widać, że jest to część sterownika ekranu. Wygląda na to, że znajduje się na ścieżce krytycznej dla potoku wyświetlania, dlatego musi działać tak szybko, jak to możliwe. Można ją uruchomić przez około 70 osób (nie jest to duże opóźnienie w harmonogramie), ale jest to kolejka robocza i może nie zostać dokładnie zaplanowana.
Sprawdź poprzednią klatkę, aby ustalić, czy to się przyczyniło; czasami wahania mogą z czasem się kumulować i ostatecznie spowodować niedotrzymanie terminu.
Uruchomiona linia w kworkerze nie jest widoczna, ponieważ przeglądarka zmienia kolor na biały po jej wybraniu, ale statystyki mówią prawdę: opóźnienie programu planującego wynoszące 2,3 ms dla części ścieżki krytycznej potoku wyświetlania jest złe . Zanim będziesz kontynuować, napraw to opóźnienie, przenosząc tę część ścieżki krytycznej potoku wyświetlania z kolejki roboczej (która działa jako wątek SCHED_OTHER CFS) do dedykowanego kwątku SCHED_FIFO . Ta funkcja wymaga gwarancji czasu, których kolejki robocze nie mogą (i nie są przeznaczone) zapewniać.
Czy to jest powód Janka? 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 te drgania mogły być przyczyną wypadania klatek? Absolutnie. Czasy ogrodzenia powinny wynosić 16,7 ms, ale wcale nie są zbliżone do tego w klatkach prowadzących do upuszczonej klatki. Biorąc pod uwagę, jak ciasno powiązany jest potok wyświetlania, możliwe jest, że drgania wokół taktowania ogrodzenia spowodowały utratę klatki.
W tym przykładzie rozwiązanie polegało na konwersji __vsync_retire_work_handler z kolejki roboczej na dedykowany wątek. Spowodowało to zauważalną poprawę drgań i zmniejszenie szarpnięć w teście odbijającej się piłki. Kolejne ślady pokazują czasy płotu, które oscylują bardzo blisko 16,7 ms.