Probleme mit Bluetooth Kopfhörern

Software
1

Hallo, zu Weihnachten gabs für meinen Kleinen Kopfhörer für seinen ESPuino, da er vor allem auf Autofahrten gerne genutzt wird. Habe sie auch verbunden bekommen und prinzipiell kommt auch Ton raus. Allerdings gibt es ein paar Problemchen welche es in Summe doch zu einem schwierigen Erlebnis machen, vor allem für einen Zweijährigen:

  • Audio SampleRate scheint nicht zu passen: Es scheint mir so, als würde der Bluetooth stream immer mit 44100 KHz abgespielt werden. mp3s die mit 44100 KHz gesampelt wurden, klingen ok. Andere mit 48000 KHz werden etwas zu langsam abgespielt.
  • Crashes beim Verbinden und Trennen: Wenn ich die Kopfhörer ein- bzw ausschalte, gibt’s gefühlt ne 50% Chance, dass der ESPuino neu startet. Beim Einschalten/Verbinden etwas weniger oft, beim Ausschalten/Trennen dafür meistens.
  • Freezes beim Ende der Playlist: Wenn die aktuelle play queue zu Ende ist, während Bluetooth Kopfhörer verbunden sind, friert das Ding öfters ein und es ist ziemlich schwer es dann neu zu starten, da auch Tasten des Öfteren nicht mehr, bzw nur extrem träge reagieren.

Während das Problem mit der SampleRate für den Kleinen wohl noch nicht so tragisch ist, und auch durch resampeln aller Dateien zu umgehen ist, sind die Crashes um so mehr ein Problem, da er noch nicht in der Lage ist die LED Farb-codes zu interpretieren um zu wissen was er machen soll.

Hier zb ein crash beim Einschalten der Kopfhörer:

I [51170] Bluetooth source => connection state: Connecting
assert failed: hash_map_set hash_map.c:129 (data != NULL)

Backtrace: 0x400855e9:0x3fff10a0 0x40098445:0x3fff10c0 0x4009d115:0x3fff10e0 0x4013b2f5:0x3fff1210 0x40130d31:0x3fff1230 0x401330b2:0x3fff1250 0x40135071:0x3fff1280 0x4012f709:0x3fff12b0 0x40132efd:0x3fff12e0 0x40135f85:0x3fff1310 0x40130b54:0x3fff1480 0x4013ba33:0x3fff14a0

ELF file SHA256: ad6424adf7ac30af

E (418) esp_core_dump_flash: Core dump flash config is corrupted! CRC=0x7bd5c66f instead of 0x0
Rebooting...

Ich wollte grad mal etwas debuggen, vielleicht finde ich ja was, bin allerdings relativ unerfahren was ESP32/Arduino SDK betrifft. Hat jemand tipps wie ich obigen Backtrace aufgeschlüsselt bekomme bzw andere Anhaltspunkte für Tests/Logs die hilfreich sein könnten die Crashes zu finden?

(Alle diese Probleme treten hier sowohl mit master als auch mit dev auf)

1 „Gefällt mir“
2

