systrace ist das primäre Tool zur Analyse der Leistung von Android-Geräten. Es ist jedoch wirklich ein Wrapper um andere Tools. Es ist der hostseitige Wrapper um atrace , die geräteseitige ausführbare Datei, die das Userspace-Tracing steuert und ftrace einrichtet , und der primäre Tracing-Mechanismus im Linux-Kernel. systrace verwendet atrace, um die Ablaufverfolgung zu aktivieren, liest dann den ftrace-Puffer und packt alles in einen eigenständigen HTML-Viewer. (Während neuere Kernel Linux Enhanced Berkeley Packet Filter (eBPF) unterstützen, bezieht sich die folgende Dokumentation auf den 3.18-Kernel (kein eFPF), da dieser auf dem Pixel/Pixel XL verwendet wurde.)
systrace gehört den Teams von Google Android und Google Chrome und ist als Teil des Catapult-Projekts Open Source. Zusätzlich zu Systrace enthält Catapult weitere nützliche Dienstprogramme. Beispielsweise hat ftrace mehr Funktionen, als direkt von systrace oder atrace aktiviert werden können, und enthält einige erweiterte Funktionen, die für das Debuggen von Leistungsproblemen entscheidend sind. (Diese Funktionen erfordern Root-Zugriff und oft einen neuen Kernel.)
Systrace läuft
Beginnen Sie beim Debuggen von Jitter auf Pixel/Pixel XL 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 Ablaufverfolgungspunkten, die für GPU- und Display-Pipeline-Aktivitäten erforderlich sind, können Sie so von der Benutzereingabe bis zum auf dem Bildschirm angezeigten Frame zurückverfolgen. Stellen Sie die Puffergröße auf etwas Großes ein, um den Verlust von Ereignissen zu vermeiden (weil einige CPUs ohne einen großen Puffer nach einem bestimmten Punkt in der Ablaufverfolgung keine Ereignisse enthalten).
Denken Sie beim Durchlaufen von Systrace daran, dass jedes Ereignis von etwas auf der CPU ausgelöst wird .
Da systrace auf ftrace aufgebaut ist und ftrace auf der CPU läuft, muss etwas auf der CPU den ftrace-Puffer schreiben, der Hardwareänderungen protokolliert. Das bedeutet, dass Sie, wenn Sie neugierig sind, warum ein Anzeigezaun den Status geändert hat, sehen können, was genau zum Zeitpunkt seines Übergangs auf der CPU ausgeführt wurde (etwas, das auf der CPU ausgeführt wird, hat diese Änderung im Protokoll ausgelöst). Dieses Konzept ist die Grundlage für die Leistungsanalyse mit Systrace.
Beispiel: Arbeitsrahmen
Dieses Beispiel beschreibt einen Systrace für eine normale UI-Pipeline. Um dem Beispiel zu folgen, laden Sie die ZIP-Datei mit Ablaufverfolgungen herunter (die auch andere Ablaufverfolgungen enthält, auf die in diesem Abschnitt verwiesen wird), entpacken Sie die Datei und öffnen Sie die Datei systrace_tutorial.html in Ihrem Browser. Seien Sie gewarnt, dass dieser Systrace eine große Datei ist; Wenn Sie Systrace nicht in Ihrer täglichen Arbeit verwenden, ist dies wahrscheinlich ein viel größerer Trace mit viel mehr Informationen, als Sie jemals zuvor in einem einzelnen Trace gesehen haben.
Für eine konsistente, regelmäßige Arbeitslast wie TouchLatency enthält die UI-Pipeline Folgendes:
- EventThread in SurfaceFlinger weckt den App-UI-Thread und signalisiert, dass es an der Zeit ist, einen neuen Frame zu rendern.
- Die App rendert einen Frame in UI-Thread, RenderThread und hwuiTasks unter Verwendung von CPU- und GPU-Ressourcen. Dies ist der Großteil der für die Benutzeroberfläche aufgewendeten Kapazität.
- Die App sendet den gerenderten Frame mithilfe eines Binders an SurfaceFlinger, dann wechselt SurfaceFlinger in den Ruhezustand.
- Ein zweiter EventThread in SurfaceFlinger weckt SurfaceFlinger, um die Komposition auszulösen und die Ausgabe anzuzeigen. Wenn SurfaceFlinger feststellt, dass keine Arbeit zu erledigen ist, geht es zurück in den Ruhezustand.
- SurfaceFlinger handhabt die Komposition mit Hardware Composer (HWC)/Hardware Composer 2 (HWC2) oder GL. Die HWC/HWC2-Zusammensetzung ist schneller und stromsparender, hat aber je nach System-on-a-Chip (SoC) Einschränkungen. Dies dauert normalerweise ~4-6 ms, kann sich aber mit Schritt 2 überschneiden, da Android-Apps immer dreifach gepuffert werden. (Während Apps immer dreifach gepuffert werden, wartet in SurfaceFlinger möglicherweise nur ein ausstehender Frame, wodurch es mit doppelter Pufferung identisch erscheint.)
- SurfaceFlinger sendet die endgültige Ausgabe an die Anzeige mit einem Anbietertreiber und kehrt in den Ruhezustand zurück und wartet auf die Aktivierung von EventThread.
Gehen wir den Frame ab 15409 ms durch:
Abbildung 1 ist ein normaler Frame, der von normalen Frames umgeben ist, daher ist dies ein guter Ausgangspunkt, um zu verstehen, wie die UI-Pipeline funktioniert. Die UI-Thread-Zeile für TouchLatency enthält zu unterschiedlichen Zeiten unterschiedliche Farben. Balken kennzeichnen verschiedene Zustände für den Thread:
- Grau . Schlafen.
- Blau. Ausführbar (es könnte ausgeführt werden, aber der Scheduler hat es noch nicht zur Ausführung ausgewählt).
- Grün. Wird aktiv ausgeführt (der Scheduler denkt, dass es ausgeführt wird).
- Rot. Unterbrechungsfreier Ruhezustand (im Allgemeinen auf einer Sperre im Kernel schlafend). Kann auf E/A-Last hinweisen. Äußerst nützlich zum Debuggen von Leistungsproblemen.
- Orange. Unterbrechungsfreier Ruhezustand aufgrund von E/A-Last.
Um den Grund für den unterbrechungsfreien Ruhezustand anzuzeigen (verfügbar über den sched_blocked_reason sched_blocked_reason), wählen Sie das rote Slice für den unterbrechungsfreien Ruhezustand aus.
Während EventThread ausgeführt wird, wird der UI-Thread für TouchLatency ausführbar. Um zu sehen, was es geweckt hat, klicken Sie auf den blauen Abschnitt.
Abbildung 2 zeigt, dass der TouchLatency-UI-Thread durch Tid 6843 aktiviert wurde, was EventThread entspricht. Der UI-Thread wird aktiviert, rendert einen Frame und stellt ihn für die Verwendung durch SurfaceFlinger in die Warteschlange.
Wenn das Tag binder_driver in einem Trace aktiviert ist, können Sie eine Bindertransaktion auswählen, um Informationen zu allen an dieser Transaktion beteiligten Prozessen anzuzeigen.
Abbildung 4 zeigt, dass Binder:6832_1 in SurfaceFlinger bei 15.423,65 ms aufgrund von tid 9579, dem RenderThread von TouchLatency, lauffähig wird. Sie können auch queueBuffer auf beiden Seiten der Binder-Transaktion sehen.
Während des queueBuffer auf der SurfaceFlinger-Seite geht die Anzahl der ausstehenden Frames von TouchLatency von 1 auf 2.
Abbildung 5 zeigt die dreifache Pufferung, bei der zwei abgeschlossene Frames vorhanden sind und die App gerade mit dem Rendern eines dritten beginnt. Dies liegt daran, dass wir bereits einige Frames ausgelassen haben, sodass die App zwei ausstehende Frames anstelle von einem behält, um zu versuchen, weitere ausgelassene Frames zu vermeiden.
Kurz darauf wird der Haupt-Thread von SurfaceFlinger durch einen zweiten EventThread geweckt, damit er den älteren ausstehenden Frame auf dem Display ausgeben kann:
SurfaceFlinger verriegelt zuerst den älteren ausstehenden Puffer, wodurch die Anzahl der ausstehenden Puffer von 2 auf 1 verringert wird.
Nach dem Zwischenspeichern des Puffers richtet SurfaceFlinger die Komposition ein und sendet den endgültigen Frame an die Anzeige. (Einige dieser Abschnitte werden als Teil des mdss -Tracepoints aktiviert, sodass sie möglicherweise nicht in Ihrem SoC enthalten sind.)
Als nächstes wacht mdss_fb0 auf CPU 0 auf. mdss_fb0 ist der Kernel-Thread der Display-Pipeline zum Ausgeben eines gerenderten Frames an das Display. Wir können mdss_fb0 als eigene Zeile im Trace sehen (zur Ansicht nach unten scrollen).
mdss_fb0 wacht auf, läuft kurz, wechselt in den unterbrechungsfreien Ruhezustand und wacht dann wieder auf.
Beispiel: Nicht funktionierender Rahmen
Dieses Beispiel beschreibt einen Systrace, der zum Debuggen von Pixel/Pixel XL-Jitter verwendet wird. Um dem Beispiel zu folgen, laden Sie die ZIP-Datei mit Ablaufverfolgungen herunter (die andere Ablaufverfolgungen enthält, auf die in diesem Abschnitt verwiesen wird), entpacken Sie die Datei und öffnen Sie die Datei systrace_tutorial.html in Ihrem Browser.
Wenn Sie den Systrace öffnen, sehen Sie etwa Folgendes:
Überprüfen Sie bei der Suche nach Jank die FrameMissed-Zeile unter SurfaceFlinger. FrameMissed ist eine von HWC2 bereitgestellte Verbesserung der Lebensqualität. Beim Anzeigen von Systrace für andere Geräte ist die FrameMissed-Zeile möglicherweise nicht vorhanden, wenn das Gerät HWC2 nicht verwendet. In beiden Fällen korreliert FrameMissed damit, dass SurfaceFlinger eine seiner extrem regelmäßigen Laufzeiten und eine unveränderte Pending-Buffer-Anzahl für die App ( com.prefabulated.touchlatency ) bei einem Vsync fehlt.
Abbildung 11 zeigt einen verpassten Frame bei 15598,29 ms. SurfaceFlinger wachte kurz im Vsync-Intervall auf und ging wieder in den Ruhezustand, ohne etwas zu tun, was bedeutet, dass SurfaceFlinger feststellte, dass es sich nicht lohnt, erneut einen Frame an das Display zu senden. Wieso den?
Um zu verstehen, wie die Pipeline für diesen Frame zusammengebrochen ist, sehen Sie sich zunächst das obige Arbeitsframe-Beispiel an, um zu sehen, wie eine normale UI-Pipeline in Systrace angezeigt wird. Wenn Sie fertig sind, kehren Sie zum verpassten Frame zurück und arbeiten Sie rückwärts. Beachten Sie, dass SurfaceFlinger aufwacht und sofort in den Ruhezustand wechselt. Wenn Sie die Anzahl der ausstehenden Frames von TouchLatency anzeigen, gibt es zwei Frames (ein guter Hinweis, um herauszufinden, was los ist).
Da wir Frames in SurfaceFlinger haben, ist es kein App-Problem. Darüber hinaus wird SurfaceFlinger zur richtigen Zeit aktiviert, sodass es sich nicht um ein SurfaceFlinger-Problem handelt. Wenn SurfaceFlinger und die App beide normal aussehen, handelt es sich wahrscheinlich um ein Treiberproblem.
Da die mdss und sync -Tracepoints aktiviert sind, können wir Informationen über die Zäune (die vom Anzeigetreiber und SurfaceFlinger gemeinsam genutzt werden) abrufen, die steuern, wann Frames an die Anzeige gesendet werden. Diese Zäune sind unter mdss_fb0_retire aufgeführt, was angibt, wann ein Frame auf dem Display angezeigt wird. Diese Zäune werden als Teil der Kategorie „ sync Trace“ bereitgestellt. Welche Zäune bestimmten Ereignissen in SurfaceFlinger entsprechen, hängt von Ihrem SOC- und Treiberstapel ab. Arbeiten Sie also mit Ihrem SOC-Anbieter zusammen, um die Bedeutung der Zaunkategorien in Ihren Ablaufverfolgungen zu verstehen.
Abbildung 13 zeigt einen Frame, der 33 ms lang angezeigt wurde, nicht wie erwartet 16,7 ms lang. Auf halbem Weg durch diesen Schnitt hätte dieser Rahmen durch einen neuen ersetzt werden sollen, war es aber nicht. Sehen Sie sich den vorherigen Frame an und suchen Sie nach irgendetwas.
Abbildung 14 zeigt 14,482 ms pro Frame. Das unterbrochene Zwei-Frame-Segment dauerte 33,6 ms, was in etwa dem entspricht, was wir für zwei Frames erwarten würden (wir rendern mit 60 Hz, 16,7 ms pro Frame, was nah dran ist). Aber 14,482 ms ist überhaupt nicht nah an 16,7 ms, was darauf hindeutet, dass etwas mit der Anzeigeleitung nicht stimmt.
Untersuchen Sie genau, wo dieser Zaun endet, um festzustellen, was ihn kontrolliert.
Eine Arbeitswarteschlange enthält __vsync_retire_work_handler , das ausgeführt wird, wenn sich der Zaun ändert. Wenn Sie die Kernel-Quelle durchsehen, können Sie sehen, dass sie Teil des Anzeigetreibers ist. Es scheint sich auf dem kritischen Pfad für die Display-Pipeline zu befinden, also muss es so schnell wie möglich laufen. Es kann für ungefähr 70 us ausgeführt werden (keine lange Planungsverzögerung), aber es ist eine Arbeitswarteschlange und wird möglicherweise nicht genau geplant.
Überprüfen Sie den vorherigen Frame, um festzustellen, ob dieser dazu beigetragen hat; Manchmal kann sich Jitter im Laufe der Zeit summieren und schließlich zu einer verpassten Frist führen.
Die ausführbare Zeile auf dem kworker ist nicht sichtbar, weil der Betrachter sie weiß färbt, wenn sie ausgewählt ist, aber die Statistiken sagen die Geschichte: 2,3 ms Verzögerung des Zeitplaners für einen Teil des kritischen Pfads der Anzeigepipeline ist schlecht . Bevor Sie fortfahren, beheben Sie die Verzögerung, indem Sie diesen Teil des kritischen Pfads der Anzeigepipeline von einer Arbeitswarteschlange (die als SCHED_OTHER CFS-Thread ausgeführt wird) in einen dedizierten SCHED_FIFO SCHED_FIFO verschieben. Diese Funktion benötigt Timing-Garantien, die Workqueues nicht bieten können (und auch nicht sollen).
Ist das der Grund für den Ruck? Es ist schwer abschließend zu sagen. Abgesehen von leicht zu diagnostizierenden Fällen wie Kernel-Sperrkonflikten, die dazu führen, dass anzeigekritische Threads in den Ruhezustand versetzt werden, geben Ablaufverfolgungen das Problem normalerweise nicht an. Könnte dieser Jitter die Ursache für den Dropped Frame gewesen sein? Unbedingt. Die Fence-Zeiten sollten 16,7 ms betragen, aber sie sind in den Frames, die zum Dropped-Frame führen, überhaupt nicht annähernd so hoch. Angesichts der engen Kopplung der Display-Pipeline ist es möglich, dass der Jitter um die Fence-Timings zu einem Dropped Frame führte.
In diesem Beispiel bestand die Lösung darin, __vsync_retire_work_handler von einer Workqueue in einen dedizierten kthread umzuwandeln. Dies führte zu spürbaren Jitter-Verbesserungen und reduziertem Ruckeln im Prellball-Test. Nachfolgende Spuren zeigen Zaunzeiten, die sehr nahe bei 16,7 ms liegen.