Korzystanie z ftrace

ftrace to narzędzie do debugowania, które pozwala zrozumieć, co dzieje się w jądrze Linuksa. Poniższe sekcje szczegółowo opisują podstawową funkcjonalność ftrace, użycie ftrace z atrace (który przechwytuje zdarzenia jądra) i dynamiczny ftrace.

Szczegółowe informacje na temat zaawansowanych funkcji ftrace, które nie są dostępne w systrace, można znaleźć w dokumentacji ftrace w <kernel tree>/Documentation/trace/ftrace.txt .

Przechwytywanie zdarzeń jądra za pomocą atrace

atrace ( frameworks/native/cmds/atrace ) używa ftrace do przechwytywania zdarzeń jądra. Z kolei systrace.py (lub run_systrace.py w późniejszych wersjach Catapult ) używa adb do uruchomienia atrace na urządzeniu. atrace wykonuje następujące czynności:

• Konfiguruje śledzenie w trybie użytkownika, ustawiając właściwość ( debug.atrace.tags.enableflags ).
• Włącza żądaną funkcjonalność ftrace poprzez zapisanie w odpowiednich węzłach ftrace sysfs. Jednakże, ponieważ ftrace obsługuje więcej funkcji, możesz samodzielnie ustawić niektóre węzły sysfs, a następnie użyć atrace.

Z wyjątkiem śledzenia czasu rozruchu, polegaj na użyciu atrace w celu ustawienia właściwości na odpowiednią wartość. Właściwość jest maską bitową i nie ma dobrego sposobu na określenie poprawnych wartości w inny sposób niż sprawdzenie odpowiedniego nagłówka (który może się zmieniać w zależności od wersji Androida).

Włączanie zdarzeń ftrace

Węzły ftrace sysfs znajdują się w /sys/kernel/tracing , a zdarzenia śledzenia są podzielone na kategorie w /sys/kernel/tracing/events .

Aby włączyć zdarzenia dla poszczególnych kategorii, użyj:

echo 1 > /sys/kernel/tracing/events/irq/enable

Aby włączyć zdarzenia dla poszczególnych zdarzeń, użyj:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Jeśli dodatkowe zdarzenia zostały włączone poprzez zapis do węzłów sysfs, nie zostaną one zresetowane przez atrace. Typowym wzorcem uruchamiania urządzenia Qualcomm jest włączenie punktów śledzenia kgsl (GPU) i mdss (potok wyświetlania), a następnie użycie atrace lub systrace :

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Możesz także użyć ftrace bez atrace lub systrace, co jest przydatne, gdy chcesz śledzić tylko jądro (lub jeśli poświęciłeś czas na ręczne napisanie właściwości śledzenia w trybie użytkownika). Aby uruchomić po prostu ftrace:

1. Ustaw rozmiar bufora na wartość wystarczająco dużą dla Twojego śledzenia:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. Włącz śledzenie:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. Uruchom test, a następnie wyłącz śledzenie:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. Zrzuć ślad:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
   

Trace_output daje ślad w formie tekstowej. Aby to zwizualizować za pomocą Catapult, pobierz repozytorium Catapult z GitHub i uruchom trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

Domyślnie zapisuje plik trace_file.html w tym samym katalogu.

Powiązanie wydarzeń

Często przydatne jest jednoczesne spojrzenie na wizualizację Katapulty i dziennik śledzenia; na przykład niektóre zdarzenia ftrace (szczególnie te specyficzne dla dostawcy) nie są wizualizowane przez Catapult. Jednak znaczniki czasu Catapult są względne albo w stosunku do pierwszego zdarzenia w śladzie, albo do określonego znacznika czasu zrzuconego przez atrace, podczas gdy surowe znaczniki czasu ftrace są oparte na konkretnym źródle zegara bezwzględnego w jądrze Linuksa.

Aby znaleźć dane zdarzenie ftrace na podstawie zdarzenia katapulty:

1. Otwórz surowy dziennik ftrace. Ślady w najnowszych wersjach systrace są domyślnie kompresowane:
   • Jeśli przechwyciłeś systrace za pomocą --no-compress , znajduje się to w pliku HTML w sekcji zaczynającej się od BEGIN TRACE.
   • Jeśli nie, uruchom html2trace z drzewa Catapult ( tracing/bin/html2trace ), aby zdekompresować ślad.
2. Znajdź względny znacznik czasu w wizualizacji katapulty.
3. Znajdź linię na początku śledzenia zawierającą tracing_mark_sync . Powinno to wyglądać mniej więcej tak:

   <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
   

   
   Jeśli ta linia nie istnieje (lub jeśli użyłeś ftrace bez atrace), czasy będą względne w stosunku do pierwszego zdarzenia w dzienniku ftrace.
   1. Dodaj względny znacznik czasu (w milisekundach) do wartości w parent_ts (w sekundach).
   2. Wyszukaj nowy znacznik czasu.

Poniższe kroki powinny przybliżyć Cię do wydarzenia (lub przynajmniej bardzo blisko niego).

Korzystanie z dynamicznego ftrace

Gdy systrace i standardowy ftrace nie wystarczą, pozostaje jeszcze jedno rozwiązanie: dynamic ftrace . Dynamiczny ftrace polega na przepisaniu kodu jądra po uruchomieniu, w wyniku czego nie jest on dostępny w jądrach produkcyjnych ze względów bezpieczeństwa. Jednak każdy trudny błąd wydajności w latach 2015 i 2016 był ostatecznie spowodowany przez roota przy użyciu dynamicznego ftrace. Jest szczególnie przydatny do debugowania nieprzerwanego uśpienia, ponieważ możesz uzyskać ślad stosu w jądrze za każdym razem, gdy naciśniesz funkcję wyzwalającą nieprzerwany sen. Możesz także debugować sekcje z wyłączonymi przerwaniami i wywłaszczeniami, co może być bardzo przydatne przy udowadnianiu problemów.

Aby włączyć dynamiczny ftrace, edytuj defconfig jądra:

1. Usuń CONFIG_STRICT_MEMORY_RWX (jeśli jest obecny). Jeśli masz wersję 3.18 lub nowszą i masz arm64, nie ma jej tam.
2. Dodaj następujące elementy: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y i CONFIG_PREEMPT_TRACER=y
3. Odbuduj i uruchom nowe jądro.
4. Uruchom następujące polecenie, aby sprawdzić dostępne znaczniki:

   cat /sys/kernel/tracing/available_tracers
   

5. Potwierdź, że polecenie zwraca function , irqsoff , preemptoff i preemptirqsoff .
6. Uruchom następujące polecenie, aby upewnić się, że dynamiczny ftrace działa:

   cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
   

Po wykonaniu tych kroków będziesz mieć do dyspozycji dynamiczny ftrace, profiler funkcji, profiler irqsoff i profiler wywłaszczania. Zdecydowanie zalecamy przeczytanie dokumentacji ftrace na te tematy przed ich użyciem, ponieważ są one potężne, ale złożone. irqsoff i preemptoff są przede wszystkim przydatne do sprawdzania, czy sterowniki mogą pozostawiać przerwania lub wywłaszczanie wyłączone na zbyt długo.

Profiler funkcji jest najlepszą opcją w przypadku problemów z wydajnością i często jest używany do sprawdzenia, gdzie funkcja jest wywoływana.

Pokaż Problem: zdjęcie HDR + obrotowy wizjer

