Logging Overhead/Functionality

I've been running into issues with firmware performance on the msom and 6.2.0 and I've managed to tie the issue to logging.

I have a usb host ic (MAX3421E) on SPI1 that I use to communicate to an external ft232 device. It seems like I am failing to read fast enough from the usb host.

My firmware works perfectly when I have the programming port connected with logging attached to the msom, however, when I disconnect from this port, the usb host fails to communicate. The only way I can get it to work is to totally disable logging via SerialLogHandler logHandler, then it runs perfectly.

My system performs a good amount of logging while communicating, and it usually runs while Particle is connecting to the cloud, which is also producing a good deal of logs.

I can't help but think that there is something going on with underlying logging implementation. If I had to guess, the internal buffer used for logging is filling up and since there is no where to sink to, it eventually becomes full (network and user logs taking most of the space). Appending to it when it is full must be expensive for some reason.

This doesn't answer your actual question, but you can create a SerialLogHandler at runtime, so if you don't actually have to recompile the firmware to turn it on and off. But you do, of course need a way for the firmware to know that it should turn it on or off.

Is it common to have to disable logging for production builds? We've been using b402/404Xs until this most recent project and never encountered this kind of issue, despite similar setups and level of logging.

No, it should not be necessary but it might be a reasonable workaround.

Hey Radek, I discovered that projects that ran fine started to present weird issues on Photon 2, like here and here.
I have a feeling that the new MCU (Realtek RTL872xDM) struggles somehow does not like it when logging statements are all over the place, and especially in handlers. Since then I reduced logging somehow: I start with plenty around, but remove them as I get confident in the code.

Best,

Simple firmware that can reproduce the problem would be very helpful.

Its going to be hard to demonstrate exactly what I am experiencing, but I believe that I can demonstrate a slow down in execution when logging is used without a usb connection.

So what I did was first log 550 bytes in a loop 100 times to fill up any underlying logging buffer in setup(), then I had loop() run 10 times counting as high as it could in 5s, logging 550 bytes every 1000 counts. After 10 times, the results are published as a csv string.

When usb is connected, I am getting counts of about ~90k. When usb is disconnected, counts fall to ~25k. So the firmware execute 3.6x slower without the usb connection.

The effects are much more drastic in my real firmware, where there are additional threads running and network connections being made.

Furthermore, when testing on a b404X, the executions increased slightly when disconnecting the usb, going from ~119K to ~122.6K. So the issue is with the msom mcu.

#include "Particle.h"

SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_INFO);

uint32_t startTime;
uint32_t loopTime;
uint64_t count[10] = {0};
int loops = 0;

void setup() {
    Serial.begin();
    delay(5000);


    startTime = millis();
    for(int i = 0; i < 100; i++) {
        Log.info("Lorem ipsum odor amet, consectetuer adipiscing elit. Facilisi netus cursus commodo; potenti est augue felis. At himenaeos mauris; urna posuere malesuada venenatis facilisis vestibulum. Hendrerit nisl mi litora quis phasellus. Fames rutrum tellus sit semper euismod nec pulvinar primis. Tellus sociosqu duis per tristique mauris orci condimentum parturient orci. Sagittis nisl non suspendisse fringilla nullam. Nostra laoreet class bibendum cubilia fames tellus aptent maecenas torquent. Aenean viverra sit cubilia cubilia pharetra ipsum eros tortor.");
    }
    startTime = millis() - startTime;

    loopTime = millis();
}

void loop() {
    count[loops]++;
    if(count[loops] % 1000 == 0) {
        Log.info("Lorem ipsum odor amet, consectetuer adipiscing elit. Facilisi netus cursus commodo; potenti est augue felis. At himenaeos mauris; urna posuere malesuada venenatis facilisis vestibulum. Hendrerit nisl mi litora quis phasellus. Fames rutrum tellus sit semper euismod nec pulvinar primis. Tellus sociosqu duis per tristique mauris orci condimentum parturient orci. Sagittis nisl non suspendisse fringilla nullam. Nostra laoreet class bibendum cubilia fames tellus aptent maecenas torquent. Aenean viverra sit cubilia cubilia pharetra ipsum eros tortor.");
    }
    if(millis() - loopTime > 5000) {
        Log.info("Count=%d", count[loops]);
        if(loops >= 9) {
            Particle.connect();
            while(!Particle.connected()) {
                Particle.process();
            }

            delay(1000);
            Particle.publish(String(startTime), WITH_ACK);
            delay(1000);
            String res = "";
            for(int i = 0; i < loops; i++) {
                res += String(count[i]) + ",";
            }

            Particle.publish(res, WITH_ACK);
            while(true) {
                Particle.process();
            }
        }
        loops++;
        loopTime = millis();
    }
}


Being curious here, does reducing the log level to NONE improve things?

SerialLogHandler logHandler(LOG_LEVEL_INFO);

In a production environment I initialize my handler to LOG_LEVEL_NONE and only set it to LOG_LEVEL_INFO after I see that Serial.isConnected() changes from false to true. This keeps the print times to a minimum when serial isn't connected.

ohh, interesting, how do you do that in code? (if you can share - otherwise ignore my comment)

LOG_LEVEL_NONE results in 302K counts on msom regardless if a usb is connected for logging or not.

2 Likes

It's mostly what I did in this post, but to actually change the log level you'll need to check if serial is connected and use a flag to make sure you only change it once when it goes from not being connected to being connected.

In my case I only print 1 thing when I connect it to serial, then return the logger back to whatever it's default was (which is LOG_LEVEL_NONE in production).

void setup() {
    
  ...

  // Init logging (LOG_LEVEL_NONE for production, LOG_LEVEL_ALL for development)
  setLogging(LOG_LEVEL_NONE);
}

Then you'll want something like this in the loop

bool serialWasPreviouslyConnected = false;

void loop() {

  ...

  if (Serial.isConnected() && !serialWasPreviouslyConnected)
  {
    serialWasPreviouslyConnected = true;
    setLogging(LOG_LEVEL_INFO);
  }

  if (!Serial.isConnected() && serialWasPreviouslyConnected)
  {
    serialWasPreviouslyConnected = false;
    resetLoggingLevel();
  }
}
1 Like

oh perfect, I used that code, but never thought of using it in the way of disabling logging when serial is not present. Awesome stuff! I'll use it even more - thanks!

1 Like