Mesmerizer framerate dropping fixed amount after N seconds?

[robertlipe]

Firstly, I know the engineering answer is "profile it"...but I thought I'd ask the crowd for similar experiences.

I'm generally really impressed at the frame rate we can get out of Mesmerizer with the ESP32. But I've noticed a rather odd pattern that's quite repeatable in some of our displays.

The case in hand is Tixy 27. I've seen this on others than Tixy, but that's the test case in on my screen right now. Tixy's "code golf" format of switching on every pixel is certainly not doing prefetch, lookahead, branch prediction, or the vector processor any favors, but we have effects that are doing WAY more than ' sinf(x / y - y / x + t);' for every pixel ... and I'm more concerned about the effect over time than the time per pixel/frame.

Upon start, we come out of the gate with a relatively smooth (more importantly, steady) 20+fps. It doesn't matter a lot what the rate IS as it'll vary between effects. The common theme I'm seeing in some, not all, effects that almost always around eight "heartbeats" of the 5 second report daemon, you can almost hear the 'glugging' sound of the frame rate tanking. Somewhere around 40 seconds, the frame rate falls from ~20+ to 7.

Once it falls, it's visibly chunky and it stays low. It falls pretty suddenly. If you're watching, you can see it downshifting. Once it falls, it stays in chunky 7 fps cadence forever. (Well, for reasonable definitions of "forever" - I've let it run 6+ hours and it's only showing 6fps.

I can repro this across multiple effects. I've locked Tixy in my case to always be effect "27" - no rapid channel changing here. There's no dynamically allocated data in the effect code and it's not like we're shifting (knowingly) between malloc'ed buffers in PSRAM vs. real memory or something.

It can be reproed from a cold device boot with no computer attached. Just prorgram the device to spray frames, punch the reset button, count about 35 bananas (or potatoes or Mississippis), then watch it throttle.

I know the answer is "profile it and see" but that's kind of a pain for embedded. First, I wanted to ask if any of you have also observed this and if you have, was there a resolution.

What changes about 35 seconds into our life cycle?
At 20FPS, we're CPU: 054%, 063%,
at 7FPS, we're CPU: 044%, 088%

So we're not balanced very well (we have too many nested schedulers for my taste) but it's not like we have one core that's just getting hammered.

Is there a ready architectural explanation for this or is it something that needs investigated? (I'm not going to block Tixy/SM Effects over it - this should be my about last fix before getting that back into the review queue....)

Thanx,
RJL

(I) (begin)(C1) Embedded timezones file size: 17834
(I) (begin)(C1) HTTP server started
(I) (ConnectToWiFi)(C1) Web Server begin called!
[ 10906][E][vfs_api.cpp:182] remove(): /current.cfg does not exists or is directory
(I) (WriteCurrentEffectIndexFile)(C0) Number of bytes written to file /current.cfg: 1
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 17 Refresh: 60 Hz, Power: 3341 mW, Brite: 100%, Audio FPS: 45, MinVU: 196.8, PeakVU: 200.4, VURatio: 0.0 Buffer: 0/500, CPU: 084%, 075%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 21 Refresh: 60 Hz, Power: 4751 mW, Brite: 94%, Audio FPS: 45, MinVU: 193.5, PeakVU: 200.4, VURatio: 0.0 Buffer: 0/500, CPU: 053%, 065%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 21 Refresh: 60 Hz, Power: 3329 mW, Brite: 100%, Audio FPS: 45, MinVU: 169.9, PeakVU: 182.4, VURatio: 0.0 Buffer: 0/500, CPU: 054%, 063%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 21 Refresh: 60 Hz, Power: 3782 mW, Brite: 100%, Audio FPS: 45, MinVU: 209.0, PeakVU: 219.4, VURatio: 0.0 Buffer: 0/500, CPU: 054%, 064%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006931/4175051, LED FPS: 21 Refresh: 60 Hz, Power: 5173 mW, Brite: 85%, Audio FPS: 43, MinVU: 204.7, PeakVU: 219.7, VURatio: 0.2 Buffer: 0/500, CPU: 054%, 064%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 20 Refresh: 60 Hz, Power: 2929 mW, Brite: 100%, Audio FPS: 45, MinVU: 205.1, PeakVU: 213.9, VURatio: 0.1 Buffer: 0/500, CPU: 053%, 065%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 11 Refresh: 60 Hz, Power: 5180 mW, Brite: 87%, Audio FPS: 45, MinVU: 182.7, PeakVU: 202.7, VURatio: 0.0 Buffer: 0/500, CPU: 043%, 086%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 7 Refresh: 60 Hz, Power: 3396 mW, Brite: 100%, Audio FPS: 45, MinVU: 203.2, PeakVU: 208.3, VURatio: 0.0 Buffer: 0/500, CPU: 044%, 089%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 7 Refresh: 60 Hz, Power: 4437 mW, Brite: 89%, Audio FPS: 43, MinVU: 205.8, PeakVU: 209.6, VURatio: 0.0 Buffer: 0/500, CPU: 044%, 088%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 7 Refresh: 60 Hz, Power: 3941 mW, Brite: 100%, Audio FPS: 43, MinVU: 199.5, PeakVU: 206.4, VURatio: 0.1 Buffer: 0/500, CPU: 044%, 088%, FreeDraw: 0.018
(I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 81824, LargestBlk: 49140, PSRAM Free: 1006403/4175035, LED FPS: 7 Refresh: 60 Hz, Power: 3706 mW, Brite: 94%, Audio FPS: 45, MinVU: 206.4, PeakVU: 211.1, VURatio: 0.1 Buffer: 0/500, CPU: 043%, 088%, FreeDraw: 0.018

[robertlipe]

OK, 5 hours and not 6:

• Debug: Command received: uptime
  (I) (ShowUptime)(C1) Uptime: 0 days - 04:58:03
  (I) (ShowUptime)(C1) Last boot reason: (1): Power On

I dont' recognize anything the runtime profilers are telling me as flagrantly bad:

• Debug: Command received: stats
  (processRemoteDebugCmd)(C1) Displaying statistics....
  (processRemoteDebugCmd)(C1) v040:1x2048 77K
  (processRemoteDebugCmd)(C1) 66dB:192.168.2.165
  (processRemoteDebugCmd)(C1) BUFR:00/500 [6fps]
  (processRemoteDebugCmd)(C1) DATA:+0.00-+0.00
  (processRemoteDebugCmd)(C1) g_Analyzer._VU: 203.35, g_Analyzer._MinVU: 203.35, g_Analyzer.g_Analyzer._PeakVU: 216.30, g_Analyzer.gVURatio: 0.00
  (processRemoteDebugCmd)(C1) Socket Buffer _cbReceived: 0

[ Edit ]
At 12 hours, the frame rate has fallen to 6. The 'mem' numbers has fallen a little from above, but nothing in proportion to that first 40 seconds.

uptime

• Debug: Command received: uptime
  (I) (ShowUptime)(C1) Uptime: 0 days - 12:17:24
  (I) (ShowUptime)(C1) Last boot reason: (1): Power On
  stats
• Debug: Command received: stats
  (processRemoteDebugCmd)(C1) Displaying statistics....
  (processRemoteDebugCmd)(C1) v040:1x2048 77K
  (processRemoteDebugCmd)(C1) 54dB:192.168.2.165
  (processRemoteDebugCmd)(C1) BUFR:00/500 [6fps]
  (processRemoteDebugCmd)(C1) DATA:+0.00-+0.00
  (processRemoteDebugCmd)(C1) g_Analyzer._VU: 193.05, g_Analyzer._MinVU: 188.01, g_Analyzer.g_Analyzer._PeakVU: 194.02, g_Analyzer.gVURatio: 0.06
  (processRemoteDebugCmd)(C1) Socket Buffer _cbReceived: 0
  (I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 79956, LargestBlk: 47092, PSRAM Free: 1004075/4174955, LED FPS: 6 Refresh: 60 Hz, Power: 391I) (loop)(C1) WiFi: WL_CONNECTED, IP: 192.168.2.165, Mem: 79956, LargestBlk: 47092, PSRAM Free: 1004075/4174955, LED FPS: 6 Refresh: 60 Hz, Power: 3916 mW, Brite: 100%, Audio FPS: 45, MinVU: 184.2, PeakVU: 196.2, VURatio: 0.0 Buffer: 0/500, CPU: 045%, 094%, FreeDraw: 0.016
  ^]

I don't think there are any allocations in the Draw() path, but this is C++, so who knows?