Fix issue #8055 missing timestamps on serial monitor

[nitram509]

The root cause was a wrong initialized variable "isStartingLine".
Additionally, I did refactor the lambda method to an inner class,
in order to make it more convenient to write a unit test (UpdateTextAreaActionTest)

This PR also introduces 3 new dependencies for testing scope only.
Testing dynamic behavior with Mockito library enables better test coverage.

As usual, any feedback is welcome.

@cmaglie I would be glad if you could have a look, since you originally developed it.

[cmaglie]

@nitram509 , thanks for your contributions, but this still won't work as expected, the sketch:

void setup() {
  Serial.begin(9600);
  delay(5000);
  Serial.print("line1\nline2\n");
  delay(1000);
  Serial.print("line3");
  delay(1000);
  Serial.print("line4");
}

void loop() {
}

prints:

instead it should be:

15:59:30.694 -> line1
15:59:30.694 -> line2
15:59:31.686 -> line3line4

The problem is that the variable isStartingLine is not preserved across calls to message (so it doesn't "remember" that the stirng line4 is a continuation of the previous line). In my first implementation I thought it was, but actually it isn't becuase the Runnable is created new at each call to message(...).

Now, things that should be improved:

1. the message method is very performance-critical (in some cases it may be called thousand of times per second leading to a massive memory consumption and unresponsive system), so we must allocate/process as less as possible. For example the line:

String now = new SimpleDateFormat("HH:mm:ss.SSS -> ").format(new Date());

is very bad because it creates a new SimpleDateFormat that parses "HH:mm:ss.SSS" and creates all the internal structures to format the date string each time the message method is called. We can do all this things just once by creating the SimpleDateFormat object at startup and using that single instance, saving a lot of processing power.

2. If we can avoid to create a new UpdateTextAreaAction on each call to message(...) it would be better. I see that previously also the anonymous Runnable passed to invokeLater was created at each call, but as I said this was my mistake. Actually the block of variables:

      // Pre-allocate all objects used for streaming data
      Date t = new Date();
      String now;
      StringBuilder out = new StringBuilder(16384);
      boolean isStartingLine = false;

was meant to be created once for all at startup, so they should really be fields of AbstractTextMonitor.

Finally, can you explain briefly what the added jars do? I see that they are related to tests, that is a good thing, but I'd like to know a bit more.

[cmaglie]

This PR https://github.com/arduino/Arduino/pull/8131/files?w=1 moves the new Runnable() out of the streaming loop as I've explained.

[nitram509]

Thank you for providing, this feedback.

And thank you very much for catching/spotting a scenario, my this PR did not cover yet.
I will add a unit test for this as well.

Please, allow me some feedback to your comments as well.

1. I agree, the message method is a UI related one and should not block - hence, everything we do inside is performance critical. What I don't get is why it is called 1000 times? There is a 30Hz scheduler, means it is called 30 times a second.
   What do I oversee?

2. The SimpleDateFormat class is not thread-safe. According to JavaDocs, it is recommended to create new instances. This is especially critical since the anonymous Runnable action method is executed in another thread and using a shared - unsynchronized logDateFormat instance.
   I highly recommend using a separate instance.

Assuming there are only 30 instances per second created, my gut feeling says this is OK.
But maybe we should measure first?

3. Regarding the JARs I added ...
   The approach I did try to implement in UpdateTextAreaActionTest is called Behavior-Driven Development (BDD). See also https://www.baeldung.com/bdd-mockito
   I truly believe in tests and created a new one for "runnable - portion" of the AbstractTextMonitor.
   I would be glad if this would be adopted to Arduino code base in total.
   What do you think about this approach?

The JARs are only required for TEST phase and not needed at deployment/runtime of Arduino program.

[nitram509]

This duplicates #8131
(Just for completeness)

[nitram509]

I did a small comparison by using VisualGC graphs

TL;DR

To me they look almost identical.
Some strange "chainsaw teeth" are visible, but still, the overall GC times in PR8055 are a little smaller.
I consider it more worth to mention, that in PR8055 some more JIT happens, which might explain the faster GC times.

Test methodology

• using Java 1.8.0_181 64bit Windows 10
• using JVisualVM incl. VisualGC plugin (included in JDK)
• using a little C-snippet to create some text (see below)
• starting the Arduino program directly from within the IDE in regular mode (not debug mode)
• directly opening the serial monitor
• attach VisualGC and watch the graphs
• wait until the graph is "full", means touches the left side of the window
• stop the java process

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

void loop() {
  Serial.print("The quick brown fox jumps over the lazy dog\n");
  delay(10);
}

Results

1. monitoring PR #8131

2. monitoring PR #8055

[nitram509]

The commit cd6331c fixes the issue/bug @cmaglie mentioned with his first comment.
Also, I did add a proper test.

May I ask for another review, please?

[cmaglie]

The test sketch you're using is slowed down, you should remove the delay(10) to increase the bandwidth utilization. BTW even then the available bandwidth on USB is not maxed, to make a real stress test you should use a board with a 32-bit MCU and a native USB port, like the Arduino Due/Zero or Teensy and run the following sketch:

void setup() {
  Serial.begin(115200);
}
void loop() {
  while (true)
    Serial.print("Hello\nWorld\nHello\nWorld\nHello\nWorld\nHello\nWorld\n");
}

This sketch is able to crash old versions of the Arduino IDE, or even make the PC unresponsive.

What I don't get is why it is called 1000 times? There is a 30Hz scheduler, means it is called 30 times a second. What do I oversee?

oh, you're right, what I was referring to is the method addToUpdateBuffer, that method is indeed called at the pace of the incoming data from the serial port. As you said the timer guarantees that the incoming buffer is emptied and pushed to the message method every 1/30 seconds

The SimpleDateFormat class is not thread-safe. According to JavaDocs, it is recommended to create new instances. This is especially critical since the anonymous Runnable action method is executed in another thread and using a shared - unsynchronized logDateFormat instance. I highly recommend using a separate instance.

The invokeLater call ensure that the dateFormat instance is called only by the "AWT event dispatching thread", since this is a single thread there is no need for synchronization (at least until now I haven't seen anything suspicious happening :-))

[nitram509]

Thank you for your feedback, @cmaglie.

Indeed, for a full regression test, the delay() will not work.
No doubts, there is room for improvement. I did make the first step ;)

When there is a single-thread guarantee for the UI, than using a non-thread-safe class would cause probably no harm. Thanks for pointing this out.

Do you have any thoughts regarding the tests or newly included JARs?

Since we have two PRs with the same purpose, I would like to leave my ego out and come to a conclusion or suggestion/proposal for the core DEV team (I don't know if you are part of, are you?).

May I ask for you input too, to collect some criteria to compare the two PRs (see below)?
What else is needed to make a decision, from your perspective?

Since the feature is implemented in both, it seems to me, we could just focus on non-functional criteria.

1. Amount of code change
2. Performance impact
3. Software quality impact
4. ... (you name it)

My view so far:

1. the PR Fix serial monitor timestamp print regression #8131 has less code changes
   the PR Fix issue #8055 missing timestamps on serial monitor #8088 adds new (test-)dependencies, which introduce a new test methodology BDD.
   --> point for PR Fix serial monitor timestamp print regression #8131
2. Performance wise I would judge it a draw, no significant differences could be measured (so far)
   --> points for both
3. the PR Fix issue #8055 missing timestamps on serial monitor #8088 adds unit tests for some functionality where there was no test before
   along the refactoring (which was made) the single responsibility principle was applied for the actual action.
   --> point for PR Fix issue #8055 missing timestamps on serial monitor #8088

Simple point wise it's a draw so far ;)
That said, I have a strong preference for adding the tests (incl. the changes) and see this more as a starting point for future test coverage improvements.

I'm curious and looking forward to read your opinion.

[cmaglie]

Hi @nitram509,

I've made some tests with an Arduino Due, indeed the performance difference is negligible, I was deceived by the addToUpdateBuffer as we already discussed.

At this point I would like to merge this one, but I have a last concern looking at your patch: I see that you changed the boolean field isStartingLine to static, I guess to preserve the state of the variable, but this makes the field shared across all AbstractTextMonitor. This is not a problem for now since only one serial monitor could be opened at a time, but we are leading toward a pluggable system that allows different kinds of "monitors" (the starting point is #8038) and I do not exclude that more than one monitor could be opened at the same time.

I think that you made the UpdateTextAreaAction so this can be mocked and tested, but can't you do the same with the AbstractTextMonitor class? I'm wondering that the whole point of this UpdateTextAreaAction is just to have some Runnable to feed into invokeLater but, since we determined that there is no performance penalty, a lambda that calls a method of AbstractTextMonitor fits much better here, something like:

  public void message(String msg) {
    SwingUtilities.invokeLater(() -> updateTextArea(msg));
  }

  boolean isStartingLine = true;
  //other fields here, instead of passing them in runnable constructor...

  void updateTextArea(String msg) {
     ....the body of the old UpdateTextAreaAction.run() method here....
  }

[cmaglie]

Hi @nitram509

This one is taking too much dev-time, in the end I opted to pick your first commit, changed the class into a method (that "incidentally" fix also the isStartingLine bug) and added a test for that, see #8131, I think this gets the best of the two approaches.

Thanks for all your feedback!