ESP8266 audioreactive UDP sync ported from MoonModules/WLED

[gaaat98]

Tries to resolve #3960

However, it seems to be unstable on RGB(W) PWM strips at higher clock speeds, causing frequent reboots

[netmindz]

As I might not have an ESP8266 to hand when doing the code review, if you could please include a screenshot of the Audio Reactive settings, including the sync dropdown being expanded please

[gaaat98]

I have left the default ones

[softhack007]

@blazoncek question as I'm not very experienced with 8266 - sync receive polls for new UDP multicast packets each 20ms. This works well on esp32.

Maybe 8266 can have a problem with it? Do you think that adding 'yield()' before/after UDP calls might help?

Or maybe it's the frequent alloc/dealloc of fftBuff[packetsize] that causes stress on 8266 due to heap fragmentation? In fact a static buffer of 88 bytes (max xpected packet size) would be enough.

[blazoncek]

I think @willmmiles or @pbolduc will know much more about AsyncUDP/TCP than me.

fftBuff is allocated on stack as far as I can see. That shouldn't be a problem. @gaaat98 please provide crash dump using exception decoder with your WDT crash.

[gaaat98]

Excuse the dumb question, but how do I enable stack trace printing? The only thing I see on serial while resets occur is this:

Loop delayed more than 3ms.
Loop delayed more than 3ms.

 ets Jan  8 2013,rst cause:4, boot mode:(3,7)

wdt reset
load 0x4010f000, len 3424, room 16
tail 0
chksum 0x2e
load 0x3fff20b8, len 40, room 8
tail 0
chksum 0x2b
csum 0x2b
v000e0460
~ld
���'�{��n<�$�l b�|{�l�o��o�l ��{�d�l

�
---WLED 0.15.0-b3 2405030 INIT---
esp8266 @ 80MHz.
Core: 3.1.2
FLASH: 2 MB
heap 29072
PIN ALLOC: Pin 1 successfully allocated by 0x89 (137)
Registering usermods ...
heap 28984

[blazoncek]

-D WLED_DEBUG

(which you have) and

monitor_filters = esp8266_exception_decoder

in your PIO environment.

But perhaps 8266 does not support WDT exceptions and does not print stack dump.
It looks to me that it may be possible that there is some loop that iterates across too many iterations (like -1 becoming 65535 when doing int16_t conversion to uint16_t).

[pbolduc]

One of the biggest issues is the Espressif networking stack has problems with high UDP traffic rates. It has been a while since I looked at the networking. I found this issue espressif/arduino-esp32#4104 which talks about errors with the parsePacket function. I need a reminder where the WifiUDP library comes from in WLED.

[willmmiles]

I need a reminder where the WifiUDP library comes from in WLED.

WifiUDP is part of the Arduino framework on ESP8266 and ESP32. (The E131 receiver elsewhere in the project is using the ESPAsyncUDP library, which is not part of the framework.)

My quick read of the WifiUDP framework code on ESP8266 suggests it's reasonably well written. By contrast, the ESP32 version is awful, heap allocating and freeing full 1460 byte packet buffer every time it polls to see if there's a new packet(!!).

I pulled this PR in to my web server stability working branch and I haven't been able to reproduce the fault yet. It's neat to see the AR effects working on an 8266 again, though it's noticably laggy compared to the other ESP8266 running as a DDP segment beside it.

@gaaat98 would you mind posting your config, in case there's something non-obvious I've got configured differently?

[softhack007]

I pulled this PR in to my web server stability working branch and I haven't been able to reproduce the fault yet

@willmmiles I think the problem is is happening with analog (PWM) strips only - may also happening with bitbang ws2812 drivers. So I suspects it's a timing issue, or simply the 8266 is overloaded when doing high freq PWM (interrupt driven) + UDP polling + WiFi + other stuff.

Besides UDP polling, audioreactive runs a linear filter (no loops) then simply copies received data to the variables used in effects. So audioreactive on 8266 does "almost nothing" in addition to UDP.

[gaaat98]

