P2 USB Serial is very slow compared to Photon

Firmware Device OS
1

We run the same code on P2 and Photon
P2 is extremely slow takes 24-25 ms to run this code, while Photon takes 0 ms.
Firmwares:
Photon 1: 2.1.0
P2: 5.1.0

if we commend out:

Serial.println(gps_coordinate, 7); // <-- Low stream speed

Then P2 will also do it in 0 ms.

SYSTEM_THREAD(ENABLED);
//STARTUP(System.enableFeature(FEATURE_DISABLE_LISTENING_MODE));
STARTUP(WiFi.selectAntenna(ANT_INTERNAL));
SYSTEM_MODE(MANUAL);

unsigned long last_check_wifi_ready_millis = 0;
unsigned long boundaries_count = 0;

bool boundaries_parse_basic_settings(const char* p) {
  p = strchr(p, '[') + 1;
  uint max_length = 30;
  /*uint max_length = SIZEOF(boundaries);
  for(unsigned int i = 0; i < max_length; i++) {
    boundaries[i].gps_pos.lat = 0;
    boundaries[i].gps_pos.lng = 0;
  }*/

  boundaries_count = 0;
  
  boolean is_lat = true;
  while(true) {
    if(p[0] == ']')
      break;

    if(boundaries_count >= max_length) {
      for(unsigned int i = 0; i < max_length; i++) {
        //boundaries[i].gps_pos.lat = 0;
        //boundaries[i].gps_pos.lng = 0;
      }

      return false;
    }

    double gps_coordinate = atof(p);

    if(is_lat) {
      //boundaries[boundaries_count].gps_pos.lat = gps_coordinate;
      is_lat = false;
    }
    else {
      //boundaries[boundaries_count].gps_pos.lng = gps_coordinate;
      boundaries_count++;
      is_lat = true;
    }
     
    Serial.println(gps_coordinate, 7); // <-- Low stream speed
    p = strchr(p, '#') + 1;
  }

  return true;
}

void setup() {
    Serial.begin(115200);

    WiFi.on();
    WiFi.connect(WIFI_CONNECT_SKIP_LISTEN);
}

void loop() {
    if(millis() - last_check_wifi_ready_millis > 1000) {
        last_check_wifi_ready_millis = millis();

        /*WiFiAccessPoint ap[5];
        int found = WiFi.getCredentials(ap, 5);
        for (int i = 0; i < found; i++) {
            Serial.printlnf("ssid: %s", ap[i].ssid);
            // security is one of WLAN_SEC_UNSEC, WLAN_SEC_WEP, WLAN_SEC_WPA, WLAN_SEC_WPA2, WLAN_SEC_WPA_ENTERPRISE, WLAN_SEC_WPA2_ENTERPRISE
            Serial.printlnf("security: %d", (int) ap[i].security);
            // cipher is one of WLAN_CIPHER_AES, WLAN_CIPHER_TKIP or WLAN_CIPHER_AES_TKIP
            Serial.printlnf("cipher: %d", (int) ap[i].cipher);
        }
        if(!WiFi.ready()) {
            Serial.println("Connect...");
            //WiFi.connect(WIFI_CONNECT_SKIP_LISTEN);
        }

        Serial.printlnf("Connecting... %d", WiFi.connecting());

        Serial.print("WIFI: ");
        Serial.println(WiFi.SSID());

        Serial.print("IP: ");
        Serial.println(WiFi.localIP());
        //print_firmware_version();
        Serial.print("MAC address: ");
        byte mac[6] = {0};
        WiFi.macAddress(mac);
        
        for (int i = 0; i < 6; i++) {
            Serial.printf("%02x%s", mac[i], i != 5 ? ":" : "");
        }
        Serial.println();
        Serial.printlnf("gateway: %s", WiFi.gatewayIP().toString().c_str());*/

        unsigned long m = millis();
        boundaries_parse_basic_settings("8GyOdLExg8;[54.1234567#14.234567#54.1234678#14.234678#54.1234689#14.234689#]*15");
        Serial.printlnf("time: %lu", (millis() - m));
    }
}

Can you please help us out? Thank you so much!

2

Can you try running this code:

#include "Particle.h"

SYSTEM_THREAD(ENABLED);


void setup() {
    Serial.begin();
}

void loop() {
    static unsigned long lastRun = 0;

    unsigned long start = millis();
    Serial.printlnf("test %lu", lastRun);
    lastRun = millis() - start;
}

This was the simplified test of Serial.printlnf and it’s taking 3 or 4 milliseconds for me on a P2 with Device OS 5.1.0.

test 4
test 3
test 3
test 3
test 3
test 3
test 3
test 4
test 3
test 4
test 3
test 3
test 3
test 3
test 3
test 3
test 4
3

Thanks for your quick reply.

You have not specified the baud rate in your code, and I am not sure what the default is, but the 3-4 ms, just to print out some data looks incredibly slow.

Thanks!

4

There is no baud rate for USB serial. Even if you specify it, it is ignored.

