systrace ist das primäre Tool zur Analyse der Leistung von Android-Geräten. Es ist jedoch in Wirklichkeit ein Wrapper für andere Tools. Es ist der hostseitige Wrapper um atrace, die geräteseitige ausführbare Datei, die das Userspace-Tracing steuert und ftrace einrichtet, sowie der primäre Tracing-Mechanismus im Linux-Kernel. Systrace verwendet atrace, um das Tracing zu aktivieren, liest dann den ftrace-Puffer und verpackt alles in einem eigenständigen HTML-Viewer. Neuere Kernel unterstützen den Linux Enhanced Berkeley Packet Filter (eBPF). Die folgende Dokumentation bezieht sich jedoch auf den Kernel 3.18 (kein eBPF), da dieser auf Google Pixel und Google Pixel XL verwendet wurde.
systrace ist Eigentum der Android- und Chrome-Teams von Google und ist als Teil des Catapult-Projekts Open Source. Neben systrace enthält Catapult weitere nützliche Dienstprogramme. Ftrace bietet beispielsweise mehr Funktionen als mit systrace oder atrace direkt aktiviert werden können. Außerdem enthält es einige erweiterte Funktionen, die für die Behebung von Leistungsproblemen entscheidend sind. (Für diese Funktionen ist Root-Zugriff und oft ein neuer Kernel erforderlich.)
systrace ausführen
Wenn Sie Jitter bei Pixel/Pixel XL beheben möchten, beginnen Sie mit dem folgenden Befehl:
./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000
In Kombination mit den zusätzlichen Tracepoints, die für die GPU- und Displaypipeline-Aktivität erforderlich sind, können Sie von der Nutzereingabe bis zum auf dem Bildschirm angezeigten Frame zurückverfolgen. Legen Sie eine große Puffergröße fest, um das Verlieren von Ereignissen zu vermeiden. Ohne einen großen Puffer enthalten einige CPUs nach einem bestimmten Punkt im Trace keine Ereignisse mehr.
Denken Sie beim Durchgehen von systrace daran, dass jedes Ereignis durch etwas auf der CPU ausgelöst wird.
Da systrace auf ftrace basiert und ftrace auf der CPU ausgeführt wird, muss etwas auf der CPU den ftrace-Puffer schreiben, in dem Hardwareänderungen protokolliert werden. Wenn Sie wissen möchten, warum sich der Status eines Display-Fences geändert hat, können Sie sehen, was genau zum Zeitpunkt des Übergangs auf der CPU ausgeführt wurde. Dieses Konzept ist die Grundlage für die Analyse der Leistung mit systrace.
Beispiel: Arbeitsrahmen
In diesem Beispiel wird ein Systrace für eine normale UI-Pipeline beschrieben. Wenn Sie dem Beispiel folgen möchten, laden Sie die ZIP-Datei mit den Traces herunter (enthält auch andere Traces, auf die in diesem Abschnitt verwiesen wird), entpacken Sie die Datei und öffnen Sie die systrace_tutorial.html-Datei in Ihrem Browser. Diese Systrace-Datei ist sehr groß. Wenn Sie Systrace nicht regelmäßig verwenden, ist dies wahrscheinlich ein viel größerer Trace mit viel mehr Informationen als Sie bisher in einem einzelnen Trace gesehen haben.
Für eine konsistente, regelmäßige Arbeitslast wie TouchLatency enthält die UI-Pipeline Folgendes:
- Der EventThread in SurfaceFlinger weckt den UI-Thread der App und signalisiert, dass es an der Zeit ist, einen neuen Frame zu rendern.
- Die App rendert einen Frame im UI-Thread, RenderThread und hwuiTasks unter Verwendung von CPU- und GPU-Ressourcen. Dies ist der Großteil der Kapazität, der für die Benutzeroberfläche aufgewendet wird.
- Die App sendet den gerenderten Frame über einen Binder an SurfaceFlinger, der dann in den Ruhemodus versetzt wird.
- Ein zweiter EventThread in SurfaceFlinger weckt SurfaceFlinger auf, um die Zusammensetzung und Displayausgabe auszulösen. Wenn SurfaceFlinger feststellt, dass keine Arbeit ansteht, wechselt er wieder in den Ruhemodus.
- SurfaceFlinger verarbeitet die Komposition mit Hardware Composer (HWC)/Hardware Composer 2 (HWC2) oder GL. Die HWC-/HWC2-Komposition ist schneller und benötigt weniger Strom, hat aber je nach System-on-Chip (SoC) Einschränkungen. Das dauert in der Regel etwa 4–6 ms, kann sich aber mit Schritt 2 überschneiden, da Android-Apps immer dreifach gepuffert werden. Apps werden zwar immer dreifach gepuffert, in SurfaceFlinger kann aber nur ein ausstehender Frame warten, was es so aussehen lässt, als wäre es eine doppelte Pufferung.
- SurfaceFlinger sendet die endgültige Ausgabe an das Display mit einem Anbietertreiber und kehrt in den Ruhemodus zurück, um auf das Wecken durch EventThread zu warten.
Sehen wir uns den Frame ab 15.409 ms an:
Abbildung 1 zeigt einen normalen Frame, der von normalen Frames umgeben ist. Sie ist ein guter Ausgangspunkt, um die Funktionsweise der UI-Pipeline zu verstehen. Die Zeile für den UI-Thread für TouchLatency hat zu verschiedenen Zeiten unterschiedliche Farben. Die Balken stehen für verschiedene Status des Threads:
- Grau Schlafen.
- Blau Ausführbar (die Aufgabe könnte ausgeführt werden, wurde aber vom Planer noch nicht ausgewählt).
- Grün Aktiv ausgeführt (der Scheduler geht davon aus, dass der Prozess aktiv ist).
- Rot Ununterbrochener Schlaf (in der Regel mit einer Sperre im Kernel) Kann ein Hinweis auf die I/O-Auslastung sein. Sehr nützlich für die Behebung von Leistungsproblemen.
- Orange Ununterbrochener Ruhemodus aufgrund von I/O-Last
Wenn Sie den Grund für den ununterbrochenen Ruhezustand sehen möchten (verfügbar über den Tracepoint sched_blocked_reason), wählen Sie den roten Abschnitt für den ununterbrochenen Ruhezustand aus.
Solange EventThread ausgeführt wird, kann der UI-Thread für TouchLatency ausgeführt werden. Wenn Sie sehen möchten, was das Gerät geweckt hat, klicken Sie auf den blauen Bereich.
Abbildung 2 zeigt, dass der UI-Thread „TouchLatency“ durch die Task-ID 6843 geweckt wurde, die dem EventThread entspricht. Der UI-Thread wird gestartet, rendert einen Frame und stellt ihn für SurfaceFlinger zur Verfügung.
Wenn das binder_driver-Tag in einem Trace aktiviert ist, können Sie eine Binder-Transaktion auswählen, um Informationen zu allen an dieser Transaktion beteiligten Prozessen aufzurufen.
Abbildung 4 zeigt, dass Binder:6832_1 in SurfaceFlinger nach 15.423,65 ms aufgrund von tid 9579 ausführbar wird. Das ist der RenderThread von TouchLatency. Sie sehen queueBuffer auch auf beiden Seiten der Binder-Transaktion.
Während des QueueBuffers auf der SurfaceFlinger-Seite steigt die Anzahl der ausstehenden Frames von TouchLatency von 1 auf 2.
Abbildung 5 zeigt die Dreifachpufferung, bei der zwei Frames fertig sind und die App gerade mit dem Rendern eines dritten beginnt. Das liegt daran, dass bereits einige Frames verworfen wurden. Daher behält die App zwei ausstehende Frames statt nur eines, um weitere verworfene Frames zu vermeiden.
Bald darauf wird der Haupt-Thread von SurfaceFlinger von einem zweiten EventThread geweckt, damit er den älteren ausstehenden Frame auf dem Display ausgeben kann:
SurfaceFlinger schützt zuerst den älteren ausstehenden Puffer, wodurch die Anzahl der ausstehenden Puffer von 2 auf 1 sinkt.
Nachdem der Puffer gefangen wurde, richtet SurfaceFlinger die Komposition ein und sendet den endgültigen Frame an das Display. Einige dieser Abschnitte werden im Rahmen des mdss-Tracepoints aktiviert und sind daher möglicherweise nicht auf Ihrem SoC enthalten.
Als Nächstes wird mdss_fb0 von CPU 0 geweckt. mdss_fb0 ist der Kernel-Thread der Displaypipeline, der einen gerenderten Frame auf dem Display ausgibt.
mdss_fb0 wird im Trace als eigene Zeile angezeigt (scrollen Sie nach unten).
mdss_fb0 wird gestartet, läuft kurz, wechselt in den ununterbrochenen Ruhemodus und wird dann wieder gestartet.
Beispiel: Nicht funktionierender Frame
In diesem Beispiel wird ein Systrace beschrieben, der zur Fehlerbehebung bei Jitter bei Pixel/Pixel XL verwendet wird. Wenn Sie dem Beispiel folgen möchten, laden Sie die ZIP-Datei mit den Traces herunter (enthält auch andere Traces, auf die in diesem Abschnitt verwiesen wird), entpacken Sie die Datei und öffnen Sie die systrace_tutorial.html-Datei in Ihrem Browser.
Wenn Sie den Systrace öffnen, sehen Sie in etwa Folgendes:
Wenn Sie nach Rucklern suchen, sehen Sie sich die Zeile „FrameMissed“ unter „SurfaceFlinger“ an.
FrameMissed ist eine Verbesserung der Lebensqualität, die von HWC2 bereitgestellt wird. Wenn Sie sich systrace für andere Geräte ansehen, ist die Zeile „FrameMissed“ möglicherweise nicht vorhanden, wenn das Gerät HWC2 nicht verwendet. In beiden Fällen ist „FrameMissed“ mit dem Auslassen einer der extrem regelmäßigen Laufzeiten von SurfaceFlinger und einer unveränderten Anzahl ausstehender Puffer für die App (com.prefabulated.touchlatency) bei einer vsync korreliert.
Abbildung 11 zeigt einen verpassten Frame bei 15.598,29 ms. SurfaceFlinger wurde kurzzeitig im vsync-Intervall geweckt und ging ohne Arbeit wieder in den Ruhemodus. Das bedeutet, dass SurfaceFlinger festgestellt hat, dass es sich nicht lohnt, noch einmal zu versuchen, einen Frame an das Display zu senden. Was steckt dahinter?
Um zu verstehen, wie die Pipeline für diesen Frame zusammengebrochen ist, sehen Sie sich zuerst das Beispiel für den funktionierenden Frame oben an, um zu sehen, wie eine normale UI-Pipeline in systrace angezeigt wird. Wenn du fertig bist, kehre zum verpassten Frame zurück und arbeite rückwärts. Beachten Sie, dass SurfaceFlinger aktiviert und sofort wieder in den Ruhemodus versetzt wird. Die Anzahl der ausstehenden Frames von TouchLatency beträgt zwei. Das ist ein guter Hinweis, um herauszufinden, was los ist.
Da wir Frames in SurfaceFlinger haben, handelt es sich nicht um ein App-Problem. Außerdem wird SurfaceFlinger zur richtigen Zeit gestartet. Es handelt sich also nicht um ein SurfaceFlinger-Problem. Wenn SurfaceFlinger und die App normal aussehen, liegt wahrscheinlich ein Treiberproblem vor.
Da die Tracepoints mdss und sync aktiviert sind, können wir Informationen zu den Fences abrufen, die zwischen dem Displaytreiber und SurfaceFlinger geteilt werden und steuern, wann Frames an das Display gesendet werden.
Diese Begrenzungen werden unter mdss_fb0_retire aufgeführt, was bedeutet, dass sich ein Frame auf dem Display befindet. Diese Begrenzungen werden als Teil der Trace-Kategorie sync bereitgestellt. Welche Grenzwerte bestimmten Ereignissen in SurfaceFlinger entsprechen, hängt von Ihrem SOC und Ihrem Treiberstack ab. Wenden Sie sich daher an Ihren SOC-Anbieter, um die Bedeutung der Grenzwertkategorien in Ihren Protokollen zu erfahren.
Abbildung 13 zeigt einen Frame, der 33 ms lang angezeigt wurde, also nicht wie erwartet 16,7 ms. In der Mitte dieses Segments sollte dieser Frame durch einen neuen ersetzt werden, was aber nicht der Fall war. Sehen Sie sich den vorherigen Frame an und suchen Sie nach etwas.
Abbildung 14 zeigt 14,482 ms pro Frame. Das fehlerhafte Segment mit zwei Frames dauerte 33,6 ms. Das entspricht ungefähr dem, was wir für zwei Frames erwarten würden (wir rendern mit 60 Hz, also 16,7 ms pro Frame, was nah dran ist). 14,482 ms sind jedoch weit von 16,7 ms entfernt, was darauf hindeutet, dass etwas mit der Displaypipeline nicht stimmt.
Prüfen Sie genau, wo dieser Zaun endet, um festzustellen, was ihn steuert.
Eine Arbeitswarteschlange enthält __vsync_retire_work_handler, das ausgeführt wird, wenn sich die Umzäunung ändert. In der Kernelquelle sehen Sie, dass es sich um einen Teil des Displaytreibers handelt. Es befindet sich offenbar auf dem kritischen Pfad für die Displaypipeline und muss daher so schnell wie möglich ausgeführt werden. Sie kann etwa 70 µs lang ausgeführt werden (keine lange Planungsverzögerung), ist aber eine Arbeitswarteschlange und wird möglicherweise nicht genau geplant.
Prüfe den vorherigen Frame, um festzustellen, ob das der Fall ist. Manchmal kann sich Jitter im Laufe der Zeit summieren und schließlich zu einem verpassten Termin führen.
Die ausführbare Zeile im kworker ist nicht sichtbar, da sie im Viewer weiß wird, wenn sie ausgewählt ist.Die Statistiken sprechen jedoch für sich: 2,3 ms Scheduler-Verzögerung für einen Teil des kritischen Pfades der Displaypipeline ist schlecht.
Beheben Sie vor dem Fortfahren die Verzögerung, indem Sie diesen Teil des kritischen Pfades der Anzeigepipeline von einem Arbeitsqueue (der als SCHED_OTHER-CFS-Thread ausgeführt wird) zu einem speziellen SCHED_FIFO-Kthread verschieben. Für diese Funktion sind zeitliche Zusicherungen erforderlich, die Workqueues nicht bieten können und auch nicht bieten sollen.
Ist das der Grund für die Ruckler? Das lässt sich nicht eindeutig sagen. Außer in leicht zu diagnostizierenden Fällen wie Kernel-Lock-Konflikten, die dazu führen, dass für die Anzeige kritische Threads in den Ruhemodus versetzt werden, geben die Protokolle in der Regel keine Hinweise auf das Problem. Könnte dieser Jitter der Grund für den Frame-Drop sein? Selbstverständlich. Die Zaunzeiten sollten 16,7 ms betragen, aber in den Frames vor dem Frame mit Aussetzern liegen sie weit darunter. Aufgrund der engen Kopplung der Displaypipeline ist es möglich, dass der Jitter bei den Grenzzeitpunkten zu einem Frame-Drop geführt hat.
In diesem Beispiel bestand die Lösung darin, __vsync_retire_work_handler von einem Arbeitsauftrag in einen speziellen Kthread umzuwandeln. Das führte zu deutlichen Verbesserungen beim Jitter und zu weniger Ruckeln beim Test mit dem springenden Ball. Nachfolgende Traces zeigen Zaunzeitpunkte, die sehr nahe an 16,7 ms liegen.