@willmmiles Here's the configuration on my athom controller (esp8285), on this board the crashes happen after a few updates when the clock speed is set to values higher than 'Slowest' (the effect I tested was DJ Light but I assume also the others will do the same).

This is the config of a ESP8266 board I used for testing, here the crashes are a bit less frequent but still happen. I noticed that if I open the /liveview page on a browser the number of reboots noticeably increases, which suggests that the boards crash due to overload.

These are both configured as PWM strips, I also have another athom controller connected to SK6812 strip with UDP sync enabled that shows no such issues

[blazoncek]

@gaaat98 please get a plain D1 mini board, configure it as an Athom controller and monitor serial output.
It is important if the crashes are caused by watchdog or something else.

[gaaat98]

@blazoncek That's basically what I did to obtain this log, the only difference is that I used a NodeMCU ESP8266 instead of D1 Mini, is that relevant?

Loop delayed more than 3ms.
Loop delayed more than 3ms.

 ets Jan  8 2013,rst cause:4, boot mode:(3,7)

wdt reset
load 0x4010f000, len 3424, room 16
tail 0
chksum 0x2e
load 0x3fff20b8, len 40, room 8
tail 0
chksum 0x2b
csum 0x2b
v000e0460
~ld
���'�{��n<�$�l b�|{�l�o��o�l ��{�d�l

�
---WLED 0.15.0-b3 2405030 INIT---
esp8266 @ 80MHz.
Core: 3.1.2
FLASH: 2 MB
heap 29072
PIN ALLOC: Pin 1 successfully allocated by 0x89 (137)
Registering usermods ...
heap 28984

Before this Serial only showed other Loop delayed more than 3ms. and other generic debug info that was printed periodically.

The configuration used is the one I uploaded earlier:

This is the config of a ESP8266 board I used for testing, here the crashes are a bit less frequent but still happen. I noticed that if I open the /liveview page on a browser the number of reboots noticeably increases, which suggests that the boards crash due to overload.

I repeated that once again and collected other logs here: crash-log.txt, clock speed is set to 'Fastest', WLED crashes after a while if I set to effect DJ Light from the Android app (the NodeMCU is receiving sound data from an esp32 which is listening to music), or crashes immediately if I enable the Peek option from the app.

EDIT: I was flashing the 2MB flash version because that's the one used on the athom controllers, so I also tried the standard NodeMCU build and the issue is still present

[willmmiles]

I pulled this PR in to my web server stability working branch and I haven't been able to reproduce the fault yet

@willmmiles I think the problem is is happening with analog (PWM) strips only - may also happening with bitbang ws2812 drivers. So I suspects it's a timing issue, or simply the 8266 is overloaded when doing high freq PWM (interrupt driven) + UDP polling + WiFi + other stuff.

I tried both bitbang ws2812 (actually my default ESP8266 test, due to a poor pin selection in a project I built before I discovered WLED!) and RGBW PWM in "normal" speed. No crashes for me after 12h of operation.

Besides UDP polling, audioreactive runs a linear filter (no loops) then simply copies received data to the variables used in effects. So audioreactive on 8266 does "almost nothing" in addition to UDP.

I suspect the polling latency might be the source of the visible lag. On 8266 calling the poll looks to be "basically free" in terms of CPU usage if there's nothing pending; we could probably poll every loop with no impact there (not so much on ESP32, though!!). Stability is more important than performance, though, so I'll investigate this later.

[willmmiles]

clock speed is set to 'Fastest', WLED crashes after a while if I set to effect DJ Light from the Android app

Aha, there it is! Just got one with these settings.

[gaaat98]

@willmmiles during your test with the PWM strip did you select a sound reactive effect on the receiving controller? Did you have another device sending the audio data? To have the sound reactive effects you need to make sure you pulled PR#3942 otherwise they are disabled.

Sorry to ask but it's stange since I have almost immediate crashes

[willmmiles]

@willmmiles during your test with the PWM strip did you select a sound reactive effect? Did you have another device sending the audio data? To have the sound reactive effects you need to make sure you pulled #3942 otherwise they are disabled.

