High Heap Fragmentation with 2 inverters

[lumapu]

Die Heap Fragmentation ist auch in Version 0.5.100 und zwei konfigurierten Invertern sehr hoch (beim ESP8266 ~36).
Wenn der zweite Inverter nicht aktiviert aber konfiguriert ist, bleibt das Problem bestehen. Mit nur einem Inverter ist die Fragmentation bei 2.
(Jetzt wieder mit 2 Invertern)
Wird in pubMqtt.h mClient.loop() auskommentiert, dann geht die Heap Framentation auf ~14.

@beegee3: Hast du eine Idee woran das liegen könnte? Ich glaube man muss jetzt eher Richtung hmSystem.h und hmInverter.h schauen.

Für mich soll der Issue als Gedankestütze dienen. Evtl. hat jemand einen guten Input was die Ursache sein könnte.

[Argafal]

Eine Kleinigkeit die mir beim Code-Review aufgefallen ist: Die JSONDocument Dokumentation schlägt vor, für kleine Jsons StaticJsonDocument zu verwenden, siehe https://arduinojson.org/v6/api/jsondocument/:

Use a StaticJsonDocument to store in the stack (recommended for documents smaller than 1KB)

In pubMqtt.h werden aber DynamicJsonDocument benutzt, von 128-256 Byte Größe. Wie wäre es mit folgendem Patch:

diff --git a/src/publisher/pubMqtt.h b/src/publisher/pubMqtt.h
index 2b2b298..5f95333 100644
--- a/src/publisher/pubMqtt.h
+++ b/src/publisher/pubMqtt.h
@@ -207,7 +207,7 @@ class PubMqtt {
             DPRINTLN(DBG_VERBOSE, F("sendMqttDiscoveryConfig"));
 
             char topic[64], name[32], uniq_id[32];
-            DynamicJsonDocument doc(256);
+            StaticJsonDocument<256> doc;
 
             uint8_t fldTotal[4] = {FLD_PAC, FLD_YT, FLD_YD, FLD_PDC};
             const char* unitTotal[4] = {"W", "kWh", "Wh", "W"};
@@ -264,7 +264,7 @@ class PubMqtt {
                         stateCls = getFieldStateClass(fldTotal[i]);
                     }
 
-                    DynamicJsonDocument doc2(512);
+                    StaticJsonDocument<512> doc2;
                     doc2[F("name")] = name;
                     doc2[F("stat_t")] = String(mCfgMqtt->topic) + "/" + ((!total) ? String(iv->config->name) : "total" ) + String(topic);
                     doc2[F("unit_of_meas")] = ((!total) ? (iv->getUnit(i,rec)) : (unitTotal[i]));
@@ -356,7 +356,7 @@ class PubMqtt {
             if(NULL == mSubscriptionCb)
                 return;
 
-            DynamicJsonDocument json(128);
+            StaticJsonDocument<128> json;
             JsonObject root = json.to<JsonObject>();
 
             bool limitAbs = false;

Note, auch das dynamische hat eine feste Größe:

https://arduinojson.org/v6/api/dynamicjsondocument/

In older versions, DynamicJsonDocument was able to grow if needed. Starting with version 6.7.0, DynamicJsonDocument has a fixed capacity, just like StaticJsonDocument.

[lumapu]

so wie ich es gelesen habe ist der Unterschied heap und stack

die publish Methode führt nicht zur fragmentation

[Argafal]

Ja genau. Und viele kleine JsonDocument auf dem heap (dynamic, jetztiger Code) zerlöchern doch auch den Heap, oder? Deswegen schlägt die Doku ja vor, kleine JsonDocument statisch zu bauen, die landen dann auf dem Stack (mein diff). Vielleicht machts ja ne Verbesserung? Ich kann's morgen mal ausprobieren wenn die Sonne wieder scheint (mit zwei Invertern).

Edit: Gerade dein Edit über die publish Methode gesehen. Ach schade.

[knickohr]

Das ePaper hat aber nichts damit zu tun ? 🤔
Oder habt ihr nur den 8266 damit konfrontiert ?

[beegee3]

Wird in pubMqtt.h mClient.loop() auskommentiert, dann geht die Heap Fragmentation auf ~14.

Dann würde das Problem doch bei MqttClient liegen, oder verstehe ich das falsch? mClient.loop() löst im verwendeten Fall nur die MqttClient internen Routinen _checkOutgoing, _checkIncoming und _checkPing aus. Nichts, was noch in direktem Kontakt zu pubMqtt.h steht.
Allerdings würde ich in pubMqtt.h noch ein wenig nacharbeiten, um dort möglichst alle Problemzonen zu beseitigen:

1. in einigen Funktionen wird lokal char topic[...] deklariert. Warum nicht eine einzelne hinreichend große globale Deklaration char mTopic[...], die in den Funktionen mit memset genullt und anschließend mit snprintf befüllt wird?
2. in publish wird String topic definiert und entsprechend der Vorgabe addTopic befüllt. Auch das lässt sich mit dem 1. Punkt ohne lokale Variable erledigen. Ggfs. braucht man also 2 globale char Arrays.

Dann mal sehen, ob der heap immer noch so löchrig wird.

[Argafal]

I removed the MQTT server from my settings and ran for an hour just looking at the webUI. I have two inverters configured. heap_frag with the MQTT server was high, around 35-40% after a few minutes of run time.

Without the MQTT server configured, the heap fragmentation basically disappears:

[Argafal]

I tried to implement some of the improvements discussed in this thread. Patch attached. I will report after a long-term test.

diff --git a/src/publisher/pubMqtt.h b/src/publisher/pubMqtt.h
index 2b2b298..3acbef1 100644
--- a/src/publisher/pubMqtt.h
+++ b/src/publisher/pubMqtt.h
@@ -111,6 +111,7 @@ class PubMqtt {
             publish(subtopics[MQTT_UPTIME], val);
             publish(subtopics[MQTT_RSSI], String(WiFi.RSSI()).c_str());
             publish(subtopics[MQTT_FREE_HEAP], String(ESP.getFreeHeap()).c_str());
+            publish(subtopics[MQTT_HEAP_FRAG], String(ESP.getHeapFragmentation()).c_str());
         }
 
         bool tickerSun(uint32_t sunrise, uint32_t sunset, uint32_t offs, bool disNightCom) {
@@ -162,14 +163,16 @@ class PubMqtt {
             if(!mClient.connected())
                 return;
 
-            String topic = "";
-            if(addTopic)
-                topic = String(mCfgMqtt->topic) + "/";
-            topic += String(subTopic);
+            memset(mTopic, 0, MQTT_TOPIC_LEN+5);
+            if(addTopic){
+                snprintf(mTopic, MQTT_TOPIC_LEN+5, "%s/%s", mCfgMqtt->topic, subTopic);
+            } else {
+                snprintf(mTopic, MQTT_TOPIC_LEN+5, "%s", subTopic);
+            }
 
             do {
-                if(0 != mClient.publish(topic.c_str(), QOS_0, retained, payload))
-                    break;
+                if(0 != mClient.publish(mTopic, QOS_0, retained, payload))
+                   break;
                 if(!mClient.connected())
                     break;
                 #if defined(ESP8266)
@@ -207,7 +210,7 @@ class PubMqtt {
             DPRINTLN(DBG_VERBOSE, F("sendMqttDiscoveryConfig"));
 
             char topic[64], name[32], uniq_id[32];
-            DynamicJsonDocument doc(256);
+            StaticJsonDocument<256> doc;
 
             uint8_t fldTotal[4] = {FLD_PAC, FLD_YT, FLD_YD, FLD_PDC};
             const char* unitTotal[4] = {"W", "kWh", "Wh", "W"};
@@ -264,7 +267,7 @@ class PubMqtt {
                         stateCls = getFieldStateClass(fldTotal[i]);
                     }
 
-                    DynamicJsonDocument doc2(512);
+                    StaticJsonDocument<512> doc2;
                     doc2[F("name")] = name;
                     doc2[F("stat_t")] = String(mCfgMqtt->topic) + "/" + ((!total) ? String(iv->config->name) : "total" ) + String(topic);
                     doc2[F("unit_of_meas")] = ((!total) ? (iv->getUnit(i,rec)) : (unitTotal[i]));
@@ -356,7 +359,7 @@ class PubMqtt {
             if(NULL == mSubscriptionCb)
                 return;
 
-            DynamicJsonDocument json(128);
+            StaticJsonDocument<128> json;
             JsonObject root = json.to<JsonObject>();
 
             bool limitAbs = false;
@@ -636,6 +639,7 @@ class PubMqtt {
         char mLwtTopic[MQTT_TOPIC_LEN+5];
         const char *mDevName, *mVersion;
         char mClientId[26]; // number of chars is limited to 23 up to v3.1 of MQTT
+        char mTopic[MQTT_TOPIC_LEN+5];
 };
 
 #endif /*__PUB_MQTT_H__*/
diff --git a/src/publisher/pubMqttDefs.h b/src/publisher/pubMqttDefs.h
index 9633e2d..088023b 100644
--- a/src/publisher/pubMqttDefs.h
+++ b/src/publisher/pubMqttDefs.h
@@ -41,6 +41,7 @@ enum {
     MQTT_UPTIME = 0,
     MQTT_RSSI,
     MQTT_FREE_HEAP,
+    MQTT_HEAP_FRAG,
     MQTT_SUNRISE,
     MQTT_SUNSET,
     MQTT_COMM_START,
@@ -64,6 +65,7 @@ const char* const subtopics[] PROGMEM = {
     "uptime",
     "wifi_rssi",
     "free_heap",
+       "heap_frag",
     "sunrise",
     "sunset",
     "comm_start",

[beegee3]

@Argafal good approch, but I'm afraid that the array mTopic isn't big enough for every subTopic when added to
mCfgMqtt->topic. mCfgMqtt->topic itself may have MQTT_TOPIC_LEN = 65 characters. And often the subTopics size used in snprintf is 32 + MAX_NAME_LENGTH = 48 characters.
By this the array should be something like mTopic[MQTT_TOPIC_LEN + 32 + MAX_NAME_LENGTH]. Maybe +1 for the final '\0'.

@lumapu btw. there's quite a lot functions where a char topic[7 + MQTT_TOPIC_LEN] is filled by snprintf(topic, 32 + MAX_NAME_LENGTH, ...). That does not fit. Shouldn't the topic array length be changed?

[lumapu]

good point 👍
We use snprintf in many places but if it doesn't fit we get an exception which isn't catched.
Do you know if there is an option to surround parts of code with try ... catch to output at least an error message?

[beegee3]

try ... catch

sorry I don't know, but shouldn't it be possible to determine the maximum length needed whenever snprintf is used?
Or determine the maximum length over all subTopics and use this for every topic declaration.
I guess you will find the longest subTopic in sendData depending on iv->config->name and fields:
snprintf(topic, 32 + MAX_NAME_LENGTH, "%s/ch%d/%s", iv->config->name, rec->assign[i].ch, fields[rec->assign[i].fieldId]);

[Argafal]

@Argafal good approch, but I'm afraid that the array mTopic isn't big enough for every subTopic when added to mCfgMqtt->topic. mCfgMqtt->topic itself may have MQTT_TOPIC_LEN = 65 characters. And often the subTopics size used in snprintf is 32 + MAX_NAME_LENGTH = 48 characters. By this the array should be something like mTopic[MQTT_TOPIC_LEN + 32 + MAX_NAME_LENGTH]. Maybe +1 for the final '\0'.

Agreed. Of course the really issue is that MQTT_TOPIC_LENGTH is not what it says it is. It's not the maximum topic length of our MQTT messages. Instead it's the maximum length of the mqtt prefix, right?

For now I have made the proposed change and added it to the pull request. We might consider some cleaning up here, too, but this corrects the immediate length issue.

@lumapu btw. there's quite a lot functions where a char topic[7 + MQTT_TOPIC_LEN] is filled by snprintf(topic, 32 + MAX_NAME_LENGTH, ...). That does not fit. Shouldn't the topic array length be changed?

I saw that and I agree that that should be changed, too.

[Argafal]

Zum Testen hab ich mal alle debug statements entfernt. Das kann man recht schnell mit folgendem Kommando erledigen: sed -i -e 's#^\s*DBGPRINT#;//&#' -e 's#^\s*DPRINT#;//&#' */*.h */*.cpp *.h *.cpp

Der heap fragmentation Wert wird etwas kleiner, aber nicht viel. Er geht bei mir von 29 nach 27. Ein kleiner Erfolg. Meiner Meinung nach könnte man also versuchen, die Debug-Strings noch ein klein wenig zu optimieren. Unglaublich viel Zeit sollte man da aber auch wieder nicht rein stecken, denn der Nutzen is begrenzt. Wichtiger wäre es zu verstehen, woher der große Anteil heap fragmentation kommt.

In der MQTT Lib dir wir benutzen wird, wenn ich das richtig verstehe, für jede Nachricht eine Kopie erzeugt. Diese Kopie wird mit malloc gemacht, und dann asynchron verschickt, Speicher dann wieder freigegeben. Ob das stark zur heap fragmentation beiträgt? Gibt es keine MQTT lib die mit einem festen/Ring-Puffer arbeitet und die speziell für ESP8266 gedacht ist? Oder benutzen wir die MQTT lib vielleicht falsch?

[lumapu]

es gibt meines Wissens synchrone und asynchrone Beispiele für den Einsatz der Lib.
Ich denke wir verwenden aktuell den synchronen.
Was ich nicht verstehe, warum ein zweiter Inverter so heftig zu Buche schlägt. Der Fehler ist bestimmt klein aber sehr gut versteckt, so wie damals die strtok

[beegee3]

wenn die MQTT Lib für's publish Speicher allokiert und diesen erst später wieder freigibt (sprich nicht in demselben Aufruf des publish), erzeugen die lokalen topic und val Arrays Löcher im heap, oder? Habe zum Ausprobieren diese mal durch globale Versionen mSubTopic und mVal ersetzt (-> pubMqtt.zip).

memset(mTopic, ...) in publish habe ich auskommentiert, denn snprintf terminiert immer mit '\0', da kann also nichts passieren. Und die Länge bei snprintf(mTopic, ...) sollte MQTT_TOPIC_LEN + 32 + MAX_NAME_LENGTH sein. Das + 1 in der mTopic Definition ist für das '\0' am Ende, falls die Länge voll ausgereizt wird.

[Argafal]

Könnten Betroffene (und auch Nicht-Betroffene) bitte kurz diese Fragen beantworten:

• ESP8266 oder ESP32?
• Version?
• Wie viele Inverter und welche?
• Inverter-Abfrage Interval und Retries aus den Einstellungen? (Default: 30s und 5 retries)
• MQTT Server konfiguriert: ja/nein?
• Falls ja, auf welcher Hardware läuft der MQTT Server? (z.B. richtiger Rechner? oder Raspberry Pi? welche Variante?)
• MQTT-Interval aus den Einstellungen? (Default: 0)
• WebUI aktiv benutzt: ja/nein?
• Typische heap_fragmentation Wert nach 20 Minuten Laufzeit? Siehe /system
• Regelmässige Probleme dass die WebUI kaputt geht, ja/nein? (siehe screenshot in issue Website breaks while ahoy keeps running #660)

[knickohr]

nicht betroffen 😎

• ESP32
• Ahoy version, immer die aktuellste DEV
• Wie viele Inverter und welche? Momentan noch 2x HM-300
• Inverter-Abfrage Interval aus den Einstellungen? 10s
• MQTT Server konfiguriert: ja
• Falls ja, auf welcher Hardware läuft der MQTT Server? RasPi 4B
• MQTT-Interval aus den Einstellungen? 0
• WebUI aktiv benutzt: gelegentlich, dann heftig 😉
• Typische heap_fragmentation Wert nach 20 Minuten Laufzeit? Wird beim ESP32 leider nicht angezeigt 😞 Wäre ein Feature Request würdig
• Regelmässige Probleme dass die WebUI kaputt geht ? nein

[Argafal]

Ich beantworte mal selbst für meine Situation:

• ESP8266 oder ESP32?

ESP8266

• Ahoy version?

0.1.105 mit einem privaten Patch der testweise alle Debugging-Nachrichten aus dem Code entfernt

• Wie viele Inverter und welche?

Zwei. HM-600 und HM-1500.

• Inverter-Abfrage Interval aus den Einstellungen? (Default: 30)

30s. 5 retries

• MQTT Server konfiguriert: ja/nein?

ja

• Falls ja, auf welcher Hardware läuft der MQTT Server?

Raspberry Pi Zero v1

• MQTT-Interval aus den Einstellungen? (Default: 0)

0

• WebUI aktiv benutzt: ja/nein?

ja

• Typische heap_fragmentation Wert nach 20 Minuten Laufzeit? Siehe /system

27

• Regelmässige Probleme dass die WebUI kaputt geht, ja/nein? (siehe screenshot in issue

ja, bei aktiver WebUI Nutzung. Ansonsten stabil wie ein Stein.

[beegee3]

hab' ESP32 und keine Probleme,
benutze die aktuellste Dev. aber mit modifiziertem Radio.
Wegen meiner Tests nur 1 Inverter und MQTT abgeklemmt, dabei das Inverter-Abfrage Intervall auf 1 sek (!)
WebUI nutze ich aktiv sehr viel.
Bei den Radio Tests ist mir aufgefallen, dass die WebUI Reaktionszeit stark davon abhängt, ob die Kommunikation mit dem Inverter gut läuft oder häufig retransmits stattfinden (Radio läuft bei mir z.Zt. auf 2MBps, da gibt's noch sehr viele retransmits).

Testet doch mal mit Inverter Settings 'Max retries per Payload' = 0. Dann gibt's zwar weniger Intervall-Updates (es sei man verkürzt das Abfrage Intervall), aber vielleicht funktioniert WebUI dann besser.

[lumapu]

@beegee3 hast du dazu auch eine nachvollziehbare Erkärung? Denkst du eher an unseren Code (RX-loop in hmRadio) oder in der NRF-Lib?

[beegee3]

@lumapu na ja, wenn retransmits erforderlich sind, werden diese sofort angestoßen, d.h. direkt mit dem nächsten Aufruf von app::loopStandard wird wieder in der RX-loop auf Antwort vom Inverter gehorcht. Bei schlechter Verbindung und 'Max retries per Payload' = 5 kann das pro Frame mehr als 5 Sekunden dauern (so, wie die RX-loop z.Zt. angelegt ist: 300*4ms = 1,2s pro Versuch). Fehlen mehrere Frames (bei einem WI mit 4 Panels können es max. 4 Frames sein), kann sich das aufsummieren bevor die Abfrage als fail eingestuft wird. Ich glaube, dass während der RX-loop nicht genug Zeit für anderes bleibt, die yield(); Anweisungen reichen nur, den 🐕 zu füttern. Bin gerade dabei, hmRadio anzupassen, wobei die RX-loop max. 300ms lang ausgeführt wird. Anstelle 4ms pro Channel zu lauschen, teste ich mit Mikrosekunden (5526us sieht ganz gut aus; kommt aus dem 'Gazell' Frequenzhopping). Je weniger retransmits stattfinden, umso reaktionsfreudiger ist das WebUI. Hab' gestern von 250kbps auf 2MBps umgestellt (dauert 2-3 Minuten, bis der WI darauf reagiert, aber dann geht's 😃). Gibt bei 1008us Frequenzhopping (auch aus 'Gazell') noch viele retransmits. Promt wurde das WebUI träge. Vom 'Klick' bis zum Ergebnis schon mal 3-5 Sekunden. Könnte das beim ESP8266 zum "WebUI Totalausfall" führen?
Aber das muss nichts mit dem eigentlichen Thema Heap Fragmentation zu tun haben, sondern kann ein ganz eigener Effekt sein. Bzgl. Heap Fragmentation hatte ich oben einen MQTT Vorschlag mit globalen SubTopics und Vals gemacht. Hast du das schon mal ausprobiert, oder bringt das nichts?

[beegee3]

hier mal der hmRadio Sourcecode mit 5526us. Neben loop nur leichte Anpassungen in getReceived und sendPacket.
Die bisherige loop entsprach mit RX_PERIOD = 4ms auch schon dem 'Gazell' Protokoll, HOST Mode 1 bzw. Mode 3
(s. https://0w0.pw/nRFGo_SDK/group__nordic__gzll.html). Ist das Zufall oder Absicht?
Die 5526us sollten im Vergleich zur bisherigem vor allem Verbesserungen bei 'RX no answer' und 'TX retransmits' liefern.

hmRadio.zip

[lumapu]

Aber das muss nichts mit dem eigentlichen Thema Heap Fragmentation zu tun haben, sondern kann ein ganz eigener Effekt sein. Bzgl. Heap Fragmentation hatte ich #768 (comment) einen MQTT Vorschlag mit globalen SubTopics und Vals gemacht. Hast du das schon mal ausprobiert, oder bringt das nichts?

nein noch nicht, steht aber auf meinem Plan. Kann mir schon vorstellen, dass es was bringt.

[lumapu]

@beegee3 die Änderung hat's echt gebracht, heap fragmentation auf 2 👍 An ein zwei Stellen habe ich noch nachjustiert, mal sehen was die große Gemeinde sagt. Wildes rumklicken in der WebUI hat die Fragmentation kurzzeitig mal auf 3 gehoben. Morgen kommt der Praxistest mit kommunizierdendem Inverter.
Jetzt geht sie nur noch auf 31, wenn man speichert, aber nicht gleich neustartet - ich denke das ist verkraftbar.

[lumapu]

nach einem OTA Update ist die fragmentation auch wieder bei 34. Ein weiterer Reboot bereinigt das. Ich erkläre das damit, dass beim Booten das Update entpackt wird und dabei der Heap versaut wird.

[Argafal]

heap_frag 29. Das ist 0.5.109 mit den Debugging print statements auskommentiert. Aber: die WebUI reagiert unheimlich gut und bis jetzt hab ich außer des etwas hohen heap_frag Wertes kein wirkliches Problem gesehen. Abwarten und beobachten.

[beegee3]

@lumapu 🎉 👍 Danke zur Version 0.6.0 !!!
Hoffentlich ist Heap Fragmentation damit Geschichte!
Zumindest ist es vorbei mit issues zur alten main Version, die im dev. bereits umgesetzt wurden!

Zwei Fragen hätte ich bei der Gelegenheit noch (will aber nicht nerven, reine Neugier 😁):

1. warum wird in app::onWifi tickNtpUpdate nicht sofort, sondern zeitverzögert mit once(...) aufgerufen?
2. sollten in pubMqtt.h discoveryConfigLoop die deaktivierten Inverter nicht besser übersprungen werden?
   (also auf iv->config->enabled prüfen; fehlt bei app::tickMidnight auch, ist da aber egal)

[knickohr]

So Jungs und Mädels, seit eben hängen bei mir 5 Inverter an der DTU. Heap immer noch wie gewohnt, aber die Webseite scheint gefühlt langsamer zu werden mit jedem weiteren Inverter. Noch kein Grund zur Sorge, läuft erst seit ein paar Minuten, lassen wir das sich noch einspielen 😉

[knickohr]

Es hat sich beruhigt und ja, es ist faszinieren ! Trotz 5 Inverter, soviel,Free_Heap hatte ich noch nie 😎

Schade das der ESP32 nicht den fragmentierten Heap anzeigt 😢

[lumapu]

ich mache hier mal zu. Beim ESP8266 gilt weiterhin: nach einem Update nochmal einen Reboot machen, dann sollte die Heap-Fragmentation < 10 sein.