Das klingt ja nicht nach einer guten Benutzererfahrung deines Kindes ;-(

  • Die 44KHZ Samplerate ist zwingend notwendig sonst gibt es eine falsche Abspielgeschwindigkeit. Ist sozusagen Systemvoraussetzung!

Zum Crash kann ich nicht viel beitragen, scheint tief unten im ESP-IDF zu passieren. Normalerweise erhalten wir einen Crashdump mit Aufrufstack.
Evt. hift es set_auto_reconnect(true) hier zu setzen?

Der Autor schreibt dazu aber auch:

Please note that when you just restart the ESP32, you might end up in the situation where you can’t reconnect to the Bluetooth Speaker, because it did not notice that the connection got lost. To prevent this you need either properly end A2DP via the API or restart your speaker. This is issue is independent on the set_auto_reconnect setting selected above!

3

Stimmt… Ich habe zwischenzeitlich den code der ESP-A2DP lib durchstöbert und auch festgestellt, dass es da keine Möglichkeit gibt, die SampleRate umzustellen… Dann werde ich wohl mal noch die restlichen Dateien resampeln.

Bzgl dem set_auto_reconnect, ich kanns schon mal versuchen, wobei der Versuch zu einem Gerät zu verbinden schon ziemlich gut funktioniert. Also wann immer keine Kopfhörer verbunden sind, sehe ich zyklisch die logs, dass es versucht wird. Wenn ich die Kopfhörer einschalte klappt das auch super, sie werden schnell gefunden und verbunden. Das Problem ist eben, dass direkt nachdem die Verbindung aufgebaut/getrennt wurde, die Box crasht/neu startet.

Die letzte Anmerkung, dass die Kopfhörer noch in einem Zustand schweben wenn die Verbindung abbricht und deshalb nicht neu Verbunden werden können, kann ich sowohl bestätigen als auch ausschließen. Dieses Modell hat nämlich ne akustische Ansage ob sie „Connected“ „Disconnected“ oder „Ready to pair“ sind. Also, ja, manchmal gibt’s diesen Zustand für bis zu ca 20 Sekunden, aber in den Tests weiß ich durch diese Ansage ziemlich genau wann das der Fall ist.

Das wäre interessant. Frage mich warum das hier nicht klappen will. Bin noch nicht fündig geworden.

4

Ich kann den Crash jetzt relativ gut nachvollziehen:

  • Wenn ich den Kopfhörer verbinde und erst danach Musik abspiele funktioniert Alles wie gewünscht
  • Läuft bereits Musik und ich verbinde dann den Kopfhörer crasht es sofort nach der Verbindungsherstellung

Ich bekomme auch einen detailierten Crashlog:

I [55563] Bluetooth source => connection state: Connected

assert failed: hash_map_set hash_map.c:129 (data != NULL)


Backtrace: 0x400855e9:0x3fff11c0 0x40098445:0x3fff11e0 0x4009d115:0x3fff1200 0x4013ad99:0x3fff1330 0x401307d5:0x3fff1350 0x40132b56:0x3fff1370 0x40134b15:0x3fff13a0 0x4012f1ad:0x3fff13d0 0x401329a1:0x3fff1400 0x40135a29:0x3fff1430 0x401305f8:0x3fff15a0 0x4013b4d7:0x3fff15c0

  #0  0x400855e9:0x3fff11c0 in panic_abort at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/esp_system/panic.c:408
  #1  0x40098445:0x3fff11e0 in esp_system_abort at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/esp_system/esp_system.c:137
  #2  0x4009d115:0x3fff1200 in __assert_func at C:\Users\dcars\.platformio\packages\framework-espidf@3.40406.0\components\newlib/assert.c:85
  #3  0x4013ad99:0x3fff1330 in hash_map_set at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/common/osi/hash_map.c:129 (discriminator 1)
  #4  0x401307d5:0x3fff1350 in btu_start_timer at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/btu/btu_task.c:435
  #5  0x40132b56:0x3fff1370 in l2c_csm_term_w4_sec_comp at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:404
      (inlined by) l2c_csm_execute at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:78
  #6  0x40134b15:0x3fff13a0 in l2c_link_sec_comp at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_link.c:334
  #7  0x4012f1ad:0x3fff13d0 in btm_sec_l2cap_access_req at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/btm/btm_sec.c:2197
  #8  0x401329a1:0x3fff1400 in l2c_csm_closed at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:249
      (inlined by) l2c_csm_execute at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:70
  #9  0x40135a29:0x3fff1430 in process_l2cap_cmd at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_main.c:674
      (inlined by) l2c_rcv_acl_data at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/l2cap/l2c_main.c:228
  #10 0x401305f8:0x3fff15a0 in btu_hci_msg_process at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/host/bluedroid/stack/btu/btu_task.c:144
  #11 0x4013b4d7:0x3fff15c0 in osi_thread_run at C:/Users/dcars/.platformio/packages/framework-espidf@3.40406.0/components/bt/common/osi/thread.c:165

BT: Show free heap after state changed · biologist79/ESPuino@efeb0fa · GitHub gibt jetzt im Log bei BT-Statusänderung den freien Heapspeicher aus & siehe da es scheint zu wenig Heap vorhanden zu sein.

Wenn noch keine Musik läuft:

I [32831] Bluetooth source => connection state: Connected (Free heap: 33300 Bytes)
I [40892] Bluetooth source => audio state: Started (Free heap: 29488 Bytes)

Wenn bereits Musik abgespielt wird:

I [60882] Bluetooth source => connection state: Connecting (Free heap: 8108 Bytes)
I [61514] Bluetooth source => connection state: Connected (Free heap: 5188 Bytes)

assert failed: hash_map_set hash_map.c:129 (data != NULL)

5KB freier Heap ist schon arg wenig & könnte Ursache für den Crash sein.
Mich wundert aber der Unterschied keine Musik/Musik abgespielt, am Ende ist doch vom Speicher Alles gleich? Könnt Ihr das so bestätigen?

5

Ich habe mir den Stack Trace mal zur Gemüte geführt. Wir sterben nach dem Aufruf dieser Funktion:

    // Get the alarm for the timer list entry.
    osi_mutex_lock(&btu_general_alarm_lock, OSI_MUTEX_MAX_TIMEOUT);
    if (!hash_map_has_key(btu_general_alarm_hash_map, p_tle)) {
        alarm = osi_alarm_new("btu_gen", btu_general_alarm_cb, (void *)p_tle, 0);
--->    hash_map_set(btu_general_alarm_hash_map, p_tle, alarm);
    }
    osi_mutex_unlock(&btu_general_alarm_lock);

Und hier die Funktion osi_alarm_new. Der ruft alarm_cbs_lookfor_available, dieser macht aber kein malloc, sondern durchsucht das Array alarm_cbs nach einem freien Slot für ein Alarm (was genau das macht, keine Ahnung).

Kannst du CONFIG_BT_LOG_OSI_TRACE_LEVEL auf Debug (d.h. CONFIG_BT_LOG_OSI_TRACE_LEVEL_DEBUG) erhöhen? Dann bekommen wir die ausgaben von den Makros OSI_TRACE_DEBUG.

Der wenige freie Speicher ist besorgniserregend, aber meine erste Vermutung ist nicht, dass wir hier speziell daran sterben.

6

Das mit dem Debug hat schon mal geklappt:

[ 43486][D][BluetoothA2DPSource.cpp:635] process_user_state_callbacks(): [BT_AV] process_user_state_callbacks ESP_A2D_CONNECTION_STATE_EVT: Connected
I [43499] Bluetooth source => connection state: Connected (Free heap: 6548 Bytes)
[ 43510][D][BluetoothA2DPSource.cpp:716] bt_app_av_state_connecting_hdlr(): [BT_AV] bt_app_av_state_connecting_hdlr evt 0
[ 43517][I][BluetoothA2DPSource.cpp:724] bt_app_av_state_connecting_hdlr(): [BT_AV] a2dp connected

E (46107) BT_OSI: osi_alarm_new failed to create timer, err 0x101


assert failed: hash_map_set hash_map.c:129 (data != NULL)

(0x101) → ESP_ERR_NO_MEM : Out of memory

Aber wo bleiben die 25KB je nach Audio/BT Startreihenfolge?

7

I stand corrected :slight_smile:

Die ~25k sind bei der Audio Klasse. Die Musikwiedergabe kann ja auch starten, ohne dass ein BT Headphone verbunden ist (niemand hälte den AudioPlayer davon ab :slight_smile: ).

Ich habe eine Ausgabe in der loop gemacht im 500ms Intervall. Das spamt zu aber es erlaubt einen genaueren Blick, zB wann der Heap ausgeht:

#include <FastLED.h>
void loop() {

	// am Ende einfügen
	static CEveryNMillis show(500);
	if (show) {
		log_n("Heap: %u (m: %u), SPRAM: %u (m: %u)", 
				heap_caps_get_free_size(MALLOC_CAP_INTERNAL | MALLOC_CAP_DEFAULT), 
				heap_caps_get_largest_free_block(MALLOC_CAP_INTERNAL | MALLOC_CAP_DEFAULT), 
				heap_caps_get_free_size(MALLOC_CAP_SPIRAM | MALLOC_CAP_DEFAULT), 
				heap_caps_get_largest_free_block(MALLOC_CAP_SPIRAM | MALLOC_CAP_DEFAULT));
	}
}

Bei mir habe ich folgende Werte:

Variante 1: Bluetooth dann MP3

[  6573][E][main.cpp:275] loop(): Heap: 40520 (m: 36852), SPRAM: 4118831 (m: 4063220)
I [6848] Bluetooth source => Device found: Fairphone Earbuds
[  8573][E][main.cpp:275] loop(): Heap: 33352 (m: 29684), SPRAM: 4122959 (m: 4063220)
I [11081] Bluetooth source => audio state: Started (Free heap: 36608 Bytes, extRam: 4122959)
[ 11576][E][main.cpp:275] loop(): Heap: 30160 (m: 28660), SPRAM: 4122959 (m: 4063220)
[...]
I [14199] info        : MP3Decoder has been initialized, free Heap: 8700 bytes , free stack 2948 DWORDs
[...]
[ 16512][E][main.cpp:275] loop(): Heap: 2208 (m: 1972), SPRAM: 3466815 (m: 3342324)

Variante 2: MP3 dann Bluetooth

[  3573][E][main.cpp:275] loop(): Heap: 40532 (m: 36852), SPRAM: 4118831 (m: 4063220)
N [3990] RFID-Karte erkannt: 92-8a-7c-1d 
[...]
I [4089] info        : MP3Decoder has been initialized, free Heap: 19072 bytes , free stack 2952 DWORDs
[...]
[4646][E][main.cpp:275] loop(): Heap: 12448 (m: 10228), SPRAM: 3462687 (m: 3342324)
I [5555] Bluetooth source => Device found: Fairphone Earbuds
I [5562] Bluetooth source => connection state: Connecting (Free heap: 14944 Bytes, extRam: 3466815)
[5606][E][main.cpp:275] loop(): Heap: 8792 (m: 8180), SPRAM: 3466815 (m: 3342324)
I [6050] Bluetooth source => connection state: Connected (Free heap: 12040 Bytes, extRam: 3466815)
[6109][E][main.cpp:275] loop(): Heap: 3460 (m: 3188), SPRAM: 3466815 (m: 3342324)

assert failed: hash_map_set hash_map.c:129 (data != NULL)

Was man hier schön sieht, dass uns jedes Mal der interne Speicher ausgeht. Wir haben bei Variante 1 das „glück“, dass wir während der Wiedergabe keine großen Blöcke reserviert werden müssen.

Wieso wir auch mit dem externen SPIRAM noch immer den internen priorisieren, kann ich nicht sagen. Das sollten wir auf jeden Fall mal anschauen.
Gruß,
Laszlo

1 „Gefällt mir“
8

Hm, hab eine mögliche Lösung für unser Problem. CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL ist auf 4096 gesetzt, d.h. jedes malloc, das kleiner als 4k ist kommt in den internen Speicher. Hab den Config auf 0 gesetzt. Damit werden alle Speicherblöcke mit malloc im SPIRAM allokiert (außer sie sind speziell, wie zB für DMA).

Damit bekomme ich bei der Variante 2 folgende RAM-Ausgabe:

[  7590][E][main.cpp:275] loop(): Heap: 81504 (m: 77812), SPRAM: 4077875 (m: 4063220)
N [7967] RFID-Karte erkannt: 92-8a-7c-1d 
[...]
[  8093][E][main.cpp:275] loop(): Heap: 57616 (m: 55284), SPRAM: 3417135 (m: 3407860)
[...]
[  8596][E][main.cpp:275] loop(): Heap: 57616 (m: 55284), SPRAM: 3417135 (m: 3407860)
I [16795] Bluetooth source => Device found: Fairphone Earbuds
I [16800] Bluetooth source => connection state: Connecting (Free heap: 64588 Bytes, extRam: 3417415)
[ 17563][E][main.cpp:275] loop(): Heap: 57568 (m: 55284), SPRAM: 3417547 (m: 3407860)
I [18018] Bluetooth source => connection state: Connected (Free heap: 64252 Bytes, extRam: 3414787)
[ 21072][E][main.cpp:275] loop(): Heap: 57712 (m: 57332), SPRAM: 3410767 (m: 3407860)
I [21078] Bluetooth source => audio state: Started (Free heap: 64156 Bytes, extRam: 3411411)
[ 21632][E][main.cpp:275] loop(): Heap: 57136 (m: 55284), SPRAM: 3411443 (m: 3407860)

Ob wir davon Nebenwirkungen haben werden, müssen wir testen. Zumindest bei einer 5 Minuten Tests scheint es keine Probleme zu verursachen (Uploads & Musikwiedergabe gehen wie erwartet).

6 „Gefällt mir“
9

Ich kann bestätigen das mit dieser Einstellung Bluetooth-Kopfhörer & alle anderen Dinge einwandfrei funktionieren, auf den ersten Blick eine tolle Lösung!

@laszloh und Du hast so ganz nebenbei die „Heapspeicher Flaschenhals Handbremse“ gelöst? Weil der verfügbare Heapspeicher hat sich jetzt mehr als verdoppelt. Das ist schon ein Kracher:

grafik
grafik1078×570 50.4 KB

Bitte an alle Early-Birds ändert doch in der sdkconfig.defaults
CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=0 und testet mal. Wäre noch interessant ob dies die Arduino-Standardeinstellung ist & ob das sonst noch Auswirkungen hat?

3 „Gefällt mir“
10

Wow. Hab mit diesem setting jetzt die Kopfhörer bei laufendem Stream sicher 20 mal verbunden und getrennt. Kein Crash, alles funktioniert wie erwartet.

Vielen Dank schon mal für die Mühe, werde das mal so weiter beobachten, aber sieht schon mal ganz gut aus!

11

Wenn ich mich richtig erinnere ist unsere ursprüngliche sdkconfig von Arduino abgeleitet. D. h. alles was wir nicht geändert haben sollte so wie bei Arduino (zum Zeitpunkt als wir die sdkconfig angelegt haben) sein.

12

https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/kconfig.html#config-spiram-malloc-alwaysinternal

Hier mal der Link zur Doku…

CONFIG_SPIRAM_TRY_ALLOCATE_WIFI_LWIP klingt auch noch interessant für uns…