Yes and yes. For the initial testing I had the same effect (GravCentric) running on three WS2812 strips - one on the ESP32 AR node directly, one on an ESP8266 over DDP, and one on an ESP8266 using AR sync. That's how I could tell the AR sync was laggy compared to DDP. ;)

For the overnight test I reconfigured that last unit to add PWM output on some unconnected pins. It ran OK for me using the GravCentric effect at 'Normal' speed. Dunno if it was the speed, the DJ light effect, or peek, but it faulted right away when I set it up with that config ... though it hasn't faulted since.

[blazoncek]

---WLED 0.15.0-b3 2405030 INIT---
esp8266 @ 80MHz.

@gaaat98 try 160MHz builds.

[gaaat98]

Same behaviour, I'm trying to establish reliable steps to reproduce the crashes but at the moment it seems that for me is enough to have the ESP8266 receiving data, the Dj Lights effect active, clock set to Fastest, and then just wait for maybe less than a minute while making some noises near the sending device...

Logs for the 160MHz build here

[willmmiles]

I managed to get the crash to reliably reproduce, but I haven't yet pinpointed the root cause. Here's what I've learned so far - might be old hat for some of you, sorry I'm still new to this environment:

• I was able to reproduce the crash using non-AR FX ('Breathe' in particular) on the PWM segment, so long as the brightness got above a certain point
• It won't reproduce without the UDP traffic, though
• -D DEBUG_ESP_HWDT gives a more helpful crash dump on WDT timer crashes such as these, but the user and system stacks are all munged together
• -D DEBUG_ESP_HWDT_NOEXTRA4K gives clean stack traces, but costs 4K of RAM
• Adding DEBUG_PRINT(F("Reset for: ")); DEBUG_PRINTLN(ESP.getResetInfo()); to WLED::setup() gives yet more clues to what was going on when the system faulted
• None of these have left me with a smoking gun, or at least I haven't isolated it yet - the faulting instruction pointers seem to be all over the system and frequently "benign" (eg. register arithmetic, nothing that would obviously lead to a fault).
• .. though there's a frequent occurrence of a ROM function at the top of the system stack, ram_rxiq_get_mis, which I am guessing is for retrieving packets from the wifi module??

I'm on vacation and away from home for the next couple of weeks, so I won't be able to do any more digging until I get back, but I wanted to leave some tracks in case anyone else was investigating.

Sorry I don't have more answers!

[flux242]

please condisder the following implementation of the receiveAudioData function:

• The buffer is static now and its size is 83 bytes (size of the v1 packet)
• Fixed possible stack crash attack if somebody would send big UDP packets
• Added a while loop to make sure that if packets are sent too often it wouldn't cause out of ram crash.

    bool receiveAudioData()   // check & process new data. return TRUE in case that new audio data was received. 
    {
      if (!udpSyncConnected) return false;
      bool haveFreshData = false;

      size_t packetSize = 0u;
      while ( (packetSize = fftUdp.parsePacket()) !=0 )
      {
        if ( (packetSize == sizeof(audioSyncPacket)) || (packetSize == sizeof(audioSyncPacket_v1)) ) {
          //DEBUGSR_PRINTLN("Received UDP Sync Packet");
          static uint8_t fftBuff[sizeof(audioSyncPacket_v1)];
          fftUdp.read(fftBuff, packetSize);

          // VERIFY THAT THIS IS A COMPATIBLE PACKET
          if ( isValidUdpSyncVersion((const char *)fftBuff)) {
            decodeAudioData(packetSize, fftBuff);
            //DEBUGSR_PRINTLN("Finished parsing UDP Sync Packet v2");
            haveFreshData = true;
            receivedFormat = 2;
          }
          else if (isValidUdpSyncVersion_v1((const char *)fftBuff)) {
            decodeAudioData_v1(packetSize, fftBuff);
            //DEBUGSR_PRINTLN("Finished parsing UDP Sync Packet v1");
            haveFreshData = true;
            receivedFormat = 1;
          }
          else receivedFormat = 0; // unknown format
        }
      }
      return haveFreshData;
    }

