Użyj ftrace

ftrace to narzędzie do debugowania, które pozwala zrozumieć, co dzieje się Jądro systemu Linux. W poniższych sekcjach opisano podstawową funkcję stóp (ftrace) użycie z atrace (które przechwytuje zdarzenia jądra) i dynamicznym ftrace.

Szczegółowe informacje o zaawansowanych funkcjach śledzenia, które nie są dostępne na systrace, zapoznaj się z dokumentacją ftrace pod adresem <kernel tree>/Documentation/trace/ftrace.txt

Przechwytywanie zdarzeń jądra za pomocą atrace

atrace (frameworks/native/cmds/atrace) używa ftrace do przechwytywania zdarzenia jądra systemu operacyjnego. Z kolei plik systrace.py (lub run_systrace.py w nowszych wersjach Catapult) używa narzędzia adb aby biegać na urządzeniu. atrace wykonuje te działania:

  • Konfiguruje śledzenie w trybie użytkownika przez ustawienie usługi (debug.atrace.tags.enableflags).
  • Włącza żądaną funkcję śledzenia, zapisując w odpowiednim węzłów ftrace sysfs. Ftrace obsługuje jednak więcej funkcji, więc możesz ustawić samodzielnie używasz niektórych węzłów sysfs, a następnie używaj atrace.

Z wyjątkiem śledzenia czasu uruchamiania korzystaj z atrybutu atrace, aby ustawić do odpowiedniej wartości. Właściwość to maska bitowa i nie ma dobrej określania prawidłowych wartości poza sprawdzaniem odpowiedniego nagłówka. (co może się zmieniać w zależności od wersji Androida).

Włącz zdarzenia ftrace

Węzły ftrace sysfs są w /sys/kernel/tracing i logu czasu wydarzenia są podzielone na kategorie w kategorii /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 przez zapis w węzłach sysfs, zostaną nie może być resetowany przez atrace. Wspólny wzorzec dla wyświetlenia urządzenia Qualcomm jest włączenie kgsl (GPU) i mdss (potok wyświetlania), a następnie użyj parametru 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 też użyć ftrace bez atrace i systrace, które jest przydatne, gdy chcesz korzystać z logów czasu tylko dla jądra (lub jeśli poświęcisz czas na ręcznie korzystając z właściwości śledzenia w trybie użytkownika). Aby biegać prosto:

  1. Ustaw rozmiar bufora na wartość wystarczająco dużą dla logu czasu: 
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
  2. Włącz śledzenie: 
    echo 1 > /sys/kernel/tracing/tracing_on
  3. Przeprowadź 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

Parametr Tras_output daje ślad tekstowy w postaci tekstowej. Aby zwizualizować to za pomocą Katapulta, zdobądź Katapulta z GitHub i uruchom tag track2html:

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

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

Skoreluj zdarzenia

Często warto spojrzeć na wizualizację Katapulta i ft zapisywać jednocześnie; np. niektóre zdarzenia statystyczne (zwłaszcza związane z danym dostawcą, tych) nie są wizualizowane przez Catapult. Sygnatury czasowe Catapulta są jednak względem pierwszego zdarzenia w logu czasu lub konkretnej sygnatury czasowej są dodawane przez parametr atrace, a nieprzetworzone sygnatury czasowe stopy są oparte na konkretnym z zegarem bezwzględnym w jądrze Linuksa.

Aby znaleźć dane zdarzenie ftrace z wydarzenia Catapult:

  1. Otwórz dziennik nieprzetworzonych danych Firebase. Ślady w ostatnich wersjach systrace to domyślnie skompresowane:
    • Jeśli zapisałaś systrace za pomocą --no-compress, jest to w: pliku html w sekcji rozpoczynającej się od tagu „POCZĄTEK TRACE”.
    • Jeśli tak nie jest, uruchom narzędzie html2trace ze źródła Katapulta drzewo (tracing/bin/html2trace), by zdekompresować log czasu.
  2. Znajdź względną sygnaturę czasową w wizualizacji Catapult.
  3. Znajdź wiersz na początku logu czasu zawierającego tracing_mark_sync Powinien 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żyto parametru ftrace bez atrybutu atrace), czasy będą względne względem pierwszego zdarzenia w logu testowym.
    1. Dodaj względną sygnaturę czasową (w milisekundach) do wartości w parent_ts (w sekundach).
    2. Wyszukaj nową sygnaturę czasową.

Te czynności powinny sprawić, że znajdziesz się w wydarzeniu (lub przynajmniej w jego pobliżu).

Używanie dynamicznych stoperów

