Add "show timestamp" to serial monitor

[cmaglie]

This is a rebase of (the remaining part of...) #5921.

@MichalSy @facchinm

[ArduinoBot]

✅ Build completed.

Please test this code using one of the following:

⬇️ http://downloads.arduino.cc/javaide/pull_requests/arduino-PR-6178-BUILD-721-linux32.tar.xz
⬇️ http://downloads.arduino.cc/javaide/pull_requests/arduino-PR-6178-BUILD-721-linux64.tar.xz
⬇️ http://downloads.arduino.cc/javaide/pull_requests/arduino-PR-6178-BUILD-721-windows.zip
⬇️ http://downloads.arduino.cc/javaide/pull_requests/arduino-PR-6178-BUILD-721-macosx.zip
⬇️ http://downloads.arduino.cc/javaide/pull_requests/arduino-PR-6178-BUILD-721-linuxarm.tar.xz

ℹ️ The linuxarm build is still experimental and may not be always available.

[mfalkvidd]

Very nice! This feature will be very useful when troubleshooting, especially when helping people in forums where I can't easily manually add timing information in the debug prints.

I saw earlier concerns about performance impact so I did some tests. My conclusion is that the timestamp option does not add measurable overhead. At very high speeds, the RAM requirements for storing the serial console in memory come into effect, but that's regardless if the timestamp is activated or not.

Tested on Windows 7 with a Intel i7 3770 CPU (a high-end but 5 years old CPU that is now end of life)
ESP8266 at 250000 bps
With timestamp: Cpu usage 1%. 3560 lines per second.
Without timestamp: Cpu usage 1%. 3560 lines per second.

I had to increase the maximum memory size because the amount of serial data was getting too big (even without timestamp) for the default setting of 256MB (Exception in thread "AWT-EventQueue-0" java.lang.OutOfMemoryError: Java heap space) so for the next test I set

run.options.memory.initial=2560
run.options.memory.maximum=2560

ESP8266 at 500000 bps
With timestamp: Cpu usage 1-3%. 7130 lines per second.
Without timestamp: Cpu usage 1-3%. 7130 lines per second.

ESP8266 at 1000000 bps
With timestamp: Cpu usage 1-4%. 14290 lines per second.
Without timestamp: Cpu usage 1-4%. 14290 lines per second.

[mfalkvidd]

@cmaglie do you know what the next step is to get this merged?

[PaulStoffregen]

Have you tested with Arduino Due printing without delays?

[mfalkvidd]

@PaulStoffregen I have not. But the interface is serial. To me, which device sending the serial data should not affect the implementation on the Serial Monitor side. However, I'm not that versed in the inner workings of the Arduino IDE.

[PaulStoffregen]

I'm running a quick test right now on Linux 64 bit running on a fast desktop (i7-3930K processor, 32G RAM, dual SSD), with Teensy 3.6 running this program:

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

// count the number of loop() runs per second
unsigned long count=0;
unsigned long priorCount=0;
unsigned long priorMillis=0;

void loop() {
  unsigned long nowMillis = millis();
  if (nowMillis - priorMillis < 1000) {
    count = count + 1;
  } else {
    priorMillis = priorMillis + 1000;
    priorCount = count;
    count = 0;
  }
  Serial.print("Hello World ");
  Serial.println(priorCount);
}

Without "Show timestamp", CPU usage is around 20%.

When the "Show timestamp" option is checked, CPU usage goes to approx 110% (using more than 1 core fully).

The "Autoscroll" checkbox also stops working when "Show timestamp" is checked.

[mfalkvidd]

How do you get the Serial Monitor to use 12,000,000 bps? The highest alternative available in the drop-down in my Arduino IDE is 2,000,000.

Will most people that activate the timestamp option use it for these high speeds? Almost all examples I see use 9600bps or 115200bps.

The autoscroll malfunction is strange. I did not experience that during my tests.

[PaulStoffregen]

Native USB boards like Due, Zero, Leonardo, Teensy, & some ChipKit always communicate at 12 Mbit/sec or 480 Mbit/sec. The baud rate number is ignored.

Changes to Arduino's serial monitor must be tested with these boards. I know you are probably only concerned about the ESP8266, but it is a slow serial board which can't really transfer nearly as much data as native USB boards.

[mfalkvidd]

Not that it matters much to this discussion, but I find this feature useful on the Atmega328-based Arduinos as well.

Do the use cases for streaming 12mbit data and getting a time stamp really overlap? What I'm getting at is that a user who's streaming 75,000 lines per second (as in your test, if I did the calculations correct), will not likely want the time stamp, and therefore will not activate it?

Do we know which use cases stream 12mbps to the Serial Monitor? I can imagine streaming data from an Arduino to a computer at 12mbps, but is the Serial Monitor with time stamp enabled really the correct receiver for that stream? I would imagine a python script or similar would consume the stream, and the Serial Monitor would not be involved.

Do these 12mbit use cases benefit from a time stamp? If they do, what precision does the time stamp need to have? The current implementation has a precision of milliseconds, which means 75 lines will be printed with the same time stamp. Is that acceptable?

I know you are aware of this, but to make sure it doesn't get lost: Note that using 12mbps serial speed and only printing occasionally will not impact performance.

To me, the use case for time stamps is to see what happened when, especially when the Arduino periodically logs data or state. For that use case, users can enable time stamps. For streaming data, users can choose to not activate this feature.

[PaulStoffregen]

In the not too distant past, this program would crash the Arduino IDE if run on Arduino Due:

void setup() {
  SerialUSB.begin(9600);
}

void loop() {
  SerialUSB.println("Hello World);
}

The GUI thread would consume far more than 100% CPU and get hopelessly overwhelmed with events, unable to ever catch up. Memory usage would grow without bound, until the JRE ran out of memory.

Please take this performance issue seriously and do not return the Arduino IDE back to those bad old days!

[PaulStoffregen]

Today many boards like ESP8266 & ESP32 still use slow serial, but native USB is becoming the norm for new boards. Most are still only 12 Mbit/sec, and some with 480 Mbit/sec (notably Arduino Due) currently aren't anywhere near fast enough to fully saturate USB at that speed. But this will soon begin changing, as Cortex-M7 chips with clocks in the 400 to 800 MHz range and powerful EHCI USB controllers become the norm over the next few years.

The Arduino IDE's serial monitor is still too inefficient to support the next generation of microcontrollers. We need nice features for users, but they need to be implemented efficiently.

[mfalkvidd]

How about disabling the time stamp generation if the speed on the Serial Monitor is set higher than some value, for example 1,000,000?

That should remove the risk of overwhelming the GUI thread. It would also deny this feature to anyone using high speeds but logging infrequently, but they don't have this feature today so to them it wouldn't make a difference.

[feikname]

How about having another thread that runs every (insert reasonable number here) ms to show the timestamp if there was new data sent since the last timestamp insertion? (i.e. showing a new timestamp every 7ms seems very reasonable to me)

Preferably adjustable with preferences.txt of course.

[facchinm]

Merged manually as 1fd794d and a15abac ; the speed/cpu consumption limitations are clear and should be solved in a future release, but at the moment the checkbox is off by default and there's no overhead for the default behaviour, so we're fine with it.