[softhack007]

I managed to get the crash to reliably reproduce, but I haven't yet pinpointed the root cause. Here's what I've learned so far - might be old hat for some of you

🤔 so the only "smoking guns" we have so far:

• it's a watchdog reset -> so something took too long time or the wifi driver did not get it's regular time slice
• it happens with PWM leds -> pwm on 8266 created a load of interrupts, because 8266 does not have the "ledc" unit like esp32 -> 8266 basicially uses a timer that fires interrupts whenever the output needs to toggle (up to ~50 times per millisecond per pin). PWM toggles most frequently when the "analog" value is around 50% of max.
• there is no real "pattern" as to where it crashes -> does not look like a single loop taking too much time, maybe it's just that the watchdog finally bites when too much time has accumulated.

@willmmiles @gaaat98 can you try if adding a "yield()" before or after the wifiudp calls helps? I.e. somewhere here:

https://github.com/gaaat98/WLED/blob/cec72419863a0ce8f19a02aa05bf9073b1302dcd/usermods/audioreactive/audio_reactive.h#L1086-L1090

receiving happens in "arduino loop" context so yield() is allowed.

[willmmiles]

https://github.com/MoonModules/WLED/blob/2edfcb33437386d32d8327a3c91b1c54c8df68e1/usermods/audioreactive/audio_reactive.h#L1050-L1062

With this, sizeof(audioSyncPacket) should be 44 on both platforms. Can you double-check please?

Confirmed this works too. I see there's a couple of new fields in the old padding - any plans to upstream those features?

[willmmiles]

Latest PWM update: I think I've finally gotten to the bottom of it. It looks like an actual, honest-to-goodness CPU bug.

The problem seems to be with the 'rfi 3' instruction used to return from the NMI used by the PWM timer. Sometimes this seems to hang the CPU instead of correctly returning. I don't know what causes it -- my best guess is contention with some other interrupt.

After the fault, the CPU stalls until the next NMI (timer event) occurs. When it does so, EPC3, the "return address" from the NMI, is set pointing to the NMI's own rfi instruction. When it tries to return from the "nested" interrupt, it goes in to a loop just resetting the instruction pointer back to the same 'return from interrupt' instruction, forever and ever, until the hard WDT trips. The timer NMIs actually still fire -- so PWM still works in this stuck state! -- but since the return address is at the end of the NMI handler, it just goes back to its loop when the ISR completes.

The good news is that the timer NMIs can maybe be used to recover the processor! I found a workaround by having the NMI handler back up the last "known good" return address, and restore it if the ISR finds the return address points to itself. My initial tests of this workaround have been very encouraging; it hasn't crashed on me yet, when it would typically fail in seconds.

What's left to do is find the cleanest way to integrate this fix in to WLED. My development approach involves duplicating and rewriting the processor's base interrupt vector table in assembly. This is great for tracing interrupts, but pretty invasive and finicky. The easiest place to do it would be the in platform PWM code - it'd be just a few lines of C, actually - but I don't relish forking the platform, and I'm not sure I could convince the upstream guys of the CPU fault: obviously the current code works well for them! Alternatively, the platform core uses some linker tricks to allow overriding the PWM code; so we could pull the ESP8266 PWM code in to our repo with only a minimal space penalty, though we'd have to pay some extra attention to monitoring upstream changes when we update the platform.

I'm somewhat leaning towards the latter solution. Anybody else got an opinion?