W tym przypadku użycie Pixela XL do zrobienia zdjęcia HDR+ i natychmiastowe obrócenie wizjera powodowało szarpnięcie za każdym razem. Użyliśmy profilera funkcji, aby rozwiązać problem w czasie krótszym niż godzina. Aby postępować zgodnie z przykładem, pobierz plik ZIP zawierający ślady (który zawiera także inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz w przeglądarce plik trace_30898724.html.

Ślad pokazuje kilka wątków w procesie serwera kamery zablokowanych w trybie nieprzerwanego uśpienia na ion_client_destroy . Jest to kosztowna funkcja, ale powinna być wywoływana bardzo rzadko, ponieważ klienci jonowi powinni obejmować wiele alokacji. Początkowo wina spadła na kod Hexagon w Halide, który rzeczywiście był jednym z winowajców (tworzył nowego klienta dla każdej alokacji jonów i niszczył tego klienta, gdy alokacja została zwolniona, co było zdecydowanie za drogie). Przejście na jednego klienta jonowego dla wszystkich przydziałów Hexagonu poprawiło sytuację, ale problem nie został naprawiony.

W tym momencie musimy wiedzieć, kto wywołuje ion_client_destroy , więc czas skorzystać z profilera funkcji:

1. Ponieważ kompilator czasami zmienia nazwy funkcji, potwierdź, że ion_client_destroy istnieje, używając:

   cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
   

2. Po potwierdzeniu, że tam jest, użyj go jako filtra ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. Włącz profiler funkcji:

   echo function > /sys/kernel/tracing/current_tracer
   

4. Włącz śledzenie stosu za każdym razem, gdy wywoływana jest funkcja filtrująca:

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. Zwiększ rozmiar bufora:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. Włącz śledzenie:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. Uruchom test i uzyskaj ślad:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace
   

8. Wyświetl ślad, aby zobaczyć mnóstwo śladów stosu:

       cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
       cameraserver-643   [003] ...1    94.192997: <stack trace>
    => ftrace_ops_no_ops
    => ftrace_graph_call
    => ion_client_destroy
    => ion_release
    => __fput
    => ____fput
    => task_work_run
    => do_notify_resume
    => work_pending
    

Na podstawie inspekcji sterownika ion widzimy, że ion_client_destroy jest spamowany przez funkcję przestrzeni użytkownika zamykającą fd na /dev/ion , a nie przez przypadkowy sterownik jądra. Przeszukując bazę kodu Androida pod kątem \"/dev/ion\" , znajdujemy sterowniki kilku dostawców, które robią to samo, co sterownik Hexagon i otwierają/zamykają /dev/ion (tworząc i niszcząc nowego klienta ion) za każdym razem, gdy potrzebują nowy przydział jonów. Zmiana tych, aby korzystali z jednego klienta jonowego przez cały czas trwania procesu, naprawiła błąd.

---

Jeśli dane z profilera funkcji nie są wystarczająco szczegółowe, możesz połączyć punkty śledzenia ftrace z profilerem funkcji. Zdarzenia ftrace można włączyć dokładnie w taki sam sposób jak zwykle i będą one przeplatane z Twoim śledzeniem. Jest to świetne rozwiązanie, jeśli od czasu do czasu występuje długi, nieprzerwany sen w określonej funkcji, którą chcesz debugować: ustaw filtr ftrace na żądaną funkcję, włącz punkty śledzenia, wykonaj śledzenie. Możesz przeanalizować wynikowy ślad za pomocą trace2html , znaleźć żądane zdarzenie, a następnie uzyskać pobliskie ślady stosu w nieprzetworzonym śladzie.

Korzystanie z lockstatu

Czasami ftrace nie wystarczy i naprawdę trzeba debugować coś, co wydaje się być rywalizacją o blokadę jądra. Warto wypróbować jeszcze jedną opcję jądra: CONFIG_LOCK_STAT . To ostateczność, ponieważ niezwykle trudno jest uruchomić system na urządzeniach z Androidem, ponieważ zwiększa to rozmiar jądra ponad możliwości większości urządzeń.

Jednak lockstat korzysta z infrastruktury blokowania debugowania, która jest przydatna w wielu innych aplikacjach. Każdy, kto pracuje nad konfiguracją urządzenia, powinien znaleźć sposób, aby ta opcja działała na każdym urządzeniu, ponieważ nadejdzie czas, gdy pomyślisz: „Gdybym tylko mógł włączyć LOCK_STAT , mógłbym potwierdzić lub odrzucić to jako problem w ciągu pięciu minut zamiast pięć dni."

Pokaż problem: Blokada w SCHED_FIFO, gdy rdzenie są przy maksymalnym obciążeniu przy użyciu systemu innego niż SCHED_FIFO

W tym problemie wątek SCHED_FIFO zatrzymał się, gdy wszystkie rdzenie były przy maksymalnym obciążeniu wątkami innymi niż SCHED_FIFO. Mieliśmy ślady wskazujące na znaczną rywalizację o blokady na fd w aplikacjach VR, ale nie mogliśmy łatwo zidentyfikować używanego fd. Aby postępować zgodnie z przykładem, pobierz plik ZIP zawierający ślady (który zawiera także inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz w przeglądarce plik trace_30905547.html.

Postawiliśmy hipotezę, że źródłem rywalizacji o blokady był sam ftrace, gdy wątek o niskim priorytecie zaczynał pisać do potoku ftrace, a następnie został wywłaszczony, zanim mógł zwolnić blokadę. Jest to najgorszy scenariusz, który został zaostrzony przez połączenie wątków o bardzo niskim priorytecie zapisujących do znacznika ftrace wraz z pewnymi wątkami o wyższym priorytecie obracającymi się na procesorach, aby symulować całkowicie załadowane urządzenie.

Ponieważ nie mogliśmy używać ftrace do debugowania, uruchomiliśmy LOCK_STAT , a następnie wyłączyliśmy wszystkie inne śledzenie z aplikacji. Wyniki pokazały, że rywalizacja o blokadę faktycznie pochodziła z ftrace, ponieważ żadna rywalizacja nie pojawiła się w śladzie blokady, gdy ftrace nie było uruchomione.

---

Jeśli możesz uruchomić jądro za pomocą opcji konfiguracyjnej, śledzenie blokad jest podobne do ftrace:

1. Włącz śledzenie:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. Uruchom test.
3. Wyłącz śledzenie:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. Zrzuć swój ślad:

   cat /proc/lock_stat > /data/local/tmp/lock_stat
   

Aby uzyskać pomoc w interpretacji wynikowego wyniku, zapoznaj się z dokumentacją lockstat w <kernel>/Documentation/locking/lockstat.txt .

Korzystanie z punktów śledzenia dostawcy

Najpierw użyj wcześniejszych punktów śledzenia, ale czasami będziesz musiał użyć punktów śledzenia dostawcy:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Punkty śledzenia można rozszerzyć za pomocą usługi HAL, co pozwala na dodawanie punktów/kategorii śledzenia specyficznych dla urządzenia. Punkty Tracepoints są zintegrowane z perfetto, atrace/systrace i aplikacją do śledzenia systemu na urządzeniu.

Interfejsy API służące do implementowania punktów/kategorii śledzenia to:

• listCategories() generuje (kategorie vec<TracingCategory>);
• EnableCategories(vec<string> kategorie) generuje (status stanu);
• disableAllCategories() generuje (status stanu);

Aby uzyskać więcej informacji, zapoznaj się z definicją HAL i domyślną implementacją w AOSP :