Debugging: Probleme Audioplayback

Hi Zusammen,

dachte ich separiere das mal aus dem dev-Branch, da es schon arg spezifisch ist, und mittlerweile in alle möglichen Richtungen geht.

Worum geht es:
bei bestimmten Konfigurationen oder durch Hinzufügen oder Ändern von Code an manchen Stellen wird die Audiowiedergabe (egal ob über Lautsprecher oder Kopfhörer) unterirdisch: ganz langsam und verzerrt.

Was hat bis jetzt Einfluss auf dieses Verhalten?

  • hinzufügen oder wegnehmen von Code an beliebigen Stellen (genaue Abhängigkeit noch nicht identifiziert)
  • Ändern von manchen Konfigurationen. Z.B. die Button-Zuweisung
  • Separieren des Audio-Loop-Calls in eigenen Task mit hoher Prio (positiver Einfluss)
  • Reduzierung der Last im loop-Task (manche Calls nur jedes n-Te mal - positiver Einfluss)
  • Entfernen mancher lokaler variablen (z.B. currentTimestamp in Button.cpp und diese direkt an der benötigten Stelle mit dem millis() call ersetzten (positiver Einfluss).

Gerade der letzte Punkt könnte auf ein Performance-Problem beim Task-Wechsel in bestimmten Situationen hindeuten, andere Ideen sind bis jetzt Hardwarezugriffe welche die CPU unterbrechen. Spannend ist vor allem, dass es von wenigen komplett beliebigen Zeilen Code abhängig ist.

Ich habe hier mal einen Branch erzeugt, bei dem ich auf dem neusten dev-branch mit ein paar Änderungen dieses Verhalten super reproduzieren kann und von wo aus man die verschiedenen Auswirkungen beobachten kann:

Hatte auch schon einfach leere Funktionen statt dem Code verwendet und konnte auch damit dieses Verhalten nachstellen, bin mir also ziemlich sicher, dass es (zumindest nicht direkt) an dem hinzugefügten Code liegt.

Wenn man die stats anschaut und drei Zustände vergleicht kommt man noch nicht so wirklich weiter. Bei identischen Ausgangsbedingungen sieht man dass der mp3play total unterschiedlich viel CPU-Anteile hat (Excel dazu und eine Beispiel MP3-Datei hänge ich mit an).

Bin über jede Idee zum weitern Eingrenzen Debuggen und letzendlich Lösen sehr dankbar :slight_smile: !
Viele Grüße
Joe
files.zip (2,5 MB)

Für mich klingt das ein bisschen nach einem Instruction-Caching-Problem.

Verdacht: Die parallel laufenden Tasks bringen insgesamt mehr Code mit, als in den Instruction-Cache passt. Das heißt es kommt während der Ausführung zu Cache-Misses und Code muss mit hoher Latenz aus dem SPI Flash nachgeladen werden. Je nachdem welchen Code es „trifft“ (z. B. Audio-Task) kann das zu hörbaren Verzögerungen beim Dekodieren und Abspielen der Audio-Datei kommen. Durch Änderungen am Code vollkommen ohne Bezug zum Audio-Task, kann das Phänomen verschwinden oder erscheinen, weil sich die Stelle an der der Cache-Miss auftritt in einen kritischen oder unkritischen Bereich verschiebt.

Das ist zumindest eine mögliche Theorie. Es kann auch eine völlig andere Ursache geben. :wink:

Ich habe mal testweise den ganzen Audio-Task in den IRAM gelegt und kann damit aktuell das Problem nicht mehr reproduzieren. Das kann aber auch Zufall sein.

--- a/src/AudioPlayer.cpp
+++ b/src/AudioPlayer.cpp
@@ -347,7 +347,7 @@ public:
 };
 
 // Function to play music as task