It might be slower but the USB serial is typically only used for debugging so I don’t expect that would be a high priority to address.

5

I am sorry, but in our project we use the USB Serial as well, so for us it is a high priority to address.

As you have seen a basic code from 0 ms with photon, how can be 25 ms and saying it is not priority to address? :frowning:

Are there any other features of P2 which is slower than Photon?

Any solution, you could helps us?

Thanks.

6

25 milliseconds is very, very slow. If you are getting that with my sample code that would be an issue.

However 3 - 4 milliseconds doesn’t seem that bad. That’s what I was referring to as probably not a high priority.

The USB drivers are completely different between the STM32F205 and the RTL8217D. It’s hard to say where the slowdown is occurring, but if it’s in the Realtek SDK, then there is little that could be done. If it’s in the interface between Device OS and the Realtek SDK, then possibly something could be optimized.

I’m not saying that we won’t fix it, I’m just indicating on the list of priorities, USB serial speed is not a priority so it’s less likely to be fixed immediately.

7

I think I see why there is a speed difference. On the STM32, there’s a ring buffer between the USB serial calls and the actual USB hardware. It’s instantaneous because it goes into the buffer and goes to the USB host asynchronously. It’s not actually faster, it just returns faster.

On the RTL8721D it actually sends the data to USB before returning.

The easiest workaround if you don’t want to block is just wrap the USB serial with ring buffer.

8

I implemented a library that replaces Serial and makes the USB CDC Serial writes asynchronous.

The instructions are in the README here: https://github.com/rickkas7/AsyncUSBSerialRK

It makes the writes instantaneous:

test 0
test 0
test 0
test 0
test 0
test 0
test 0
9

I was mistaken. There is a buffer in the RTL8721D CDC driver. So it should not take 3-4 milliseconds (or more).

However, using the library with the external buffer definitely makes writes much faster, so now I’m not sure what the cause of the slowdown is. But the library would be a reasonable workaround until the actual problem is found.

10

Hello Rickkas,

Thank you very much for your time and effort.

Can you please make public your github repo AsyncUSBSerialRK?

I am happy that at least, we have found out that there is a misbehaviour. Hopefully your team will find out what cause the problem.

Thank you so much again, we test further P2.

11

I made the Github repo public. Sorry about that.

12

Thank you Rickkas

13

Hi @rickkas7

I was wondering if there has been any updates on this issue?

Comparing the serial output between Photon 2 and Photon 1, I still get a > 20 fold slow down in Photon 2 vs 1 with > 5ms compared to ~250 µs (details below) for a log message. I'm assuming this is still the same buffer issues you explained in this thread and was hoping there might be a way for solving this more generally, Or if not, could you kindly point out a good way to use your solution with the SerialLogHandler (recommend instead of Serial in the particle docs)? Note on context: running a stepper motor at a range of speeds up to pretty fast rates (requiring ~1 step / ms) which used to be no problem but now the Serial debug messages cause the stepper to skip.

Thank you for all your help!

Photon 2 (firmware v. 5.6.0):

0000010907 [app] INFO: log message took 5563 microseconds
0000011913 [app] INFO: log message took 5723 microseconds
0000012918 [app] INFO: log message took 5370 microseconds
0000013924 [app] INFO: log message took 5310 microseconds
0000014929 [app] INFO: log message took 5520 microseconds

Photon 1 (firmware v. 2.3.1):

0000008089 [app] INFO: log message took 220 microseconds
0000009090 [app] INFO: log message took 225 microseconds
0000010090 [app] INFO: log message took 220 microseconds
0000011090 [app] INFO: log message took 261 microseconds
0000012090 [app] INFO: log message took 220 microseconds

Generated with this slightly adapted version of your code:

#include "Particle.h"

SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler;

void setup() {

}

void loop() {
    static unsigned long lastRun = 0;
    unsigned long start = micros();
    Log.info("log message took %lu microseconds", lastRun);
    lastRun = micros() - start;
    delay(1000);
}
14

SerialLogHandler is but one of many things that could block the main application thread for a period of time.

You should run your timing-sensitive stepper motor code from a worker thread if you can use 1 millisecond time scheduling. Faster than that would be tricky because it would require interrupts, but there isn't a good way to use hardware timers on the P2/Photon 2 at this time. Also the relatively slow speed of the GPIO could be an issue.

15

Thank you so much for the quick response! Tried a worker thread for the stepper but the 1ms scheduling is not fast enough to allow for different speeds at the high end (e.g. one that needs a step every 1.4 ms skips). I think the GPIO should be fast enough (a few µs) not to be an issue. I read through the Threading explainer | Firmware | Particle details and came away with the conclusion that without interrupts my best option is to keep the stepper in main app thread and put everything else in worker threads but would love suggestions for better approaches.

16

I would look at how the NeoPixel library works. Instead of trying to precisely time the pulses, which is kind of impossible on the RTL872x, it uses the SPI peripheral to do it in hardware. You load up a buffer with the digital values to write out and the hardware streams out the bits with precise timing without using bit-level interrupts or timing loops.

2 Likes