Visualisierung von Antwortzeiten in FreeRTOS

Die effiziente Entwicklung von auf FreeRTOS basierender Firmware setzt voraus, dass das Timing und die Interaktionen zwischen Tasks, Interrupts und Kernel genau bekannt sind. Wie lassen sich diese aber in Software-Tests visuell darstellen und nachvollziehbar machen?

Anbieter zum Thema

Axivion GmbH

RTI Real-Time Innovations

Percepio sammelt und reproduziert Beispiele dafür, wie Tracealyzer von den Kunden an realen Problemen eingesetzt wurde. In dem hier vorliegenden Fall entwickelte ein Kunde ein vernetztes System, auf dem ein TCP/IP-Stack, ein Flash-Dateisystem und ein RTOS auf einem ARM Cortex-M4-Mikrocontroller liefen. Das System enthielt mehrere RTOS-Tasks, darunter eine serverähnliche, auf Anfragen aus dem Netzwerk reagierende Task und eine Log-File-Spooler-Task. Die Antwortzeit auf Netzwerk-Anfragen hatte sich oftmals als Problem erwiesen, und beim Testen des letzten Builds hatte das System sogar noch langsamer reagiert als bisher. Diesem Problem wollte das Unternehmen deshalb jetzt auf den Grund gehen.

Hierfür kam der Percepio Tracealyzer zum Einsatz. Als Lösung zum Analysieren und Visualisieren FreeRTOS-basierter Embedded-Software zeigt Percepio Tracealyzer verschiedene Aspekte des Echtzeitverhaltens der jeweiligen Software mithilfe von mehr als 25 grafischen Ansichten, die sich intelligent verknüpfen lassen und intuitiv zu verwenden sind.

Bildergalerie

Bildergalerie mit 6 Bildern

Vergleich der Aufruf- und Antwortzeiten der FreeRTOS-Tasks

Naheliegenderweise verglich man zunächst die Codes der beiden Versionen, aber auf den ersten Blick war kein Grund für die längere Antwortzeit erkennbar. Wegen des Refactorings gab es zwar zahlreiche kleine Änderungen, aber neue Funktionen waren nicht hinzugekommen. Man entschied deshalb, Tracealyzer einzusetzen, um das Laufzeitverhalten der vorigen Version und der neuen Version miteinander zu vergleichen.

Nachdem unter ähnlichen Bedingungen Traces von beiden Versionen aufgezeichnet worden waren, begann man mit Vergleichen im Statistics Report (Bilder 2a und 2b), der übergeordnete Timing-Statistiken beispielsweise zur CPU-Auslastung, zur Zahl der Ausführungen, zu den Scheduling-Prioritäten und zu den Antwortzeiten enthält.

Wie zu erwarten war, ließ der Statistics Report erkennen, dass die Antwortzeiten für die Server-Task in der neuen Version länger ausfielen, und zwar um durchschnittlich 50 %. Allerdings war auch zu erkennen, dass die Verarbeitungszeiten der Server-Task (also die Zahl der tatsächlich genutzten Zyklen) recht ähnlich waren und in der neuen Version nur um rund 7 % höher lagen. Der Hauptgrund für die längeren Antwortzeiten musste deshalb in anderen Tasks liegen, die die Ausführung behindern.

Darstellung der Tasks in der Trace-Hauptansicht

Um herauszufinden, was die Ursache für die längeren Antwortzeiten war, muss man einfach nur die Extremwerte im Statistics Report anklicken. Hierdurch wird die Haupt-Traceansicht auf die entsprechenden Stellen fokussiert, wodurch die Details erkennbar werden, wie unten gezeigt. Öffnet man jetzt zwei parallele Tracealyzer-Instanzen – eine pro Trace –, so werden die Unterschiede gut erkennbar (vgl. Bilder 3a und 3b).

Da die Applikationsserver-Task mehrere Dienste ausführte, wurden zwei User Events hinzugefügt, um die Punkte zu markieren, an denen die jeweiligen Anfragen empfangen und beantwortet werden (in den Bildern 2a und 2b mit ‘serverLog’ bezeichnet). Da der Zoomfaktor in beiden Abbildungen identisch ist, sind die längeren Antwortzeiten der neuen Version deutlich zu sehen. Ebenso ist zu erkennen, dass die Logger-Task die Server-Task ganze elf Mal anhält, während es bei der vorigen Version nur sechs Mal waren – ein erheblicher Unterschied. Sichtbar ist überdies, dass die Logger-Task mit höherer Priorität läuft als die Server-Task, weshalb jeder Logging-Aufruf die Server-Task anhält.

Es scheint also, als wären in der neuen Version neue Logging-Aufrufe hinzugekommen, die zur Folge haben, dass die Logger-Task die Server-Task stärker behindert.

Optimierung der Leistungsfähigkeit

Um zu erkennen, was geloggt wird, muss nur ein User Event in die Logger-Task eingefügt werden, damit die Nachrichten in der Trace-Ansicht zu sehen sind (siehe Bild 4). Vielleicht würden sich einige entfernen lassen, um die Leistungsfähigkeit zu verbessern?

Tut man dies, sieht man, dass auch andere Tasks Logging-Nachrichten generieren, so zum Beispiel die in Gelb dargestellte Task ADC_0. Um alle Tasks zu sehen, die Nachrichten an die Logger-Task senden, eignet sich das in Bild 5 gezeigte Kommunikations-Flussdiagramm.

Das Kommunikations-Flussdiagramm zeigt eine Übersicht über alle Operationen an Message Queues, Semaphoren und anderen Kernel-Objekten, die von Tasks und Interrupts im Trace ausgeführt werden. Hiermit werden in abstrakter Form die Design- und Konzept-Abhängigkeiten in den aufgezeichneten Situationen visualisiert.

Im vorliegenden Fall lässt der Kommunikationsablauf fünf Tasks erkennen, die Logging-Nachrichten senden. Durch einen Doppelklick auf den mit „LoggerQueue“ bezeichneten Knoten in der Grafik wird die Ansicht „Kernel Object History“ geöffnet, die sämtliche mit dieser Message Queue ausgeführten Operationen zeigt (Bild 6). Wie zu erwarten war, sieht man, dass die Logger-Task häufig einzelne Nachrichten erhält und nach jeder Nachricht blockiert wird (erkennbar an der roten „Ampel“).

Kann man dies als ein gutes Design bezeichnen? Wahrscheinlich ist es nicht notwendig, die Logging-Nachrichten einzeln in einer Datei abzuspeichern. Würden wir den Server-Tasks eine höhere Priorität zuweisen als der Logger-Task, würde die Server-Task nicht mehr so häufig angehalten und könnte somit schneller antworten. Die Logging-Nachrichten würden in der LoggerQueue gepuffert, bis die Server-Task (sowie alle anderen Tasks mit höherer Priorität) beendet ist. Erst dann würde die Logger-Task ihre Arbeit wieder aufnehmen und sämtliche gepufferten Nachrichten in einem Durchgang bearbeiten.

Das Ergebnis ist in Bild 7 zu sehen. Die längste Antwortzeit beträgt jetzt nicht mehr 7,5 ms, sondern nur noch 5,4 ms und ist damit sogar kürzer als in der vorigen Version (5,7 ms). Dies liegt daran, dass die Logger-Task die Server-Task jetzt nicht mehr anhält, sondern alle anstehenden Nachrichten in einem Rutsch verarbeitet, nachdem die Server-Task abgearbeitet ist.

Wir erkennen hier außerdem „Event Labels“ für die Message-Queue-Operationen. Wie zu erwarten war, kommen mehrere „xQueueSend”-Aufrufe nacheinander vor, ohne dass es zu Blockierungen (erkennbar an roten Labels) oder Task-Preemptions kommt. Zwar gibt es noch Preemptions durch die ADC-Tasks, jedoch stößt dies keine zusätzlichen Aktivierungen der Logger-Task an. Damit ist das Problem gelöst!

Visualisierung von RTOS-Tasks - wie funktioniert das?

Tracealyzer arbeitet mit softwaredefiniertem Tracing, was sehr flexibel ist und auf jedem Prozessor funktioniert. Zum Aufzeichnen eines Trace müssen man lediglich die Recorder-Bibliothek von Percepio in dem Build einbinden, konfigurieren und mit dem Tracing beginnen.

Der Mehraufwand beträgt lediglich wenige Mikrosekunden pro Event, und das Trace kann kontinuierlich per Debug-Probe, TCP/IP oder über andere Kanäle an den Host-Computer gestreamt werden. Ebenso ist es möglich, das Trace zunächst in einen RAM-Puffer im Zielsystem zu geben und nach Bedarf hochzuladen.

Software-Visualisierung und -Analytics: Stand der Technik und Perspektiven

Trace-Visualisierung beim Debugging von RTOS-Firmware

* Dr. Johan Kraft ist CEO und Gründer von Percepio AB

(ID:45962678)