I'd also note that we the platform offers a phase-locked PWM core we should probably switch to - the way they've implemented the base PWM system produces pathologically bad performance if you change several outputs back to back, like we do for RGB(WW) outputs. Each channel tries to keep its own phase, so you can often get separate nearly-back-to-back interrupts for every channel. :( The phase-locked implementation should never generate more than analogFreq interrupts per second, while the base solution could theoretically generate as many as (analogFreq * active PWM channels)!

Thanks for bearing with me. It's been quite an adventure getting this deep in to the ROM and platform code.

[blazoncek]

@willmmiles ESP8266 is nearly at the end of its lifespan. Just put a band aid on it and be done with it.

Nevertheless, it would be nice to inform upstream of the findings. WLED used Tasmota framework in the past and @Jason2866 was very kind to us on many occasions so we could change to that if they incorporated such bugfix.

[Jason2866]

We do not use core 3.x for esp8266. Tried the first releases. Was not stable for us. So we stayed on a modified v2.7.4 version which works well for us. There is no 3.x version from us and I won't do a 3.x based one. Tasmota based on esp8266 will end with our modified v2.7.x version
EDIT: You can easily patch the framework code part with Platformio before compile starts see https://docs.platformio.org/en/stable/scripting/examples/override_package_files.html

[blazoncek]

Thank you @Jason2866 .
So the option is to revert core to 2.7.x but use newer toolchain (as we need newer C++ due to requirements from NeoPixelBus).
I do not know how to do that correctly so any help would be appreciated. There is a hint (I believe by @softhack007 or perhaps by me) in our platformio.ini for reverting to older version.

[Jason2866]

@blazoncek Why should you want to revert? If the current version works well for you.
With a Platformio script you can patch the current core with the changes you want/need.

[softhack007]

I'd also note that we the platform offers a phase-locked PWM core we should probably switch to - the way they've implemented the base PWM system produces pathologically bad performance if you change several outputs back to back

From software perspective, I would like to use the phase-locked PWM generator - looks like it can be activated by adding -DPIO_FRAMEWORK_ARDUINO_WAVEFORM_LOCKED_PHASE to build_flags? Another option seems to be just call enablePhaseLockedWaveform(); in our setup function.

Just one but - from electrical perspective. Phase-locked means that all PWM channels will be aligned, so more often we'll see all channels switch from 0 to 1 at the same time. This could become a problem for users with high current PWM setups using lots of color channels. If all PWM channels switch at the same time, its a sudden rise of power demand to the PSU. This may lead to stronger "coil whining" tones emitted from cheap PSU models. So we should habe some beta tester (with long PWM strips having many color channels) feedback, before going that route on 8266.

[softhack007]

@willmmiles just an idea about the "nearly-back-to-back interrupts for every channel" problem. What if we slightly delay the starting of each PWM channel? I'm thinking of something like analogWrite(RED, new_red); delay(1); analogWrite(GREEN, new_green); delay(3); analogWrite(BLUE, new_blue);. Use prime numbers for the delays, to avoid creating harmonics between shifted phases.

If I'm right, this would bring the PWM channels a bit more "out of phase", making the "nearly-back-to-back interrupts" scenario less likely to happen?

Edit: another option is called spread spectrum. For this, PWM frequency (or duty cycles) have to be slightly different for each PWM channel, which also reduces the likelihood of channels switching "in sync".

[blazoncek]

Regarding phase shifted PWM: I've had a discussion about bringing that to WLED with @jw2013. IMO that would be great addition.
But this is steering away from this PR. Shall we open a new issue for tracking PWM progress?

[Jason2866]

We introduced lowering power supply load by "PWM auto-phasing" with this PR arendst/Tasmota#14590 for Tasmota (for esp32x).

[softhack007]

But this is steering away from this PR. Shall we open a new issue for tracking PWM progress?

@blazoncek agreed. Either a new issue ticket, or maybe a new (draft) PR to also share related code.

For "8266 sound sync" we still need to know if special handling in the UDP code is necessary to prevent PWM crashes.
Or maybe we need an automatic "kill switch" feature, that disables the usermod when PWM analog leds are used.

For the "singled logical LED" PWM scenario (see comments from @tablatronix), the 8266 could also be controlled by DDP and a separate segment assigned to the one-led remote 8266. So audio processing would entirely be done on the esp32 having the microphone, while 8266 can handle PWM outputs without troubles.

@willmmiles i'll look into your other recommendations, too.

[softhack007]

We introduced lowering power supply load by "PWM auto-phasing" with this PR arendst/Tasmota#14590 for Tasmota (for esp32x).

nice 😄 could be something for our esp32 PWM driver, too.

@Jason2866 If i understand correctly, checking if several PWM outputs are actually "phase-locked" just requires a 12€ logic analyzer and sigrok pulseview ?

[Jason2866]

We introduced lowering power supply load by "PWM auto-phasing" with this PR arendst/Tasmota#14590 for Tasmota (for esp32x).

nice 😄 could be something for our esp32 PWM driver, too.

@Jason2866 If i understand correctly, checking if several PWM outputs are actually "phase-locked" just requires a 12€ logic analyzer and sigrok pulseview ?

Yes, since you can test with a low PWM frequency (in our case 977Hz)

[tablatronix]

I dropped my target fps to 30 and my stability has improved exponentially, might be anecdotal.. maybe it helps someone shrug

[willmmiles]

Either a new issue ticket, or maybe a new (draft) PR to also share related code.

I'll open a new PR tonight with a minimal PWM crash fix, vendoring in the soft PWM core currently in use. We can follow it up with a second PR regarding analog phase improvements. I believe the 8266 phase-locked core could be trivially modified to either (a) introduce a fixed phase offset for each line, or (b) introduce a "maximum transitions per tick" parameter. Either way, separate PR.

just an idea about the "nearly-back-to-back interrupts for every channel" problem. What if we slightly delay the starting of each PWM channel? I'm thinking of something like analogWrite(RED, new_red); delay(1); analogWrite(GREEN, new_green); delay(3); analogWrite(BLUE, new_blue);. Use prime numbers for the delays, to avoid creating harmonics between shifted phases.

My $0.02 would be yes to phase shifting or spread spectrum, no to delay(). The 8266 soft PWM code can let us specify the phase directly without losing FPS. The PWM code from Tasmota linked above demonstrates how to do it for ESP32.

For "8266 sound sync" we still need to know if special handling in the UDP code is necessary to prevent PWM crashes.

I'm fairly confident that the PWM problems could be triggered without the sound sync code at all, I believe that any kind of network traffic risks it. The fast regular traffic from the sync code is exacerbating a pre-existing bug. I'll post a beta PWM fix tonight and hopefully we can head off these problems.

[softhack007]

@gaaat98 thanks, good job 👍

Approved from my side.

[softhack007]

NB: this line would also work without static - putting the buffer into stack, instead of using global space.
The important point is just to make it a fixed-size array, because variable size arrays are allocated from the heap, each time the function runs.

I was not sure if it's better to use heap (no static), or global space (with static). @blazoncek I'll leave it up to you to decide what's better for 8266.

[blazoncek]

Use stack if possible. It costs nothing and the array size is not problematic.

Edit: I'm not sure if array is allocated in heap if its size is dynamic. Only new or malloc() will allocate from heap AFAIK.

[softhack007]

I'm not sure if array is allocated in heap if its size is dynamic. Only new or malloc() will allocate from heap AFAIK.

That's the important difference. array[packetsize] was allocated from the heap - because compiler does not know the size when compiling so it couldn't arrange stack offsets of other local vars.

see https://en.cppreference.com/w/c/language/array section "Variable-length arrays"

[blazoncek]

I have not tested the code, but skimming it reveals no major issues. It has my "go".

@softhack007 merge it when you're comfortable with it.

[netmindz]

Great to see we are almost there with this. Good work guys

[blazoncek]

I'd like to add addendum to this PR.

My recent PR #4066 exploits ESP-NOW for WiFi-less syncing between devices. If audio sync would use ESP-NOW (in addition to UDP) that would make large-scale audio deployments a possibility.

[netmindz]

I have a PoC of audio sync over ESP-NOW, which I was working on for the case where users had issue with multicast on their network @blazoncek

https://github.com/MoonModules/WLED/pull/148/files

It's 9 months old so would need to be updated before it could be merged, but shows that basic idea and some of the refactoring required to get access from the callback

[blazoncek]

@netmindz yes, something like that but hooked into framework provided in upstream implementation.