systrace to główne narzędzie do analizowania wydajności urządzenia z Androidem. Jest to jednak swego rodzaju zewnętrzna warstwa innych narzędzi. Jest to oprogramowanie na stronie hosta, które otacza atrace, czyli plik wykonywalny po stronie urządzenia, który kontroluje śledzenie przestrzeni użytkownika i konfiguruje ftrace, oraz podstawowy mechanizm śledzenia w jądrze Linuksa. systrace używa atrace do włączenia śledzenia, a następnie odczytuje bufor ftrace i spakuję wszystko w samodzielnym podglądzie HTML. (chociaż nowsze jądra obsługują filtr pakietów eBPF dla systemu Linux, poniższa dokumentacja dotyczy jądra 3.18 (bez eFPF), ponieważ było ono używane na Pixelu i Pixelu XL).
Narzędzie systrace jest własnością zespołów Google Android i Google Chrome. Jest to narzędzie open source w ramach projektu Catapult. Oprócz systrace Catapult zawiera też inne przydatne narzędzia. Na przykład ftrace ma więcej funkcji, które można włączyć bezpośrednio za pomocą systrace lub atrace, oraz zawiera niektóre zaawansowane funkcje, które są kluczowe dla debugowania problemów z wydajnością. (Te funkcje wymagają dostępu roota i często nowego jądra).
Uruchamianie systrace
Podczas debugowania jittera na Pixelu/Pixelu XL zacznij od tego 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 do aktywności GPU i rdzenia wyświetlania umożliwia to śledzenie od danych wejściowych użytkownika do wyświetlenia obrazu na ekranie. Ustaw duży rozmiar bufora, aby uniknąć utraty zdarzeń (bez dużego bufora niektóre procesory nie zawierają żadnych zdarzeń po pewnym punkcie w śladzie).
Podczas analizowania pliku systrace pamiętaj, że każde zdarzenie jest wywoływane przez coś na procesorze.
Ponieważ systrace jest oparty na ftrace, a ftrace działa na procesorze, coś na procesorze musi zapisywać w buforze ftrace, który rejestruje zmiany sprzętowe. Oznacza to, że jeśli chcesz się dowiedzieć, dlaczego stan wyświetlacza zmienił się w ogrodzenie, możesz sprawdzić, co było wykonywane na procesorze w dokładnym momencie przejścia (coś działającego na procesorze wywołało tę zmianę w rejestrze). Ten koncept jest podstawą analizowania wydajności za pomocą systrace.
Przykład: ramka robocza
Ten przykład opisuje ślad systemowy dla zwykłego potoku interfejsu. Aby prześledzić przykład, pobierz plik ZIP z śladami (zawiera on też inne ślady wymienione w tej sekcji), rozpakuj plik ZIP i otwórz plik systrace_tutorial.html w przeglądarce. Pamiętaj, że ten plik systrace jest duży. O ile nie używasz go na co dzień, jest to prawdopodobnie znacznie większy ślad z wiele większą ilością informacji niż kiedykolwiek wcześniej.
W przypadku spójnego, okresowego obciążenia, takiego jak TouchLatency, potok interfejsu użytkownika zawiera:
- EventThread w SurfaceFlinger budzi wątek interfejsu użytkownika aplikacji, sygnalizując, że nadszedł czas na renderowanie nowego kadru.
- Aplikacja renderuje klatkę w wątku interfejsu użytkownika, wątku renderowania i hwuiTasks, używając zasobów procesora i procesora graficznego. To większość mocy obliczeniowej przeznaczonej na interfejs.
- Aplikacja wysyła wyrenderowaną klatkę do usługi SurfaceFlinger za pomocą bindera, a potem usługa SurfaceFlinger przechodzi w stan uśpienia.
- Drugi wątek zdarzeń w SurfaceFlinger uruchamia SurfaceFlinger, aby wywołać kompozycję i wyświetlić dane wyjściowe. Jeśli SurfaceFlinger stwierdzi, że nie ma nic do zrobienia, wraca do stanu uśpienia.
- SurfaceFlinger obsługuje kompozycję za pomocą narzędzia do tworzenia kompozycji na sprzęcie (HWC)/narzędzia do tworzenia kompozycji na sprzęcie 2 (HWC2) lub GL. Kompilacja HWC/HWC2 jest szybsza i wymaga mniej energii, ale ma ograniczenia zależne od systemu na chipie (SoC). Zwykle zajmuje to około 4–6 ms, ale może się pokrywać z etap 2, ponieważ aplikacje na Androida mają zawsze potrójny bufor. (chociaż aplikacje zawsze mają potrójny bufor, w SurfaceFlinger może być tylko 1 ramka oczekująca na wyświetlenie, co sprawia, że wygląda to jak podwójne buforowanie).
- SurfaceFlinger wysyła ostateczne dane do wyświetlenia za pomocą sterownika dostawcy, a potem przechodzi w stan uśpienia, oczekując na powiadomienie z EventThread.
Przyjrzyjmy się klatce, która zaczyna się w 15409 ms:
Rysunek 1 przedstawia zwykły kadr otoczony zwykłymi kadrami, więc jest dobrym punktem wyjścia do zrozumienia, jak działa ścieżka interfejsu użytkownika. Wiersz wątku interfejsu użytkownika dotyczący opóźnienia dotykowego zawiera różne kolory w różnych momentach. Paski oznaczają różne stany wątku:
- Szary. śpi.
- Niebieski. Możliwość uruchomienia (może zostać uruchomiony, ale planista nie wybrał go jeszcze do uruchomienia).
- Zielony. Aktywnie działający (planista uważa, że jest aktywny).
- Czerwony. Nieprzerwany sen (zwykle w trybie blokady w rdzeniu). Może wskazywać obciążenie wejść/wyjść. Jest to bardzo przydatne podczas debugowania problemów z wydajnością.
- Pomarańczowy. Nieprzerwany sen z powodu obciążenia wejść/wyjść.
Aby wyświetlić powód nieprzerwanego snu (dostępny w punkcie śledzenia sched_blocked_reason), wybierz czerwony wycinek nieprzerwanego snu.
Gdy działa EventThread, staje się możliwy do uruchomienia wątek interfejsu użytkownika TouchLatency. Aby zobaczyć, co je wywołało, kliknij niebieski obszar.
Rysunek 2 pokazuje, że wątek interfejsu użytkownika TouchLatency został wybudzony przez identyfikator tid 6843, który odpowiada wątkowi EventThread. Wątek interfejsu użytkownika się budzi, renderuje ramkę i wstawia ją do kolejki do wykorzystania przez SurfaceFlinger.
Jeśli w śladzie jest włączony tag binder_driver, możesz wybrać transakcję bindera, aby wyświetlić informacje o wszystkich procesach związanych z tą transakcją.
Rysunek 4 pokazuje, że w miejscu 15 423,65 ms Binder:6832_1 w SurfaceFlinger staje się możliwy do uruchomienia z powodu identyfikatora tid 9579, który jest wątkiem renderowania TouchLatency. Możesz też zobaczyć kolejkę buforów po obu stronach transakcji binder.
Podczas kolejkowania bufora po stronie SurfaceFlinger liczba oczekujących ramek z TouchLatency zmienia się z 1 na 2.
Rysunek 5 przedstawia potrójne buforowanie, w którym są 2 ukończone klatki, a aplikacja ma zacząć renderowanie trzeciej. Dzieje się tak, ponieważ niektóre klatki zostały już utracone, więc aplikacja przechowuje 2 oczekujące klatki zamiast 1, aby uniknąć utraty kolejnych klatek.
Wkrótce wątek główny SurfaceFlingera jest aktywowany przez drugi wątek zdarzenia, aby mógł wyświetlić na ekranie starsze oczekujące klatki:
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 ostatnią ramkę do wyświetlacza. (niektóre z tych sekcji są włączone w ramach punktu śledzenia mdss, więc mogą nie być uwzględnione w Twoim SoC).
Następnie mdss_fb0 budzi się na procesorze 0. mdss_fb0 to wątek jądra w pipeline wyświetlania, który służy do przesyłania wyrenderowanej klatki do wyświetlacza.
W pliku śladu widać wiersz mdss_fb0 (przewiń w dół, aby go wyświetlić).
mdss_fb0 budzi się, krótko działa, przechodzi w tryb nieprzerwanego snu, a potem budzi się ponownie.
Przykład: niedziałający element
Ten przykład opisuje ślad systemowy używany do debugowania jittera na urządzeniach Pixel i Pixel XL. Aby wykonać ten przykład, pobierz plik ZIP z śladami (zawiera on inne ślady wymienione w tym rozdziale), rozpakuj go i otwórz plik systrace_tutorial.html w przeglądarce.
Po otwarciu pliku systrace zobaczysz coś takiego:
Aby sprawdzić, czy występuje zjawisko jank, sprawdź wiersz FrameMissed w sekcji SurfaceFlinger.
FrameMissed to ulepszenie jakości życia, które zapewnia HWC2. Gdy wyświetlasz systrace na innych urządzeniach, wiersz FrameMissed może być nieobecny, jeśli urządzenie nie używa HWC2. W obu przypadkach wartość FrameMissed jest skorelowana z brakiem jednego z bardzo regularnych czasów wykonywania w SurfaceFlinger i niezmienioną liczbą oczekujących buforów aplikacji (com.prefabulated.touchlatency) w ramach synchronizacji pionowej.
Rysunek 11 przedstawia pominiętą klatkę w 15598,29 ms. SurfaceFlinger krótko obudził się w interwale vsync i powrócił do stanu uśpienia bez wykonania żadnej operacji, co oznacza, że SurfaceFlinger uznał, że nie warto ponownie wysyłać klatki do wyświetlacza. Dlaczego?
Aby zrozumieć, jak łańcuch przetwarzania został podzielony w przypadku tej klatki, najpierw zapoznaj się z przykładem działającej klatki powyżej, aby zobaczyć, jak zwykły łańcuch przetwarzania interfejsu użytkownika wygląda w systrace. Gdy będziesz gotowy, wróć do pominiętej klatki i pracuj wstecz. Zauważ, że SurfaceFlinger budzi się i natychmiast przechodzi w stan uśpienia. Gdy wyświetlasz liczbę oczekujących klatek z TouchLatency, widzisz 2 klatki (to dobry trop, który pomoże Ci zrozumieć, co się dzieje).
Ponieważ mamy ramki w SurfaceFlinger, nie jest to problem aplikacji. Dodatkowo SurfaceFlinger uruchamia się we właściwym czasie, więc problem nie dotyczy tej aplikacji. Jeśli aplikacja SurfaceFlinger i aplikacja, z której korzystasz, działają normalnie, problem prawdopodobnie dotyczy sterownika.
Dzięki włączonym punktom śledzenia mdss i sync możemy uzyskać informacje o fence’ach (udostępnianych przez sterownik wyświetlacza i SurfaceFlinger), które kontrolują, kiedy ramki są przesyłane do wyświetlacza.
Te ograniczenia są wymienione w sekcji mdss_fb0_retire, która wskazuje, kiedy dany kadr jest wyświetlany. Te ogrodzenia są dostępne w ramach kategorii sync ścieżek. Które ogrodzenia odpowiadają konkretnym zdarzeniom w SurfaceFlinger zależy od SOC i sterownika, dlatego współpracuj z dostawcą SOC, aby poznać znaczenie kategorii ogrodzeń w śladach.
Rysunek 13 przedstawia kadr, który był wyświetlany przez 33 ms, a nie 16,7 ms, jak należało. W połowie tego fragmentu kadr powinien zostać zastąpiony nowym, ale tak się nie stało. Wyświetl poprzednią klatkę i sprawdź, czy zawiera ona coś interesującego.
Rysunek 14 przedstawia 14,482 ms na klatkę. Uszkodzony segment 2 klatek trwał 33,6 ms, co jest zbliżone do oczekiwanego czasu renderowania 2 klatek (renderujemy z częstotliwością 60 Hz, czyli 16,7 ms na klatkę, co jest zbliżone do oczekiwanego czasu). Jednak 14,482 ms to nie 16,7 ms, co oznacza, że coś jest nie tak z kanałem wyświetlania.
Sprawdź, gdzie dokładnie kończy się ogrodzenie, aby określić, co je kontroluje.
kolejka zadań zawiera element __vsync_retire_work_handler, który jest wykonywany, gdy zmienia się krata. W źródle jądra widać, że jest to część sterownika wyświetlacza. Wygląda na to, że znajduje się on na ścieżce krytycznej dla potoku reklamowego, więc musi być wykonywany tak szybko, jak to możliwe. Może być wykonywany przez około 70 μs (nie jest to długi czas opóźnienia), ale jest to praca w kolejce i może nie zostać zaplanowana dokładnie.
Sprawdź poprzednią ramkę, aby ustalić, czy to ona jest przyczyną problemu. Czasami jitter może się kumulować z czasem i ostatecznie spowodować przekroczenie terminu.
Linia wykonalna w kworkerze nie jest widoczna, ponieważ po wybraniu staje się biała, ale statystyki mówią wszystko: 2,3 ms opóźnienia w planowaniu w przypadku części ścieżki krytycznej w pipeline wyświetlania to zły wynik.
Zanim przejdziesz dalej, napraw opóźnienie, przenosząc tę część ścieżki krytycznej przepływu danych wyświetlania z kolejki zadań (która działa jako wątek SCHED_OTHER CFS) do dedykowanego wątku SCHED_FIFOk. Ta funkcja wymaga gwarancji czasowych, których kolejki zadań nie mogą (i nie są przeznaczone do) zapewniania.
Czy to jest przyczyną problemów? Trudno to jednoznacznie stwierdzić. Poza łatwymi do zdiagnozowania przypadkami, takimi jak rywalizacja o blokadę jądra powodująca uśpienie wątków krytycznych dla wyświetlania, ścieżki zwykle nie wskazują problemu. Czy to drżenie mogło być przyczyną utraty klatki? Oczywiście. Czasy bariery powinny wynosić 16,7 ms, ale w przypadku klatek poprzedzających utratę klatki są one znacznie wyższe. Ze względu na ścisłe powiązanie ścieżki wyświetlania możliwe, że drżenie w okolicach czasów granicznych spowodowało utratę klatki.
W tym przykładzie rozwiązanie polegało na przekształceniu funkcji __vsync_retire_work_handler z workqueue na dedicated_kthread. W efekcie udało się znacznie zmniejszyć jitter i zaburzenia w teście z kulą odbijającą się. Kolejne ścieżki pokazują czasy działania ogrodzenia, które są bardzo zbliżone do 16,7 ms.