Śledzenie w trakcie procesu (eksperymentalne)

Nowa biblioteka androidx.tracing:tracing:2.0.0-alpha01 to lekki interfejs API w Kotlinie, który umożliwia rejestrowanie zdarzeń śledzenia w procesie. Te zdarzenia mogą rejestrować przedziały czasowe i ich kontekst. Biblioteka obsługuje też propagację kontekstu w przypadku korutyn w języku Kotlin.

Biblioteka używa tego samego formatu pakietu śledzenia Perfetto, który jest znany deweloperom Androida. Śledzenie 2.0 (w przeciwieństwie do interfejsów API 1.0.0-*) obsługuje koncepcję wtykowych backendów śledzenia i ujść, dzięki czemu inne biblioteki śledzenia mogą dostosowywać format śledzenia danych wyjściowych oraz sposób działania propagacji kontekstu w swojej implementacji.

Zależności

Aby rozpocząć śledzenie, musisz zdefiniować te zależności w pliku build.gradle.kts.

kotlin {
  androidLibrary {
    namespace = "com.example.library"
    // ...
  }
  sourceSets {
    androidMain {
      dependencies {
        api("androidx.tracing:tracing-wire:2.0.0-alpha01")
        // ...
      }
    }
    jvmMain {
      dependencies {
        api("androidx.tracing:tracing-wire:2.0.0-alpha01")
        // ...
      }
    }
  }
}

Zadeklaruj zależność od androidx.tracing:tracing-wire:2.0.0-alpha01, jeśli kierujesz reklamy na bibliotekę Androida, aplikację na Androida lub na JVM.

Podstawowe użycie

TraceSink określa sposób serializacji pakietów śledzenia. Śledzenie w wersji 2.0.0 zawiera implementację elementu Sink, który używa Perfetto formatu pakietu śledzenia. TraceDriver udostępnia uchwyt do Tracer i może służyć do finalizowania śledzenia.

Możesz też użyć ikony TraceDriver, aby wyłączyć wszystkie punkty śledzenia w aplikacji, jeśli w niektórych jej wersjach nie chcesz w ogóle śledzić danych. Przyszłe interfejsy API w TraceDriver będą też umożliwiać deweloperom określanie, które kategorie śledzenia ich interesują (lub wyłączanie kategorii, gdy generuje ona zbyt dużo danych).

Aby rozpocząć, utwórz instancję TraceSink i TraceDriver.

/**
 * A [TraceSink] defines how traces are serialized.
 *
 * [androidx.tracing.wire.TraceSink] uses the `Perfetto` trace packet format.
 */
fun createSink(): TraceSink {
    val outputDirectory = File(/* path = */ "/tmp/perfetto")
    if (!outputDirectory.exists()) {
        outputDirectory.mkdirs()
    }
    // We are using the factory function defined in androidx.tracing.wire
    return TraceSink(
        sequenceId = 1,
        directory = outputDirectory
    )
}
/**
 * Creates a new instance of [androidx.tracing.TraceDriver].
 */
fun createTraceDriver(): TraceDriver {
    // We are using a factory function from androidx.tracing.wire here.
    // `isEnabled` controls whether tracing is enabled for the application.
    val driver = TraceDriver(sink = createSink(), isEnabled = true)
    return driver
}

Gdy masz instancję TraceDriver, uzyskaj Tracer, który definiuje punkt wejścia dla wszystkich interfejsów API śledzenia.

// Tracing Categories identify subsystems that are responsible
// in generating trace sections. Future APIs in `TraceDriver` will allow the
// application to specify which categories they are interested in tracing.
// This lets the application disable entire trace categories, without
// needing to disable trace instrumentation at the call sites for those
// categories.

internal const val CATEGORY_MAIN = "main"

fun main() {
    val driver = createTraceDriver()
    driver.use {
        driver.tracer.trace(category = CATEGORY_MAIN, name = "basic") {
            Thread.sleep(100L)
        }
    }
}

Spowoduje to wygenerowanie tego logu czasu.

Zrzut ekranu podstawowego śledzenia Perfetto

Rysunek 1. Zrzut ekranu z podstawowym śladem Perfetto.

Widać, że wypełnione są prawidłowe ścieżki procesu i wątku, a także wygenerowana została pojedyncza sekcja śledzenia basic, która działała przez 100ms.

Sekcje śladu (lub wycinki) mogą być zagnieżdżone na tym samym śladzie, aby reprezentować nakładające się zdarzenia. Oto przykład.

