ESP32- Sporadic slow receive of MQTT messages

Question

Problem description: Every ~20+ published messages (using terminal), MCU receives that message in a very noticeable delay (mostly ~10 sec, few time it got up to 1 min). Upon receive (printed in Serial monitor), MCU is working as expected.

Hardware: ESP32 DEVKIT MCU, PubSubClient.h for MQTT and WiFi.h for WiFi.

Important remark: Code is same for ESP8266 and ESP32.This behavior happens only on ESP32.

Question: Does ESP32 has a know issue regarding receiving MQTT messages? is there a workaround? or perhaps- bug in code?

What did I do to try isolating the problem:

1. Tried on 3 different ESP32s (2 DEVkit MCU, and 1 with relays on board) - same behavior - it is not an specific MCU hardware problem.

2. Used another PC to publish MQTT messages (via terminal. MAC and Linux, and a 3rd party MQTT App)- no change. It has nothing to do with publishing platform.

3. To rule out it may be a MQTT broker's fault (Local RPI3 connected using LAN cable)- Subscribing to that topic in order to see if the delay repeats . MQTT server receive pubs on time. Broker responds on time (while waiting to see when publish is received in Serial monitor).

4. adding a flashing LED every 200ms in loop(), to verify that MCU is not get stuck in a process. loop() is looping as expected (see in code below).

5. Spitting heap free memory to Serial monitor, in order to see if there is some memory issue, degradation. Nothing suspicious.

6. Code simplification- used code segments from ESP32 wifi and MQTT pubsub's example, while disabling every functionality of original code(with and without). Delay still happens sporadically.

OUTPUT1- sending "0" and "1" almost simultaneously, almost 15 sec delay

13:31:21.516 -> Message arrived [myHome/test] 0 <--- right after this, "1" was sent
13:31:22.510 -> 278616 <---- free heap size (send every 1000 ms. non-blocking)
13:31:23.570 -> 278616
13:31:24.630 -> 278616
13:31:25.657 -> 278616
13:31:26.718 -> 278616
13:31:27.778 -> 278616
13:31:28.805 -> 278616
13:31:29.866 -> 278616
13:31:30.926 -> 278616
13:31:31.954 -> 278616
13:31:33.014 -> 278616
13:31:34.075 -> 278616
13:31:35.102 -> 278616
13:31:35.964 -> Message arrived [myHome/test] 1 <--- received 15 sec later

OUTPUT-2: Code

#include <WiFi.h>
#include <PubSubClient.h>

WiFiClient espClient;
PubSubClient client(espClient);


const char *mqtt_server = "192.168.2.100";


void setup_wifi()
{

        delay(10);
        // We start by connecting to a WiFi network
        Serial.println();
        Serial.print("Connecting to ");
        // Serial.println(ssid);

        WiFi.mode(WIFI_STA);
        WiFi.begin("iot", "GdS");

        while (WiFi.status() != WL_CONNECTED)
        {
                delay(500);
                Serial.print(".");
        }

        Serial.println("");
        Serial.println("WiFi connected");
        Serial.println("IP address: ");
        Serial.println(WiFi.localIP());
}

void callback(char *topic, byte *payload, unsigned int length)
{
        Serial.print("Message arrived [");
        Serial.print(topic);
        Serial.print("] ");
        for (int i = 0; i < length; i++)
        {
                Serial.print((char)payload[i]);
        }
        Serial.println();

        // Switch on the LED if an 1 was received as first character
}

void reconnect()
{
        // Loop until we're reconnected
        while (!client.connected())
        {
                Serial.print("Attempting MQTT connection...");
                // Create a random client ID
                String clientId = "ESP8266Client-";
                clientId += String(random(0xffff), HEX);
                // Attempt to connect
                if (client.connect(clientId.c_str()),"guy","kupelu9e")
                {
                        Serial.println("connected");
                        // Once connected, publish an announcement...
                        client.publish("myHome/log", "hello world");
                        // ... and resubscribe
                        client.subscribe("myHome/test");
                }
                else
                {
                        Serial.print("failed, rc=");
                        Serial.print(client.state());
                        Serial.println(" try again in 5 seconds");
                        // Wait 5 seconds before retrying
                        delay(5000);
                }
        }
}

void setup()
{
        Serial.begin(115200);
        setup_wifi();
        client.setServer(mqtt_server, 1883);
        client.setCallback(callback);
        reconnect();
}
void loop()
{
        loop_buttons();
        if (!client.connected())
        {
                reconnect();
        }
        client.loop();
        static unsigned long lastentry = 0;
        static unsigned long lastentry2 = 0;
        if (millis() - lastentry > 200)
        {
                pinMode(2, OUTPUT);
                digitalWrite(2, !digitalRead(2));
                lastentry = millis();
        }
        delay(50);
        if (millis() - lastentry2 > 1000)
        {
                Serial.println(ESP.getFreeHeap());
                lastentry2 = millis();
        }
}

Answer 1

In case somebody finds this when faced with the same issue: I had a similar problem on a Pico W. Turned out that the Serial.println()s in the MQTT callback clobbered the MQTT+WiFi stack. Something did not multitask nicely. Not accessing the Arduino Serial port in the MQTT callback fixed it.