-void AudioPlayer_Task(void *parameter) {
+void IRAM_ATTR AudioPlayer_Task(void *parameter) {
 #ifdef BOARD_HAS_PSRAM
        AudioCustom *audio = new AudioCustom();
 #else
1 „Gefällt mir“

Sehr cool! Klingt erstmal super plausibel.
Grade zuletzt hatte ich einfach ein paar Zeilen fürs debugging eingefügt und schon war es wieder weg.
Da Iram ja immer knapp ist:
Ist es sinnvoll den Audio-task auf die Loop zu reduzieren und den Rest in den Cyclic call zu verschieben?
Hast du angeschaut wie viel iram dadurch zusätzlich benötigt wird?
Werde das vermutlich morgen nochmal ausgiebig testen.

Wie gesagt, das ist alles noch sehr spekulativ und kann auch völliger Quatsch sein. Weitere Tests sind also auf jeden Fall notwendig. Wenn du damit mal spielen könntest wäre das super.

Den ganzen Task ins IRAM zu legen ist sicher keine gute Lösung. Hat mich ehrlich gesagt gewundert, dass es überhaupt rein gepasst hat. Ich hab mir die IRAM Nutzung noch nicht angeschaut.

Wenn sich das als Ursache wirklich bestätigt, müsste man also schauen wo die kritischen Codeabschnitte sind, die ins IRAM müssten. Vielleicht stellt sich auch heraus, dass der Fix eigentlich in die Audio-Lib gehört.

4 „Gefällt mir“

Kann gut sein, dass wir diese Probleme mit potentiellen Cache-misses erst dadurch haben, dass wir das RTOS nicht mehr im IRAM haben. Dadurch wird potentiell viel instruction-cache mit OS-Zeug gefüllt sein…

1 „Gefällt mir“

Das wäre ein mögliche Ursache. Gibt es eine Möglichkeit das zu bestätigen?

Ich denke aber eher in Richtung Taskverteilung oder Hardwarezugriffe die den Ablauf/Audiowiedergabe blockieren. Insbesondere der Port-Expander wird periodisch abgefagt. Es gibt dazu einen frischen PR die Zugriffszeit zu halbieren. PE läuft ja im Hauptthread im Core 1.
Setze ich den Code in Dein Projekt ein wird Audio wieder sauber wiedergegeben.
Könnt Ihr das bestätigen? Interessant wäre dann ob es bei kleinen Codeänderungen auch so bleibt…

Stimmt, daran hatte ich noch nicht gedacht. Damit könnte es natürlich auch zu tun haben.

Wo findet sich denn die Stelle, wo der Thread von Core 0 auf Core 1 verschoben wird? Ich habe bisher immer nur gelesen, dass der loop-Thread auf Core 0 mit Prio 1 läuft. Und dann sollten sich die beiden Tasks gar nicht in die Quere kommen.

Eine Möglichkeit wäre noch denkbar, nämlich dass ein Interrupt immer erst beide Cores unterbricht. Dann würde die Änderung im PR, dass praktisch nur noch auf den I2C zugegriffen wird, wenn sich wirklich was am PE geändert hat, tatsächlich (etwas) helfen.

Aber allgemein vermute ich auch, dass die Ursache eher hier liegt:

Ich weiß nicht, ob der Prozessor intelligent genug ist zu erkennen, dass Instructions aus dem internen RAM nicht in den Instruction-Cache muss. Aber wenn nicht, dauert bei einem Cache-Miss das Lesen aus dem internen RAM nicht so lange wie aus dem externen Flash oder RAM.
Und den Scheduler, das Handling von Queues, Mutexen usw. möchte man eher nicht aus langsamem Speicher holen.

Ist aktuell wieder sehr schwer hier direkte Aussage zu treffen was was bringt, da man wenn überhaupt viel herumspielen muss bis man zufällig wieder so einen Stand reproduzieren kann. Man weiß nie, ob es jetzt gut ist weil man das Problem angegangen ist, oder einfach nur weil es sich verschoben hat und jetzt (sollte es daran liegen) der I-Cache weniger misses hat. Vom IRAM her kostest es uns 4.472 Bytes den kompletten Audio-Task ins IRAM zu schieben. Ist schon viel, aber passt aktuell gut rein.

@36b6fp6s
Über die sdkconfig wird definiert, dass Arduino auf Core 1 läuft (default). Man kann das aber entsprechend umändern auf Core 0 per menuconfig.
Tatsächlich sind die ipc-Tasks genau das, dass z.B. beim Zugriff auf eine Resource der jeweils andere Core kurz pausiert wird wenn ich es richtig verstanden habe. Hier sieht man allerdings in den Stats keine übermäßigen anstiege.

Das Grundproblem ist das sehr limitierte IRAM (siehe Memory Types - ESP32-S2 - — ESP-IDF Programming Guide latest documentation)
Da wir viele Libs verwenden die hier schon ganz gut sich bedienen müssen wir irgendwo IRAM sparen und von den Optionen die von Haus aus kommen (Minimizing RAM Usage - ESP32-S2 - — ESP-IDF Programming Guide latest documentation) ist das Placen des RTOS ins Flash die einfachste, die viel einspart und zumindest als wir es damals untersucht hatten keine negativen Auswirkungen hat.
Wenn wir andere Wege finden genügend IRAM freizuschaufeln, dass wir genügend Luft haben und keine noch dümmeren Kompromisse eingehen müssen, wäre es natürlich schöner das OS im IRAM zu haben.

Besonders attraktiv für aktuelle Boards wäre natürlich die Option die min Rev der Boards auf V3 zu setzten (spart viel Speicher, unter anderem auch viel IRAM), das ist aber halt keine allgemeingültige Lösung.

Wo findet sich denn die Stelle, wo der Thread von Core 0 auf Core 1 verschoben wird? Ich habe bisher immer nur gelesen, dass der loop-Thread auf Core 0 mit Prio 1 läuft. Und dann sollten sich die beiden Tasks gar nicht in die Quere kommen.

Ich meine Arduino loop() läuft auf Core 1, siehe z.B. hier.
Da der PortExpander zyklisch in der Main-Loop aufgerufen wird bringt der (gerade übernommene) optimierte Code direkt mehr Rechenzeit für Core 1. Und hier läuft Audio.

Es bringt nur wenig Zeit, denn während ein I2C-Transfer läuft, ist der aufrufende Thread suspended und wartet darauf, vom I2C-Interrupt wieder geweckt zu werden. Die Zeit steht dann anderen Threads zur Verfügung. Der Main-Thread wird nur seinen Zyklus eher beenden, die benötigte Prozessorzeit ist dagegen nur geringfügig verändert (hauptsächlich wird der Overhead von 3 bzw. 4 Interrupts gespart).
Solange der Audio-Thread eine höhere Prio als der Main-Thread hat, müsste er auch immer Prozessorzeit bekommen, wenn er sie braucht, egal was der Main-Thread macht. Es sei denn, der FreeRTOS-Scheduler versucht sich an Fairness oder er hat nur eine feste Zahl an Zeitschlitzen pro Sekunde zur Verfügung. Letzteres würde aber das Problem entweder immer oder nie zeigen. Und Fairness gehört sich nicht in einem RTOS.

2 „Gefällt mir“