fun main() {
    // Initialize the tracing infrastructure to monitor app performance
    val driver = createTraceDriver()
    val tracer = driver.tracer
    driver.use {
        tracer.trace(
            category = CATEGORY_MAIN,
            name = "processImage",
        ) {
            // Load the data first, then apply the sharpen filter
            sharpen(tracer = tracer, output = loadImage(tracer))
        }
    }
}

internal fun loadImage(tracer: Tracer): ByteArray {
    return tracer.trace(CATEGORY_MAIN, "loadImage") {
        // Loads an image
        // ...
        // A placeholder
        ByteArray(0)
    }
}

internal fun sharpen(tracer: Tracer, output: ByteArray) {
    // ...
    tracer.trace(CATEGORY_MAIN, "sharpen") {
        // ...
    }
}

Spowoduje to wygenerowanie tego logu czasu.

Zrzut ekranu podstawowego śladu Perfetto z zagnieżdżonymi sekcjami

Rysunek 2. Zrzut ekranu podstawowego śladu Perfetto z sekcjami zagnieżdżonymi.

Widać, że na ścieżce głównego wątku występują nakładające się zdarzenia. Wyraźnie widać, że wywołania processImage, loadImage i sharpen są wykonywane w tym samym wątku.

Dodawanie dodatkowych metadanych w sekcjach śladu

Czasami warto dołączyć do wycinka śladu dodatkowe metadane kontekstowe, aby uzyskać więcej szczegółów. Przykłady takich metadanych to nav destination, na którym znajduje się użytkownik, lub input arguments, które mogą ostatecznie określić, ile czasu zajmie funkcja.

fun main() {
    val driver = createTraceDriver()
    driver.use {
        driver.tracer.trace(
            category = CATEGORY_MAIN,
            name = "basicWithContext",
            // Add additional metadata
            metadataBlock = {
                // Add key value pairs.
                addMetadataEntry("key", "value")
                addMetadataEntry("count", 1L)
            }
        ) {
            Thread.sleep(100L)
        }
    }
}

Daje to następujący rezultat. Zwróć uwagę, że sekcja Arguments zawiera pary klucz-wartość dodane podczas tworzenia sekcji slice.

Zrzut ekranu podstawowego śladu Perfetto z dodatkowymi metadanymi

Rysunek 3. Zrzut ekranu podstawowego śladu Perfetto z dodatkowymi metadanymi.

Przekazywanie kontekstu

Jeśli używasz Kotlin Coroutines (lub innych podobnych platform, które pomagają w przypadku równoczesnych obciążeń), Tracing 2.0 obsługuje koncepcję propagacji kontekstu. Najlepiej wyjaśnić to na przykładzie.

suspend fun taskOne(tracer: Tracer) {
    tracer.traceCoroutine(category = CATEGORY_MAIN, "taskOne") {
        delay(timeMillis = 100L)
    }
}

suspend fun taskTwo(tracer: Tracer) {
    tracer.traceCoroutine(category = CATEGORY_MAIN, "taskTwo") {
        delay(timeMillis = 50L)
    }
}

fun main() = runBlocking(context = Dispatchers.Default) {
    val driver = createTraceDriver()
    val tracer = driver.tracer
    driver.use {
        tracer.traceCoroutine(category = CATEGORY_MAIN, name = "main") {
            coroutineScope {
                launch { taskOne(tracer) }
                launch { taskTwo(tracer) }
            }
        }
        println("All done")
    }
}

Daje to następujący rezultat.

Zrzut ekranu śladu Perfetto z propagacją kontekstu

Rysunek 4. Zrzut ekranu podstawowego śladu Perfetto z propagacją kontekstu.

Propagacja kontekstu znacznie ułatwia wizualizację przepływu wykonania. Możesz dokładnie sprawdzić, które zadania były powiązane (połączone z innymi), a także kiedy dokładnie zostały zawieszone i wznowione.Threads

Możesz na przykład zobaczyć, że wycinek main wygenerował wycinki taskOne i taskTwo. Potem oba wątki były nieaktywne (zakładając, że korutyny zostały zawieszone – z powodu użycia delay).

Ręczne propagowanie

Czasami podczas łączenia współbieżnych zadań za pomocą korutyn Kotlin z instancjami Java Executor może być przydatne przekazywanie kontekstu z jednego do drugiego. Oto przykład:

fun executorTask(
    tracer: Tracer,
    token: PropagationToken,
    executor: Executor,
    callback: () -> Unit
) {
    executor.execute {
        tracer.trace(
            category = CATEGORY_MAIN,
            name = "executeTask",
            token = token,
        ) {
            // Do something
            Thread.sleep(100)
            callback()
        }
    }
}