Gdy systrace i stopnie standardowe są niewystarczające, istnieje jeszcze dostępne odwołanie: dynamic ftrace. Dynamiczny ruch obejmuje przepisywanie kodu jądra po uruchomieniu, przez co nie jest on dostępny w środowisku produkcyjnym przez jądra systemu operacyjnego. Każdy trudny błąd w działaniu Rok 2015 i 2016 został ostatecznie zakłócony przy użyciu dynamicznych ścieżek. Szczególnie ważne jest, bardzo przydatne do debugowania uśpień niewyrażonych, ponieważ możesz uzyskać zrzut stosu w jądrze po każdym uruchomieniu funkcji aktywującej nieprzerwany sen. Możesz też debugować sekcje z wyłączonymi przerwami i wywłaszczeniem, co może może być bardzo przydatna przy weryfikowaniu problemów.

Aby włączyć dynamiczne ftrace, zmodyfikuj plik defconfig jądra:

  1. Usuń plik CONFIG_STRICT_MEMORY_RWX (jeśli jest dostępny). Jeśli używasz 3.18 lub nowszego i arm64, tego nie ma.
  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 to polecenie, aby sprawdzić dostępne trackery: 
    cat /sys/kernel/tracing/available_tracers
  5. Potwierdź, że polecenie zwraca function, irqsoff, preemptoff i preemptirqsoff.
  6. Uruchom to polecenie, aby upewnić się, że ścieżka dynamiczna działa: 
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>

Po wykonaniu tych czynności uzyskasz dynamiczne ftrace, program profilujący funkcji, oraz narzędzie do profilowania irqsoff i profilowanie z wyprzedzeniem. Zdecydowanie zdecydowanie zalecamy zapoznanie się z dokumentacją dotyczącą tych tematów ponieważ są zaawansowane, ale złożone. irqsoff i zapobiegawcze przydatne do potwierdzenia, że kierowcy mogą przerywać pracę Wyłączona zbyt długo.

Narzędzie do profilowania funkcji to najlepsza opcja w przypadku problemów z wydajnością. służy do ustalenia miejsca wywołania funkcji.

W tym przypadku zrób zdjęcie HDR+ Pixelem XL, a potem od razu obracanie wizjera za każdym razem powodowało zacinanie. Za pomocą programu profilującego funkcji na debugowanie problemu w niecałą godzinę. Korzystając z przykładu: pobierz plik zip ze logami czasu (który jest również zawiera inne ślady, o których mowa w tej sekcji), rozpakuj plik i otwórz track_30898724.html w przeglądarce.

Śledzenie pokazuje kilka wątków w procesie Cameraserver zablokowanych w nieprzerwany sen ion_client_destroy. To jest drogie funkcji, ale należy ją wywoływać bardzo rzadko, ponieważ klienty jonów powinny obejmują wiele przydziałów. Początkowo wina spoczywała na sześciokątnym kodzie Halide, która doprowadziła do powstania nowego klienta dla każdego przydzielanie jonów i zniszczył tego klienta po zwolnieniu alokacji, co było o wiele za drogie). Przejście na jeden klient jonów dla wszystkich sześciokątów alokacje rozwiązały problem, ale problem nie został rozwiązany.

W tej chwili musimy wiedzieć, kto dzwoni pod numer ion_client_destroy, więc pora użyć programu profilującego funkcji:

  1. Kompilator zmienia czasem nazwy funkcji, więc sprawdź, ion_client_destroy jest dostępne za pomocą: 
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
  2. Gdy potwierdzisz jej obecność, użyj jej jako filtra Ftrace: 
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
  3. Włącz program profilujący funkcji: 
    echo function > /sys/kernel/tracing/current_tracer
  4. Zrzut stosu włącza się za każdym razem, gdy wywoływana jest funkcja filtra: 
    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 pobierz log czasu: 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Wyświetl ślad, aby zobaczyć wiele zrzutó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 jonu stwierdziliśmy, że Zamknięcie funkcji przestrzeni użytkownika powoduje spamowanie witryny ion_client_destroy wartość fd do /dev/ion, a nie losowy sterownik jądra systemu operacyjnego. Wyszukując w Baza kodu Androida dla aplikacji \"/dev/ion\", znaleźliśmy kilka sterowników dostawców robimy to samo co wkręt sześciokąta i otwieram/zamykam /dev/ion (tworzenie i zniszczenie nowego klienta jonu) za każdym razem, potrzebują nowego przydziału jonów. Zmiana ich na użyj tylko jeden klient jonowy w całym cyklu życia błędu.

