Refactor comms: save 130+ bytes RAM

[adbancroft]

PR Effect

1. Save between 53 (compiler reported) and 138 bytes (TS reported) of RAM
2. Increase the reliability of the free memory count reported back to TS: it can fluctuate wildly with minor code changes.
3. (minor) Save 5Kb of flash
4. (subjective) Improve readability of new comms code.

Tested on Mega2560 using Ardustim. No loss in loops per second.

Not tested on CAN or SD hardware - but that code is unchanged

Why

Sometimes tiny one line changes (E.g. adding a condition to an if statement) will result in 60+ byte reductions in the free memory reported in TS. This makes any memory optimization work difficult.

This was traced to the processSerialCommand function. Assumption is that under certain conditions the compiler/linker will unroll some of the loops, causing the stack frame to expand and thus decreasing available RAM when freeRAM is called.

Detail

This is essentially a refactoring of the comms code (comms.cpp heavily and comms_legacy.cpp to a much lesser extent), to hoist code into separate non-inlined functions & thus reduce the size of the processSerialCommand stack frame

In doing this, there were obvious opportunities to remove duplicate code & consolidate global variables to provide a real reduction in RAM usage.

1. Compile comms.cpp as -Os (optimized for size). This is necessary but does not have any affect on performance.
2. Simplify the comms interface to 4 functions: serialReceive, serialRecieveInProgress, serialTransmit, serialTransmitInProgress
3. Remove all duplicate code blocks in comms.cpp
4. Consolidate the various comms boolean status flags into a single enum (SerialStatus)
5. Consolidate a few overlapping comms global counters
6. Remove unused or unneeded comms global vars
7. Move constant serial responses into flash (PROGMEM)
8. Remove the global FastCRC instance - it can't really be shared and is only used by the page CRC calc anyway
9. Add Doxygen comments on everything
10. Replace hard coded buffer sizes with sizeof().

[noisymime]

I'm seeing regular comms dropouts on Teensy 3.5 with this. I'll need to investigate further, but it consistently drops out every 15 seconds or so with this code. Reverting back to master on the same tune and the problem goes away.

Project is set to Teensy controller and new comms activated.

[noisymime]

TS debug log shows that it looks to be timing out part way through sending a packet every time this occurs:

30/08/22 2:34:33 PM :Debug: Blocked time to read outpc: 4 ms.
30/08/22 2:34:33 PM :Debug: Real OchDelay for Speeduino Dev: 0, timeout=300
30/08/22 2:34:33 PM :Time: 8:15.549: SENT 13 bytes, 13 bytes
x00 x07 x72 x00 x30 x00 x00 x77 x00 x27 xC4 x49 xCB                   ..r.0..w.'.I.

30/08/22 2:34:33 PM :Time: 8:15.554: READ 3 bytes, 3 bytes
x00 x78 x00                                                           .x.

30/08/22 2:34:35 PM :Time: 8:17.555: READ Timout after 61 bytes, Expected:123, actual read:61 Raw buffer, 61 bytes
x1A x00 x00 x00 x2C x00 x00 x00 x00 xF2 x21 x64 x00 x00 x00 x00       ....,.....!d....
x00 x00 x00 x2F x00 x00 x00 x0F x0B xF3 x4D xFF xFF x00 x00 x40       .../......M....@
x00 x00 x00 x00 x00 x54 x00 xFF x52 x00 x00 x00 x00 x00 x00 x00       .....T..R.......
x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00                   .............

30/08/22 2:34:35 PM :Debug: Comm Exception Caught: Timeout after:2001ms. requested timeout:2000, Expected bytes:123, bytes read:61

When it times out, it always seems to send 61 bytes first, so it looks like it's having an issue at that point. I've verified this same 61 bytes on multiple timeouts, so it's consistent. Keep in mind that would be 61 bytes + the 3 status/size bytes it sends at the beginning, so 64 bytes total, which seems like it might be relevant.

Data rate is set to 25, so that shouldn't be an issue.

[adbancroft]

I'll take a look - I don't have a Teensy handy, so it will require some guesswork.

TS is sending the 'r' cmd, 0x30 (send live values), offset 0, length 119 - which seems reasonable.

the 3 status/size bytes it sends at the beginning

Those go through OK (x00 x78 x00) & indicate a 120 byte response which is correct: 119 + SERIAL_RC_OK flag.

Then add in 4 bytes for the CRC & we get to 124 bytes but TS is trying read 123? Expected:123

[adbancroft]

It works OK on a Mega? I wonder if the Teensy serial code has an issue: the code is reliant on availableForWrite().

[adbancroft]

Ah hah! https://github.com/PaulStoffregen/cores/issues/10#issuecomment-61514955 might be relevant.

I'll return writeNonBlocking() to an older version that doesn't rely on availableForWrite().

[noisymime]

Still happening I'm afraid.

I found that if I turn the comms rate up to Max then the disconnections happen within 1-2 seconds of connecting every time. Again, reverting to current master corrects the issue. I'll try and find some time to investigate more over the next few days.

[adbancroft]

Could you post a larger comms log snippet, from one timeout to the next?

[noisymime]

Teensy Comms issue.txt Try this log file. It shows a few live read requests, then a timeout, TS restablishes the connection, does a heap of live data reads and then around 11 seconds after the initial timeout, the same issue occurs again.

[adbancroft]

I've pushed a couple of changes: not hopeful though.

[noisymime]

Still the same behaviour I'm afraid

[adbancroft]

Discovered that with Teensy 3.5, Serial.write() will timeout (after 70ms) and return -1 rather than blocking! (https://github.com/PaulStoffregen/cores/blob/master/teensy3/usb_serial.c#L215).

Code fixes applied.

[adbancroft]

@noisymime Teensy 3.5 boards are unavailable so I've started unit testing the comms code (which will be a separate PR). A few fixes uploaded. Any chance you could retest on a real board?

[noisymime]

As much as I hate to say it, still seeing these dropouts on the Teensy 3.5. They don't appear to be as frequent as they were previously, but they're still every 30s or so:

7/11/22 3:28:54 PM :Debug: Blocked time to read outpc: 4 ms.
7/11/22 3:28:54 PM :Debug: Real OchDelay for Speeduino Dev: 0, timeout=300
7/11/22 3:28:54 PM :Time: 2:04.030: SENT 13 bytes, 13 bytes
x00 x07 x72 x00 x30 x00 x00 x77 x00 x27 xC4 x49 xCB                   ..r.0..w.'.I.

7/11/22 3:28:54 PM :Time: 2:04.036: READ 3 bytes, 3 bytes
x00 x78 x00                                                           .x.


7/11/22 3:28:56 PM :Time: 2:06.036: READ Timout after 61 bytes, Expected:123, actual read:61 Raw buffer, 61 bytes
x09 x00 x00 x00 x1E x00 x00 x00 x00 x2A x00 x64 x00 x00 x00 x00       .........*.d....
x00 x00 x00 x31 x00 x00 x00 x16 x05 xD8 x49 xFF xFF x00 x00 x00       ...1......I.....
x00 x00 x00 x00 x00 x00 x00 x00 x4C x00 x00 x00 x00 x00 x00 x00       ........L.......
x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00 x00                   .............

7/11/22 3:28:56 PM :Debug: Comm Exception Caught: Timeout after:2001ms. requested timeout:2000, Expected bytes:123, bytes read:61
Nov 07, 2022 3:28:56 PM y.u run
WARNING: Comm Timeout Caught
U.b: Timeout after:2001ms. requested timeout:2000, Expected bytes:123, bytes read:61
	at y.t.a(Unknown Source)
	at F.J.b(Unknown Source)
	at F.J.a(Unknown Source)
	at F.J.b(Unknown Source)
	at F.J.z(Unknown Source)
	at y.t.e(Unknown Source)
	at y.u.run(Unknown Source)

It's still that same timeout after exactly 61 bytes (+3 bytes of overhead)

[adbancroft]

@noisymime I bought a Teensy 3.5, reproduced the timeout & uploaded a fix.

[noisymime]

@noisymime I bought a Teensy 3.5, reproduced the timeout & uploaded a fix.

Awesome! What was the fix in the end out of interest? It’s a little hard to follow along with the large number of commits going in.

[adbancroft]

In loop(), collapsing these nested if statements causes the lock up:

      if (serialInProgress == true) 
      { 
        if(Serial.availableForWrite() > 16) { sendValues(inProgressOffset, inProgressLength, 0x30, 0); }
      }

I can repro on master just by changing the above to (no other changes):

      if (Serial.availableForWrite() > 16 && serialInProgress == true) 
      { 
        sendValues(inProgressOffset, inProgressLength, 0x30, 0); }
      }

I'm guessing the Arduino Serial wrapper implementation for Teensy 3.5 has issues somewhere.

[TBAMax]

In loop(), collapsing these nested if statements causes the lock up:

      if (serialInProgress == true) 
      { 
        if(Serial.availableForWrite() > 16) { sendValues(inProgressOffset, inProgressLength, 0x30, 0); }
      }

I can repro on master just by changing the above to (no other changes):

      if (Serial.availableForWrite() > 16 && serialInProgress == true) 
      { 
        sendValues(inProgressOffset, inProgressLength, 0x30, 0); }
      }

I'm guessing the Arduino Serial wrapper implementation for Teensy 3.5 has issues somewhere.

Could it be the race condition happening here (Interrupt firing between the two comparisons)? Only differnce that I see in the code is changing the order of how conditions are checked: Serial.availableForWrite() > 16 first or last.

Or how this turned out at the end?

[adbancroft]

Could it be the race condition happening here (Interrupt firing between the two comparisons)?

Could be. I haven't investigated further - it's a subtle problem with multiple libraries interacting with one another (Teensy, Arduino + Speeduino). Diagnosing the root cause would likely be expensive and of low value since Teensy 3.5 has been superseded by Teensy 4.x.

[adbancroft]

@noisymime Could this PR be merged? I have a couple of other PRs I'd like to submit and would like to base them on this one for reliable free RAM reporting. I've been running this on a Mega2560 on the bench for months, but it would be good to expose other platforms.

I just rebased it to the latest master, so should be good to go.

[DeionSi]

I've used this a bit on mega2560 as well. No issues to report from my side.

[noisymime]

Yeah, will look to merge this soon (Hopefully later today). I'm just still smacking my head against the desk trying to figure out what's going on with that change to address the lockup on Teensy. So strange.

So just to confirm before final review, none of the earlier potential fixes or changes that went into this to try and resolve the Teensy issue need to be pulled out or anything?

[adbancroft]

So just to confirm before final review, none of the earlier potential fixes or changes that went into this to try and resolve the Teensy issue need to be pulled out or anything?

They are all worth keeping - they add more error checks, increase the level of defensive code, increase the use of non-blocking writes and make a few assumptions explicit.

[rafolg]

Nice work! it also works fine in Teensy 4.1