@OptIn(DelicateTracingApi::class)
fun main() = runBlocking(context = Dispatchers.Default) {
    val driver = createTraceDriver()
    val executor = Executors.newSingleThreadExecutor()
    val tracer = driver.tracer
    driver.use {
        tracer.traceCoroutine(category = CATEGORY_MAIN, name = "main") {
            coroutineScope {
                val deferred = CompletableDeferred<Unit>()
                executorTask(
                    tracer = tracer,
                    // Obtain the propagation token from the CoroutineContext
                    token = tracer.tokenFromCoroutineContext(),
                    executor = executor,
                    callback = {
                        deferred.complete(Unit)
                    }
                )
                deferred.await()
            }
        }
        executor.shutdownNow()
    }
}

Daje to następujący rezultat.

Zrzut ekranu śladu Perfetto z ręcznym propagowaniem kontekstu

Rysunek 5. Zrzut ekranu podstawowego śladu Perfetto z ręcznym propagowaniem kontekstu.

Widać, że wykonanie rozpoczęło się w CoroutineContext, a następnie przełączyło się na Executor w języku Java, ale nadal mogliśmy używać propagacji kontekstu.

Łączenie ze śladami systemu

Nowy androidx.tracing nie rejestruje informacji takich jak planowanie procesora, wykorzystanie pamięci i interakcje aplikacji z systemem operacyjnym. Dzieje się tak, ponieważ biblioteka umożliwia wykonywanie śledzenia w procesie o bardzo niskim obciążeniu.

W razie potrzeby można jednak bardzo łatwo połączyć logi czasu systemu z logami czasu w procesie i wizualizować je jako jeden log czasu. Dzieje się tak, ponieważ Perfetto UI umożliwia wizualizację wielu plików śledzenia z urządzenia na ujednoliconej osi czasu.

Aby to zrobić, możesz rozpocząć sesję śledzenia systemu za pomocą Perfetto UI, postępując zgodnie z instrukcjami tutaj.

Możesz też rejestrować zdarzenia śledzenia w trakcie procesu za pomocą interfejsu Tracing 2.0 API, gdy śledzenie systemu jest włączone. Gdy będziesz mieć oba pliki śledzenia, możesz użyć opcji Open Multiple Trace Files w Perfetto.

Otwieranie wielu plików śledzenia w interfejsie Perfetto

Rysunek 6. Otwieranie wielu plików śledzenia w interfejsie Perfetto.

Zaawansowane przepływy pracy

Korelacja pasków

Czasami przydatne jest przypisywanie fragmentów śladu do działania użytkownika wyższego poziomu lub zdarzenia systemowego. Aby na przykład przypisać wszystkie wycinki odpowiadające pracy w tle do powiadomienia, możesz wykonać te czynności:

fun main() {
    val driver = createTraceDriver()
    onEvent(driver, eventId = EVENT_ID)
}

fun onEvent(driver: TraceDriver, eventId: Long) {
    driver.use {
        driver.tracer.trace(
            category = CATEGORY_MAIN,
            name = "step-1",
            metadataBlock = {
                addCorrelationId(eventId)
            }
        ) {
            Thread.sleep(100L)
        }

        Thread.sleep(20)

        driver.tracer.trace(
            category = CATEGORY_MAIN,
            name = "step-2",
            metadataBlock = {
                addCorrelationId(eventId)
            }
        ) {
            Thread.sleep(180)
        }
    }
}

Daje to następujący rezultat.

Zrzut ekranu śladu Perfetto ze skorelowanymi wycinkami

Rysunek 7. Zrzut ekranu śladu Perfetto ze skorelowanymi wycinkami.

Dodawanie informacji o stosie wywołań

Narzędzia po stronie hosta (wtyczki kompilatora, procesory adnotacji itp.) mogą dodatkowo osadzać w śladzie informacje o stosie wywołań, aby ułatwić lokalizowanie pliku, klasy lub metody odpowiedzialnej za utworzenie sekcji śladu.

fun main() {
    val driver = createTraceDriver()
    driver.use {
        driver.tracer.trace(
            category = CATEGORY_MAIN,
            name = "callStackEntry",
            metadataBlock = {
                addCallStackEntry(
                    name = "main",
                    lineNumber = 14,
                    sourceFile = "Basic.kt"
                )
            }
        ) {
            Thread.sleep(100L)
        }
    }
}

Daje to następujący rezultat.

Zrzut ekranu z zrzutu Perfetto z informacjami o stosie wywołań

Rysunek 8. Zrzut ekranu śladu Perfetto z informacjami o stosie wywołań.