Jeśli dane z narzędzia do profilowania funkcji nie są wystarczająco szczegółowe, możesz połączyć ftrace logpoints za pomocą narzędzia do profilowania funkcji. zdarzenia ftrace można włączyć w: dokładnie tak samo jak zwykle i zostaną przeplatane z Twoim logiem czasu. To świetne rozwiązanie, jeśli o danej porze sen sporadycznie się zdarza. funkcja, którą chcesz debugować: ustaw filtr ftrace na wybraną funkcję, włącz śledzenie punktów, rozpocznij ślad. Otrzymany log czasu możesz przeanalizować za pomocą trace2html, znajdź interesujące Cię zdarzenie i uzyskaj zrzuty stosu w pobliżu w nieprzetworzonym logu czasu.

Użyj metody Lockstat

Czasami parametr Ftrace nie wystarcza i koniecznie trzeba debugować, rywalizację o blokadę jądra systemu operacyjnego. Jest jeszcze jedna opcja jądra, którą warto wypróbować: CONFIG_LOCK_STAT To ostateczna sytuacja, ponieważ praca na urządzeniach z Androidem powoduje zwiększenie rozmiaru ekranu. jądra systemu operacyjnego wykracza poza to, co obsługuje większość urządzeń.

Parametr Lockstat korzysta jednak z funkcji debugowania infrastrukturą blokującą, co przydaje się w wielu innych aplikacjach. Wszyscy podczas otwierania urządzenia powinno znaleźć sposób na uruchomienie tej opcji na każdym urządzeniu, ponieważ przyejdzie czas, gdy zaczniesz się zastanawiać, „Gdybym tylko mogła włączyć usługę LOCK_STAT, mogłabym to potwierdzić lub odrzucić jako źródło problemu w 5 minut, a nie w 5 dni”.

W tym problemie wątek SCHED_FIFO zawiesił się, gdy wszystkie rdzenie miały maksymalną liczbę rdzeni. jest wczytywany z wątkami innymi niż SCHED_FIFO. Mieliśmy ślady wskazujące na znaczną blokadę dotyczące fd w aplikacjach VR, ale nie udało nam się łatwo zidentyfikować fd używanego. Aby podążać za przykładem, pobierz plik ZIP ze śladami (który zawiera też inne ślady wymienione w tym artykule ), rozpakuj plik i otwórz plik track_30905547.html w przeglądarce.

Ustaliliśmy, że samo ftrace było źródłem rywalizacji o blokady, wątek o niskim priorytecie zacznie zapisywać dane do potoku ftrace, a następnie zostanie został uprzedzony, zanim zdążył usunąć blokadę. To najgorszy przypadek, pogorszyło się przez połączenie bardzo niskich wątków, które wysyłały wiadomości wraz ze znacznikiem ftrace, które działają na procesorach, symulację w pełni załadowanego urządzenia.

Ponieważ nie udało się przeprowadzić debugowania za pomocą Ftrace, udało się uruchomić LOCK_STAT a potem wyłącz wszystkie inne śledzenie w aplikacji. Wyniki pokazują, że ikona blokady spór wynikał z ftrace, ponieważ żaden z nich nie pojawił się śledzenie blokady, gdy aplikacja ftrace nie była uruchomiona.

Jeśli możesz uruchomić jądro z opcją konfiguracji, śledzenie blokady jest podobne do ftrace:

  1. Włącz śledzenie: 
    echo 1 > /proc/sys/kernel/lock_stat
  2. Przeprowadź test.
  3. Wyłącz śledzenie: 
    echo 0 > /proc/sys/kernel/lock_stat
  4. Zrzut logu czasu: 
    cat /proc/lock_stat > /data/local/tmp/lock_stat

Pomoc w interpretacji wynikowych danych wyjściowych znajdziesz w dokumentacji narzędzia Lockstat. na stronie <kernel>/Documentation/locking/lockstat.txt.

Użyj punktów śledzenia dostawcy

Najpierw użyj punktów śledzenia z góry, ale czasami trzeba też 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 rozszerzać przez usługę HAL, co pozwala dodawać log czasu dla konkretnego urządzenia punktów/kategorii. Punkty śledzenia są zintegrowane z systemami perfetto, atrace/systrace i systemem na urządzeniu. do śledzenia aktywności.

Interfejsy API do implementacji punktów śledzenia/kategorii:

  • listCategory()generates (vec<TrackingCategory> );
  • enabledKategorie(vec<string> categories) generate (Status status);
  • offAllCategory() generuje (Stan).
. Więcej informacji znajdziesz w definicji HAL i domyślnej implementacji w AOSP: