Zbiorcza analiza logów czasu oczekiwania

Gdy zbierzesz wiele logów czasu za pomocą ProfilingManager, analizowanie ich pojedynczo w celu znalezienia problemów z wydajnością staje się niepraktyczne. Analiza logów czasu zbiorczo umożliwia jednoczesne wysyłanie zapytań do zbioru danych logów czasu w celu:

• identyfikować typowe regresje wydajności;
• obliczać rozkłady statystyczne (np. czas oczekiwania p50, p90, p99);
• znajdować wzorce w kilku logach czasu,
• Znajdź ślady odstające, aby zrozumieć i debugować problemy z wydajnością.

W tej sekcji pokazujemy, jak używać procesora Perfetto Python Batch Trace Processor do analizowania danych o uruchamianiu w zbiorze śladów przechowywanych lokalnie i znajdowania śladów odstających w celu przeprowadzenia dokładniejszej analizy.

Projektowanie zapytania

Najpierw utwórz zapytanie PerfettoSQL, które wyodrębnia dane, które chcesz porównać. W przykładzie poniżej mierzymy czas rozpoczęcia kontrolowany przez aplikację od activityStart do pierwszej wyrenderowanej klatki (Choreographer#doFrame), jak pokazano na rysunku 1.

Uwaga: przed uruchomieniem zapytania zbiorczego przetestuj je na pojedynczym śladzie w interfejsie Perfetto, aby sprawdzić wyniki.

Rysunek 1. Sekcja śledzenia od activityStart do pierwszej wygenerowanej klatki.

CREATE OR REPLACE PERFETTO FUNCTION find_slices(pattern STRING) RETURNS
TABLE (name STRING, ts LONG, dur LONG) AS
SELECT name,ts,dur FROM slice WHERE name GLOB $pattern;

CREATE OR REPLACE PERFETTO FUNCTION generate_start_to_end_slices(startSlicePattern STRING, endSlicePattern STRING, inclusive BOOL) RETURNS
TABLE(name STRING, ts LONG, dur LONG) AS
SELECT name, ts, MIN(startToEndDur) as dur
FROM
  (SELECT S.name as name, S.ts as ts, E.ts + IIF($inclusive, E.dur, 0) - S.ts as startToEndDur
  FROM find_slices($startSlicePattern) as S CROSS JOIN find_slices($endSlicePattern) as E
  WHERE startToEndDur > 0)
GROUP BY name, ts;

SELECT ts,name,dur from generate_start_to_end_slices('activityStart','*Choreographer#doFrame [0-9]*', true)

Możesz wykonać zapytanie w interfejsie Perfetto, a następnie użyć wyników zapytania do wygenerowania ścieżki debugowania (rysunek 2) i zwizualizowania jej na osi czasu (rysunek 3).

Rysunek 2. Utwórz ścieżkę debugowania dla zapytania startowego.

Rysunek 3. Wygenerowano ścieżkę debugowania dla zapytania dotyczącego uruchamiania.

Konfigurowanie środowiska Pythona

Zainstaluj Pythona na komputerze lokalnym i wymagane biblioteki:

pip install perfetto pandas plotly

Tworzenie skryptu do zbiorczej analizy logów czasu

Ten przykładowy skrypt wykonuje zapytanie w wielu logach czasu za pomocą interfejsu Perfetto Python BatchTraceProcessor.

from perfetto.batch_trace_processor import BatchTraceProcessor
import glob
import plotly.express as px

# Collect all trace files in the local directory
traces = glob.glob('*.perfetto-trace')

if not traces:
    print("No .perfetto-trace files found in the current directory.")
    exit(1)

if __name__ == '__main__':
    # Process all traces in parallel to aggregate metrics across runs
    with BatchTraceProcessor(traces) as btp:
        query = """
        CREATE OR REPLACE PERFETTO FUNCTION find_slices(pattern STRING) RETURNS
        TABLE (name STRING, ts LONG, dur LONG) AS
        SELECT name,ts,dur FROM slice WHERE name GLOB $pattern;

        CREATE OR REPLACE PERFETTO FUNCTION generate_start_to_end_slices(startSlicePattern STRING, endSlicePattern STRING, inclusive BOOL) RETURNS
        TABLE(name STRING, ts LONG, dur LONG) AS
        SELECT name, ts, MIN(startToEndDur) as dur
        FROM
          (SELECT S.name as name, S.ts as ts, E.ts + IIF($inclusive, E.dur, 0) - S.ts as startToEndDur
          FROM find_slices($startSlicePattern) as S CROSS JOIN find_slices($endSlicePattern) as E
          WHERE startToEndDur > 0)
        GROUP BY name, ts;

        SELECT ts,name,dur / 1000000 as dur_ms from generate_start_to_end_slices('activityStart','*Choreographer#doFrame [0-9]*', true)
        """
        df = btp.query_and_flatten(query)
        # Plot the distribution of startup times, tracking trace file paths on
        # hover
        violin = px.violin(df, x='dur_ms', hover_data='_path', title='startup time', points='all')
        violin.show()

Zrozumienie skryptu

Po uruchomieniu skryptu w Pythonie wykonuje on te działania:

1. Skrypt wyszukuje w katalogu lokalnym wszystkie logi Perfetto z przyrostkiem .perfetto-trace i używa ich jako logów źródłowych do analizy.
2. Uruchamia zbiorcze zapytanie śledzenia, które oblicza podzbiór czasu uruchamiania odpowiadający czasowi od wycinka śledzenia activityStart do pierwszej klatki wygenerowanej przez aplikację.
3. Przedstawia czas oczekiwania w milisekundach za pomocą wykresu skrzypcowego, aby zwizualizować rozkład czasów uruchamiania.

Interpretowanie wyników

Rysunek 4. Wykres skrzypcowy opóźnień uruchamiania, o które wysłano zapytanie.

Uruchomienie skryptu generuje wykres skrzypcowy przedstawiający rozkład bimodalny z 2 wyraźnymi szczytami czasu oczekiwania (rysunek 4). Najedź kursorem na poszczególne punkty danych na wykresie, aby sprawdzić nazwę pliku _path i porównać ślady z poszczególnych szczytów (rysunek 5):

• Ślady o wysokim opóźnieniu (prawy szczyt): otwarcie śladu z tej grupy w interfejsie Perfetto UI ujawnia dodatkowy wycinek MyFlaggedFeature uruchamiany podczas uruchamiania (rysunek 6).
• Ślady o niskim opóźnieniu (lewy szczyt): otwarcie śladu z szybszej grupy potwierdza, że nie ma w niej MyFlaggedFeature (rysunek 7). Oznacza to, że regresję uruchamiania spowodowała flaga funkcji włączona dla podzbioru użytkowników.

Rysunek 5. Punkt danych o wysokim opóźnieniu na wykresie skrzypcowym.

Rysunek 6. Uruchomienie śledzenia z dużym opóźnieniem z dodatkowym wycinkiem MyFlaggedFeature.

Rysunek 7. Uruchomienie logu czasu oczekiwania z krótkim czasem oczekiwania.

Ten przykład pokazuje jeden z wielu sposobów korzystania z analizy logów czasu oczekiwania zbiorczo. Inne przypadki użycia obejmują wyodrębnianie statystyk z pola w celu oceny wpływu, wykrywanie regresji i inne.

Uwaga: lokalny Batch Trace Processor Python API może analizować dziesiątki lub setki logów czasu, w zależności od dostępnej pamięci. Aby przeanalizować tysiące śladów, zapoznaj się z dokumentacją Perfetto Bigtrace.