Systrace verstehen

systrace ist das wichtigste Tool zur Analyse der Leistung von Android-Geräten. Es handelt sich jedoch tatsächlich um eine Umhüllung anderer Tools. Es handelt sich um den hostseitigen Wrapper um atrace , die geräteseitige ausführbare Datei, die das Userspace-Trace steuert und ftrace einrichtet, sowie den primären Tracing-Mechanismus im Linux-Kernel. Systrace verwendet atrace, um die Ablaufverfolgung zu ermöglichen, liest dann den Ftrace-Puffer und packt alles in einen eigenständigen HTML-Viewer. (Während neuere Kernel den 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 Google Android- und Google Chrome-Teams und ist Open Source als Teil des Catapult-Projekts . Neben Systrace enthält Catapult weitere nützliche Dienstprogramme. Beispielsweise verfügt ftrace über mehr Funktionen, als von systrace oder atrace direkt aktiviert werden können, und enthält einige erweiterte Funktionen, die für das Debuggen von Leistungsproblemen von entscheidender Bedeutung sind. (Diese Funktionen erfordern Root-Zugriff und häufig einen neuen Kernel.)

Systrace ausführen

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 Tracepoints, die für die GPU- und Display-Pipeline-Aktivität erforderlich sind, erhalten Sie so die Möglichkeit, von der Benutzereingabe bis zum auf dem Bildschirm angezeigten Frame zu verfolgen. Stellen Sie die Puffergröße auf einen großen Wert ein, um den Verlust von Ereignissen zu vermeiden (da einige CPUs ohne einen großen Puffer nach einem bestimmten Punkt im Trace keine Ereignisse mehr enthalten).

Bedenken Sie beim Durchlaufen von Systrace, dass jedes Ereignis durch etwas auf der CPU ausgelöst wird .

Da systrace auf ftrace aufbaut und ftrace auf der CPU ausgeführt wird, muss etwas auf der CPU in den ftrace-Puffer schreiben, der Hardwareänderungen protokolliert. Wenn Sie also wissen möchten, warum ein Anzeigezaun seinen Status geändert hat, können Sie sehen, was zum genauen Zeitpunkt des Übergangs auf der CPU ausgeführt wurde (etwas, das auf der CPU ausgeführt wurde, 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 den Traces herunter (die auch andere in diesem Abschnitt erwähnte Traces enthält), entpacken Sie die Datei und öffnen Sie die Datei systrace_tutorial.html in Ihrem Browser. Seien Sie gewarnt, dass es sich bei dieser Systrace um eine große Datei handelt. Sofern Sie systrace nicht in Ihrer täglichen Arbeit verwenden, handelt es sich wahrscheinlich um einen viel größeren Trace mit viel mehr Informationen, als Sie jemals zuvor in einem einzelnen Trace gesehen haben.

Für eine konsistente, periodische Arbeitslast wie TouchLatency enthält die UI-Pipeline Folgendes:

  1. EventThread in SurfaceFlinger weckt den App-UI-Thread und signalisiert damit, dass es Zeit ist, einen neuen Frame zu rendern.
  2. Die App rendert einen Frame im UI-Thread, RenderThread und hwuiTasks und nutzt dabei CPU- und GPU-Ressourcen. Dies ist der Großteil der für die Benutzeroberfläche aufgewendeten Kapazität.
  3. Die App sendet den gerenderten Frame mithilfe eines Binders an SurfaceFlinger, woraufhin SurfaceFlinger in den Ruhezustand wechselt.
  4. 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 wieder in den Ruhezustand über.
  5. SurfaceFlinger übernimmt die Komposition mit Hardware Composer (HWC)/Hardware Composer 2 (HWC2) oder GL. Die HWC/HWC2-Zusammensetzung ist schneller und stromsparender, weist jedoch je nach System-on-a-Chip (SoC) Einschränkungen auf. Dies dauert normalerweise ca. 4–6 ms, kann sich jedoch mit Schritt 2 überschneiden, da Android-Apps immer dreifach gepuffert sind. (Während Apps immer dreifach gepuffert sind, kann es sein, dass in SurfaceFlinger nur ein ausstehender Frame wartet, was den Eindruck erweckt, dass es sich um eine doppelte Pufferung handelt.)
  6. SurfaceFlinger sendet die endgültige Ausgabe zur Anzeige mit einem Herstellertreiber, geht wieder in den Ruhezustand und wartet auf das Aufwachen von EventThread.

Gehen wir ab 15409 ms durch den Frame:

Normale UI-Pipeline mit ausgeführtem EventThread
Abbildung 1. Normale UI-Pipeline, EventThread wird ausgeführt

Abbildung 1 ist ein normaler Frame, der von normalen Frames umgeben ist. Daher ist sie ein guter Ausgangspunkt für das Verständnis der Funktionsweise der UI-Pipeline. Die UI-Threadzeile für TouchLatency enthält zu unterschiedlichen Zeiten unterschiedliche Farben. Balken kennzeichnen verschiedene Zustände des Threads:

  • 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. Läuft aktiv (der Planer geht davon aus, dass es läuft).
  • Rot. Ununterbrochener Schlaf (im Allgemeinen Schlaf auf einer Sperre im Kernel). Kann ein Hinweis auf die E/A-Last sein. Äußerst nützlich zum Debuggen von Leistungsproblemen.
  • Orange. Ununterbrochener Ruhezustand aufgrund der E/A-Last.

Um den Grund für den unterbrechungsfreien Ruhezustand anzuzeigen (verfügbar über den Tracepoint sched_blocked_reason ), wählen Sie das rote Segment für den unterbrechungsfreien Ruhezustand aus.

Während EventThread ausgeführt wird, kann der UI-Thread für TouchLatency ausgeführt werden. Um zu sehen, was es aufgeweckt hat, klicken Sie auf den blauen Abschnitt.

UI-Thread für TouchLatency
Abbildung 2. UI-Thread für TouchLatency

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 in die Warteschlange, damit SurfaceFlinger ihn nutzen kann.

Der UI-Thread wird aktiviert, rendert einen Frame und stellt ihn in die Warteschlange, damit SurfaceFlinger ihn nutzen kann
Abbildung 3. Der UI-Thread wird aktiviert, rendert einen Frame und stellt ihn in die Warteschlange, damit SurfaceFlinger ihn nutzen kann

Wenn das Tag binder_driver in einer Ablaufverfolgung aktiviert ist, können Sie eine Binder-Transaktion auswählen, um Informationen zu allen an dieser Transaktion beteiligten Prozessen anzuzeigen.

Abbildung 4. Binder-Transaktion

Abbildung 4 zeigt, dass Binder:6832_1 in SurfaceFlinger bei 15.423,65 ms aufgrund von TID 9579, dem RenderThread von TouchLatency, ausführbar wird. Sie können queueBuffer auch auf beiden Seiten der Binder-Transaktion sehen.

Während des queueBuffer auf der SurfaceFlinger-Seite steigt die Anzahl der ausstehenden Frames von TouchLatency von 1 auf 2.

Ausstehende Frames gehen von 1 auf 2
Abbildung 5. Ausstehende Frames wechseln von 1 auf 2

Abbildung 5 zeigt die dreifache Pufferung, bei der es zwei abgeschlossene Frames gibt und die App gerade mit dem Rendern eines dritten beginnt. Das liegt daran, dass wir bereits einige Frames gelöscht haben. Daher behält die App zwei ausstehende Frames statt einem bei, um weitere Frames zu vermeiden.

Kurz darauf wird der Hauptthread von SurfaceFlinger von einem zweiten EventThread geweckt, sodass er den älteren ausstehenden Frame auf dem Display ausgeben kann:

Der Hauptthread von SurfaceFlinger wird durch einen zweiten EventThread geweckt
Abbildung 6. Der Hauptthread von SurfaceFlinger wird durch einen zweiten EventThread geweckt

SurfaceFlinger speichert zunächst den älteren ausstehenden Puffer, wodurch die Anzahl der ausstehenden Puffer von 2 auf 1 sinkt.

SurfaceFlinger greift zunächst auf den älteren ausstehenden Puffer ein
Abbildung 7. SurfaceFlinger rastet zunächst in den älteren ausstehenden Puffer ein

Nach dem Zwischenspeichern des Puffers richtet SurfaceFlinger die Komposition ein und übermittelt den endgültigen Frame an die Anzeige. (Einige dieser Abschnitte sind als Teil des mdss Tracepoints aktiviert und daher möglicherweise nicht in Ihrem SoC enthalten.)

SurfaceFlinger richtet die Komposition ein und übermittelt den endgültigen Frame
Abbildung 8. SurfaceFlinger richtet die Komposition ein und übermittelt den endgültigen Frame

Als nächstes wird mdss_fb0 auf CPU 0 aktiviert. mdss_fb0 ist der Kernel-Thread der Anzeigepipeline für die Ausgabe eines gerenderten Frames an die Anzeige. Wir können mdss_fb0 als eigene Zeile im Trace sehen (scrollen Sie nach unten, um es anzuzeigen).

mdss_fb0 wird auf CPU 0 aktiviert
Abbildung 9. mdss_fb0 wird auf CPU 0 aktiviert

mdss_fb0 wacht auf, läuft kurz, wechselt in den ununterbrochenen 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 den Spuren herunter (einschließlich anderer in diesem Abschnitt erwähnter Spuren), entpacken Sie die Datei und öffnen Sie die Datei systrace_tutorial.html in Ihrem Browser.

Wenn Sie das Systrace öffnen, sehen Sie etwa Folgendes:

TouchLatency läuft auf Pixel XL, wobei die meisten Optionen aktiviert sind
Abbildung 10. TouchLatency läuft auf Pixel XL (die meisten Optionen aktiviert, einschließlich mdss- und kgsl-Tracepoints)

Wenn Sie nach Jank suchen, überprüfen Sie die Zeile „FrameMissed“ 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 hängt FrameMissed damit zusammen, dass SurfaceFlinger eine seiner äußerst regelmäßigen Laufzeiten verpasst und die Anzahl der ausstehenden Puffer für die App ( com.prefabulated.touchlatency ) bei einem Vsync unverändert bleibt.

FrameMissed-Korrelation mit SurfaceFlinger
Abbildung 11. FrameMissed-Korrelation mit SurfaceFlinger

Abbildung 11 zeigt einen verpassten Frame bei 15598,29&nbps;ms. SurfaceFlinger wachte im Vsync-Intervall kurz auf und ging wieder in den Ruhezustand, ohne etwas zu tun, was bedeutet, dass SurfaceFlinger zu dem Schluss kam, dass es sich nicht lohnt, erneut zu versuchen, einen Frame an das Display zu senden. Warum?

Um zu verstehen, wie die Pipeline für diesen Frame zusammengebrochen ist, sehen Sie sich zunächst das Arbeitsframe-Beispiel oben an, um zu sehen, wie eine normale UI-Pipeline in Systrace aussieht. 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, sind es zwei Frames (ein guter Hinweis, um herauszufinden, was vor sich geht).

SurfaceFlinger wacht auf und geht sofort schlafen
Abbildung 12. SurfaceFlinger wacht auf und geht sofort schlafen

Da es in SurfaceFlinger Frames gibt, handelt es sich nicht um ein App-Problem. Darüber hinaus wacht SurfaceFlinger zum richtigen Zeitpunkt auf, sodass es sich nicht um ein SurfaceFlinger-Problem handelt. Wenn sowohl SurfaceFlinger als auch die App normal aussehen, liegt wahrscheinlich ein Treiberproblem vor.

Da die mdss und sync -Tracepoints aktiviert sind, können wir Informationen über die Zäune (gemeinsam zwischen dem Anzeigetreiber und SurfaceFlinger) abrufen, die steuern, wann Frames an die Anzeige übermittelt werden. Diese Zäune werden unter mdss_fb0_retire aufgelistet, was angibt, wann ein Frame auf dem Display angezeigt wird. Diese Fences werden als Teil der sync Trace-Kategorie bereitgestellt. Welche Zäune bestimmten Ereignissen in SurfaceFlinger entsprechen, hängt von Ihrem SOC und Treiberstapel ab. Arbeiten Sie daher mit Ihrem SOC-Anbieter zusammen, um die Bedeutung der Zaunkategorien in Ihren Spuren zu verstehen.

mdss_fb0_retire Zäune
Abbildung 13. mdss_fb0_retire Zäune

Abbildung 13 zeigt einen Frame, der 33 ms lang angezeigt wurde, nicht wie erwartet 16,7 ms. In der Mitte dieses Abschnitts hätte dieser Rahmen durch einen neuen ersetzt werden sollen, was aber nicht der Fall war. Sehen Sie sich den vorherigen Frame an und suchen Sie nach etwas.

Rahmen vor kaputtem Rahmen
Abbildung 14. Rahmen vor dem kaputten Rahmen

Abbildung 14 zeigt 14,482 ms pro Frame. Das unterbrochene Zwei-Frame-Segment dauerte 33,6 ms, was ungefähr dem entspricht, was wir für zwei Frames erwarten würden (wir rendern mit 60 Hz, 16,7 ms pro Frame, was nahe kommt). Aber 14,482 ms sind überhaupt nicht annähernd 16,7 ms, was darauf hindeutet, dass mit der Anzeigeröhre etwas nicht stimmt.

Untersuchen Sie genau, wo dieser Zaun endet, um festzustellen, was ihn kontrolliert.

Zaunende untersuchen
Abbildung 15. Untersuchen Sie das Zaunende

Eine Arbeitswarteschlange enthält __vsync_retire_work_handler , der ausgeführt wird, wenn sich der Zaun ändert. Wenn Sie die Kernel-Quelle durchsehen, können Sie erkennen, dass es sich um einen Teil des Anzeigetreibers handelt. Es scheint sich auf dem kritischen Pfad für die Anzeigepipeline zu befinden und muss daher so schnell wie möglich ausgeführt werden. Es ist für etwa 70 us lauffähig (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 dies dazu beigetragen hat. Manchmal kann sich der Jitter im Laufe der Zeit summieren und schließlich dazu führen, dass eine Frist verpasst wird.

Vorheriger Frame
Abbildung 16. Vorheriger Frame

Die ausführbare Zeile auf dem kworker ist nicht sichtbar, da der Betrachter sie weiß färbt, wenn sie ausgewählt wird, aber die Statistiken sprechen eine deutliche Sprache: 2,3 ms Scheduler-Verzögerung für einen Teil des kritischen Pfads der Anzeigepipeline sind 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 -Thread verschieben. Diese Funktion benötigt Zeitgarantien, die Arbeitswarteschlangen nicht bieten können (und auch nicht bieten sollen).

Ist das der Grund für den Knall? Das lässt sich schwer abschließend sagen. Abgesehen von leicht zu diagnostizierenden Fällen wie Kernel-Sperrkonflikten, die dazu führen, dass anzeigekritische Threads in den Ruhezustand versetzt werden, geben Traces das Problem normalerweise nicht an. Könnte dieser Jitter die Ursache für den Frame-Ausfall gewesen sein? Absolut. Die Fence-Zeiten sollten 16,7 ms betragen, aber in den Frames vor dem Dropped Frame kommen sie überhaupt nicht annähernd daran heran. Angesichts der engen Kopplung der Anzeigepipeline ist es möglich, dass der Jitter um die Fence-Timings zu einem Bildausfall geführt hat.

In diesem Beispiel umfasste die Lösung die Konvertierung __vsync_retire_work_handler von einer Arbeitswarteschlange in einen dedizierten Kthread. Dies führte zu spürbaren Jitter-Verbesserungen und einem geringeren Ruckeln beim Hüpfball-Test. Nachfolgende Aufzeichnungen zeigen Zaunzeiten, die sehr nahe bei 16,7 ms liegen.