Serial communication errors: checksum and line number not +1

[Sebastianv650]

As mentioned in the advance dev thread, I'm getting communication errors when printing over USB. The error messages are:

Resend: 380
Error:checksum mismatch, Last Line: 385
[ERROR] Error:checksum mismatch, Last Line: 385

and

Resend: 386
Error:Line Number is not Last Line Number+1, Last Line: 412
[ERROR] Error:Line Number is not Last Line Number+1, Last Line: 412

Printer: Lulzbot TAZ 5 (Rambo board). I'm also writing for others from the Lulzbot forum, where we have threads from time to time that are also based on communication problems.

What I know through tests:

• This is not related to my advance patch, but enabling it makes the problem worse as the main isr takes more time.
• It's not the USB cable or the USB port.
• It scales with print speed (higher ISR rate): At normal speeds (say up to 50-60mm/s) there is nearly no error, maybe one in some print hours. At high speed, especialy high speed combined with high needed command transfer rate due to short line segments, the error rate increases.
• It was better in RC4, I get significant more errors in current RCBugFix.

I have not the skill to track this down in detail without help. I guess the main ISR can interrupt something in the USB communication, if that happens the transfer gets corrupted. There are more errors as the ISR rate or duration is increased because the probability increases that an ISR happens at the time where something with the communication is done.

If there are already ideas to test in some branches or forks, I would be happy to test them.

[Blue-Marlin]

PR "Encapsulate Stepper, Planner, Endstops in singleton classes" #3631 can potentially affect the ISR-runtime.

[AnHardt]

@Sebastianv650
What host program do you use? What BAUDRATE do you use? Is the error rate significantly dropped when using a lower BAUDRATE?

If you are using RepetierHost in not ping-pong-mode, try ping-pong, or reducing 'Receive Cache Size' to about 75%.

If you have the suspicion your LIN_ADVANCE code takes much extra time like when the 'normal' stepperISR goes in dubblestep/quadstep-mode, try to put in:

      #ifndef USBCON
        customizedSerial.checkRx(); // Check for serial chars.
      #endif

[Sebastianv650]

I'm using pronterface with 250000 baud, changed it to 115200 with no sucess.
I'm not using speed ranges where double stepping would occur in the last days, I went up to 80% of single step mode.

[thinkyhead]

#3631 can potentially affect the ISR-runtime

Not if the compiler is smart. Firstly, using myObject.functionCall() is not any more expensive than functionCall(). So that alone should not add any cycles. In "Embedded C++" we assiduously avoid virtual, this->, objPointer->, etc. to ensure flatter compilation.

The compiler should also be smart about this:

ISR(TIMER1_COMPA_vect) { stepper.isr(); }

It should recognize that it should not do this…

ISR_HANDLER:
  JSR Stepper_isr
  RET

…but that it should do this…

ISR_HANDLER:
  JMP Stepper_isr

…and, frankly, it should recognize that:

ISR_HANDLER == Stepper_isr

Am I putting too much trust in the compiler?

[jbrazio]

I just don't agree with this->method() being less efficient than method() when inside the class, the compiler will throw away the this reference and do a JMP func() in both cases, the advantage of using this-> is increased readability.

[Blue-Marlin]

I'm using pronterface with 250000 baud, changed it to 115200 with no sucess.
I'm not using speed ranges where double stepping would occur in the last days, I went up to 80% of single step mode.

Using Promterface translates to me as using ping-pong, That makes overfilling the RX-buffer unlikely.
No improvement with 115200bd means doublet time between arriving chars. That makes missing to fetch a char from the register unlikely.
Errors on the USB between host and AT32U2 (used as the USB chip) is unlikely because of the USB block checksum.
Errors on the serial line between AT32U2 and AT2560 (hardware problem). That's unlikely to change with release versions. But more likely with increased frequency of high current lines near the serial lines.
RX-buffer corruption. Is unlikely with 8bit buffer indices and interrupt protection. Likelihood increases with the amount of buffer content - unlikely with ping-pong. 'Strange' pointer from somewhere? Wrong array indices in a near by array?

Hard to say what is going on.
Maybe @AnHardt's little input debug helpers can give a hint.
AnHardt#32

[jbrazio]

I'm using pronterface with 250000 baud, changed it to 115200 with no sucess.

This for me somehow clears the ISR delay errors.. otherwise we would need to be really screwing it up to still affect 115.2bps.

Are we positive this is now hardware ? Could it be noise on the serial line ? Noise could increase with the higher stepping on the motors at higher speeds. Do you have a scope ?

[Sebastianv650]

Sorry, no scope available. I can't imagine it's hardware. I'm in the process of printing 70 identical parts, so all tests are done with the exact same gcode. RC4 runs "smooth" even with advance (maybe 4-5 errors per hour), RCBugFix on the other side is flooding the pronterface status window with error messages and 1-2 times per hour the printer is even doing wrong "print" moves to one edge of the print bed (only limited by software end limits I guess).

This for me somehow clears the ISR delay errors.. otherwise we would need to be really screwing it up to still affect 115.2bps.

I might be wrong, but do you think so? If we need to transfer 10 commands for a print, say each one takes 0.5s (I know, only for easy calculation) at 115200 baud and 0.25 at 250000 baud and the ISR is running at a fixed rate. Than it should be more likely that a ISR is "hitting" the transfer of the 0.5s long slow 115200 baud than it's hitting a only 0.25s long transfer?
For me as a hobby-programmer I would say higher rate should be better to not influence with stepper ISR.

I will build AnHardt#32 into my code and run some tests with it, but it will take some time to get results as my printer is blocked for the next 9h.

[jbrazio]

Yes but lowering the baud rate you'd expect to see a difference in the number of errors, if no difference then one of two things could be true:

• it's not the ISR
• it's the ISR with a deep screw up

But the ISR changes were minimal.

So last good version was RC4 right ?

[Sebastianv650]

OK to be honest I can't say for sure if lowering the baud rate made it worse. In both cases, the errors come one after the other. If we want to know that precise, I have to do several runs with both baud rates and count an average value.

Yes I'm seeing errors also in RC4, but without advance maybe 1 in 10h print. Don't nail be down on the number, but it's a rate where I'm not worried about.

[thinkyhead]

RCBugFix on the other side is flooding the pronterface status window with error messages

@Sebastianv650 Are you talking about "host keepalive" messages like "busy:processing", or line number / checksum errors?

[Sebastianv650]

All versions of error messages: Mostly checksum, some line number mismatch, some "no checksum with line number".

[Sebastianv650]

I did @AnHardt debug changes, here is an example:

SENT: N803 G1 X145.808 Y146.311 E0.14351*107
RECV: ok N802 P0 B2 R128 "N802 G1 X147.472 Y147.976 E0.11133"
SENT: N804 G1 X144.915 Y146.058 E0.15620*108
RECV: ok N803 P0 B2 R128 "N803 G1 X145.808 Y146.311 E0.14351"
SENT: N805 G1 X147.099 Y148.241 E0.19841*98
RECV: ok N804 P0 B2 R128 "N804 G1 X144.915 Y146.058 E0.15620"
SENT: N806 G1 X146.764 Y148.544 E0.20460*98
RECV: ok N805 P0 B2 R128 "N805 G1 X147.099 Y148.241 E0.19841"
SENT: N807 G1 X143.891 Y145.671 E0.26015*107
RECV: Error:checksum mismatch, Last Line: 806 "N803 G1 X145.808 Y146.311 E0.14351"
[ERROR] Error:checksum mismatch, Last Line: 806 "N803 G1 X145.808 Y146.311 E0.14351"
RECV: Resend: 807
SENT: N807 G1 X143.891 Y145.671 E0.26015*107
RECV: ok N806 P0 B3 R128 "N806 G1 X146.764 Y148.544 E0.20460"
SENT: N808 G10*24
RECV: ok N806 P0 B1 R128 "N806 G1 X146.764 Y148.544 E0.20460"

Somebody has an idea? The line looks OK to me..

[bobc]

The actual data exchange looks good, although we don't see all the checksums. But I am puzzled by the error message - is it 806 or 803 that has the error? And why does it then resync at 807? What really happened to 803 to 806... odd.

[thinkyhead]

The line looks OK to me..

Looks bizarre to me. It's telling us that when it tries to interpret line "806" it is seeing the text of line "803."

Did I already ask which version of Arduino you are using to build with?

[Sebastianv650]

I'm using 1.6.8.
I did a test, adding customizedSerial.checkRx(); also in the extruder ISR. This reduced the error rate significantly, now it's ~4 for a 6min print, without this second check its >> 12.

[AnHardt]

Sorry.
AnHardt#32 is debug code that used to work before serial_line_buffer[] was introduced in get_serial_commands(). Now when the errors happen the relevant string is still in serial_line_buffer[] and not copied to command_queue[cmd_queue_index_w] yet.
The wrong line is printed.
Sorry.

[thinkyhead]

@Sebastianv650 Well, that is interesting. I cannot (quite) imagine what would make the stepper isr significantly slower between RC4 and RC6, but it sure seems to be the case. I'll do more research on optimizing C++ code and see if there's a way to keep the encapsulated Stepper::isr method but still maintain top performance.

[thinkyhead]

@AnHardt @Sebastianv650
If the gcode_line_error function is altered to take a string pointer, then you can pass serial_line_buffer to it from within get_serial_commands and print that string instead.

[Sebastianv650]

Thanks for the hints, @AnHardt, @thinkyhead ! I did the modification and it's now printing the corrupted line, here one of the many ones I get:

SENT: N967 G1 X134.346 Y136.203 E2.96084*105
RECV: ok N967 P0 B3 R128 "N967 G1 X134.346 Y136.203 E2.96084"
SENT: N968 G1 X134.403 Y135.652 E2.96970*97
RECV: ok N968 P0 B3 R128 "N968 G1 X134.403 Y135.652 E2.96970"
SENT: N969 G1 X139.652 Y140.901 E3.08866*96
RECV: Error:checksum mismatch, Last Line: 968 "N969 G1 X19.652 Y140.901 E3.08866*96"
[ERROR] Error:checksum mismatch, Last Line: 968 "N969 G1 X19.652 Y140.901 E3.08866*96"

It's missing single chars in commands, in this example the "3" in the X coordinate. Now it makes also sense that my change yesterday (putting customizedSerial.checkRx() also in the stepper ISR) made it less worse: The "input" is checked more frequently and missing chars are not happening that often any more.

But I'm not smart enough to know the real answer: Why it is missing chars when the main stepper ISR takes more time?

[Sebastianv650]

After thinking about what @AnHardt wrote:

Missing chars -> an ISR takes too long, or a CRITICAL_SECTION is not closed properly. The serials RX-interrupt is executed too late - the RX-registers content was replaced by the next char.

and looking how Marlin handles available chars, I would sum up as followed. Please correct me if I'm wrong:
.) At a baud rate of 250000, there is a new char every 40µs. If the char is not read, it gets replaced by the next one sent by the host.
.) There are two ways of storing a new char:
The interrupt triggered when a new char is recieved - but this one has nearly the lowest possible priority available on the Atmega so it may be "postponed" by timer0 interrupts used by the steppers, it get's even worse with the timer1 used by the advance stepper ISR.
That may be the reason why there is another checkpoint inside the stepper ISR, which tries to store a char at every loop. But if this loop takes more than 40µs, the char is gone - my error messages are triggered now.

So the answer why I get much more errors with enabled advance is clear: I'm doing a few more calculations inside stepper ISR. This may take the ISR close to the 40µs.
That there are even more errors with RC6 means that the stepper ISR is a tad slower than in RC4. Maybe not much, but 40µs are not much too..

To proof this, I set the baud rate to 115200 again. I did this already as I saw the errors when I started the advance coding, without success. But I optimized the code since theese day. With 115200 baud the Atmega has 2x the time to get a char from the buffer. With the latest advance code, this solved 100% of the error messages! :-) (Remember: I'm using the RC4 version. I have to see if that's also true for RC6.)

This leads two following options:
.) Live with "only" 115200 baud. Was sombody testing if this ever has an impact to printing? Maybe the impact due to the fast char impact at 250000 baud is worse than 115200 baud "slow" transfer rates?
.) Find some ways to improve the stepper ISR so it takes less cycles.
.) Test if it helps when the serial receive thing has it's own ISR, fired at a fixed rate depending on the selected baud rate. This way, no char should be lost. In worst case, this will brake down the rest of the code due to the high check rate, but in this case the current implementation shouldn't be better as than you get the missed chars..

Your opinion?

[thinkyhead]

Find some ways to improve the stepper ISR so it takes less cycles.

I'm considering that option, which basically means reverting all the Singletons back to (still better-encapsulated) flat C code with static linkage. But before I do that, I'm looking to exhaust every other option, for example finding out of the C++ compiler can be "smarter" and produce machine code that is just as efficient as the old code.

Honestly, I do not know how much the compiler output truly differs. But my expectation was that the compiler would be smart enough to see the Singletons as basically just being used as "namespaces" to encapsulate some functions. But linkage is something compilers are weirdly religious about sometimes.

I wish we had better profiling so we could see where all our cycles are being spent. That Marlin Simulator could probably help with this, since it would also be affected by the linkage.

That there are even more errors with RC6 means that the stepper ISR is a tad slower than in RC4.
Remember: I'm using the RC4 version. I have to see if that's also true for RC6.

If the performance issues and communication errors are manifest in RC4 then perhaps the current Singletons aren't the main culprit. Running an Advance ISR at 3-4 times the rate of the Stepper ISR could actually be more problematic, and perhaps mutliple-stepping in the Advance ISR is the better solution.

Again, proper profiling would be most helpful!

[thinkyhead]

Something worth reading…

http://www.drdobbs.com/implementing-interrupt-service-routines/184401485

[andrebstv]

It really points to starvation, that is the processor is running out of time and pretty much only working on the ISR. I`m not sure if what is being generated with c++ coding is slower than C, though I must say the probability of that is quite high.

It does depends on the compiler flags/settings. Note that arduino IDE uses a quite optimized version of these flags. It won`t get (much) better than that.

[AnHardt]

I love it, when a theory can be confirmed by a test.

250000 <-> 115200 baud. Receiving with 115200bd should be ok. Sending with 115200bd may be a problem. Marlin is busy waiting while writing. (https://github.com/MarlinFirmware/Marlin/blob/RC/Marlin/MarlinSerial.h#L122 https://github.com/MarlinFirmware/Marlin/blob/RC/Marlin/MarlinSerial.h#L152 ++)
Writing for 80 chars means about 3.2ms at 250000bd, more than 6ms at 115200bd. That could make a difference as soon we are not only sending 'ok's but lots of debug output. However the ISRs can interrup the busy waiting.

serial receive thing has it's own ISR

It already has. But no (software) interrupt can interrupt an other interrupt. The interrupt priority only schedules, who is the next, if more than one interrupt request is in the register, after the current interrupt has finished.

[thinkyhead]

I love it, when a theory can be confirmed by a test.

Thank you testers, feedbackers! Without you we who know code well, but not the platform or the compiler, often feel a little lost in the dark. But through this kind of experience, much is learned. Deep gratitude to all of you!

[andrebstv]

Or you could put transmition on a TxInterrupt routine....
On May 10, 2016 12:16 PM, "Roxy-3DPrintBoard" [email protected]
wrote:

Sending with 115200bd may be a problem. Marlin is busy waiting while
writing.

This is kind of a brute force way to work around it... But this would work
for either 115,000 or 250000 baud rate. And there isn't much penalty
because we are busy waiting anyway. As long as we are spinning waiting to
see if we can transmit the character, we probably should be checking to see
if a character came in the receive side of the UART. We would just add a
little bit of jitter to when we return:

FORCE_INLINE void write(uint8_t c) {
  while (!TEST(M_UCSRxA, M_UDREx))
    checkRx();
  M_UDRx = c;
}

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#3680 (comment)

[ruggb]

Maybe we should start a new thread - this one has been confused with other things..........
BUT I am still of the opinion that Marlin is trying to do too much - or it can't do what it needs to do in the time between commands. Lowering the baud rate may help but it will not cure the problem. Lowering the print speed worked for me - until more stuff was added for Marlin to do between commands. Maybe the only solution is more horsepower in the hardware and more RAM.
IMHO, the error is because the printer misses a command then responds to the next command while the computer is waiting for a response from the previous one. The model obviously showed the result of missing commands.

[Sebastianv650]

@VanessaE I bet that's the reason, MINIMUM_STEPPER_PULSE will increase the duration of each stepper ISR and therefore it's much more likely to miss a char.

@ruggb I'm afraid if we create a new thread we will start from scratch while there is already a lot of investigations done here. Therefore I can also say that Marlin is missing single chars from a command that can't be received due to stepper ISR is executed at the specific time.
More CPU speed can reduce the error rate (as far as there is neraly never an error visible), but the flaw is inside the design. If the stepper ISR is blocking at the needed time, and it takes so much time that the next char is already incomming when the ISR is finished, the error is unavoidable..

[Blue-Marlin]

Chars can get lost if (E_step_loops * pulse_length > 1 / (baudrate / 10))

Maybe a

    #ifndef USBCON
      customizedSerial.checkRx(); // Check for serial chars.
    #endif

inside the loop helps. Ideally between starting and stopping the pulses.

[ruggb]

I think the obvious question is: Does the hardware have enough horsepower to run both the ISR and handle the i/o data stream simultaneously? If it does not, then there are three options:

1. Require higher performance H/W to run Marlin. - that probably won't go over big with users.
2. Eliminate features that bog down the ISR - That won't be any fun for users.
3. Make the code more efficient - that may be a BIG challenge for developers.
   I believe @thinkyhead had indicated in a previous thread that he thought he had the ISR as fast as he could make it. If so Compile in arduino 22, M80/M81 support, remove M140/M190 from supported gcodes #3 is impossible, not a challenge. I think he also indicated the i/o data stream was handled via interrupt - or he was striving to implement it that way. I don't know where that stands, but that goes to the first question on hp.
   Is there any overhead in the code for features that are disabled?

[Sebastianv650]

I don't see that as a main problem of processing power, @Blue-Marlin is bringing it to the point. If we could tell the ATMega that serial communication has a higher priority than the stepper ISR and that it should interrupt the stepper ISR, there would be no problem. But that's impossible. Putting some checkRX() at good positions inside the stepper ISR can work.

With Blue Marlins calculation, there is a limit of 87µs at 115200 baud and 40µs at 250000 baud.
At the moment, the stepper ISR takes about 50µs, therefore if 250kbaud is working or not depends more or less only on how lucky you are.

@ruggb only disabling features that do calculations inside the stepper ISR can minimize the error rate. There are not much: MIXING_EXTRUDER, LIN_ADVANCE, ADVANCE and MINIMUM_STEPPER_PULSE. Each of them will add a few µs if enabled.

[ruggb]

I was under the impression that there was something like a DSR in the comm so that the host waited until the printer was ready to accept data. Is that the response string and if so is Marlin sending it prematurely?

IE instead of sending it as soon as it receives the command it should wait till it is ready to rcv another command - and this has to do with filling up the buffer.

[VanessaE]

In the old days, we used RTS/CTS for flow control on old 8-bitters with fast modems - does that exist here?

[Blue-Marlin]

No.
Only two lines (RX, TX) at arduino. Hardware handshake would need another two.

[ruggb]

In one of these threads someone said that when the buffer was full a message was sent to the host to wait.
If that is true, there may be an issue in that process. Like it is sending a wait AFTER the buffer is full and the host is getting it AFTER the host has sent another command. It may be that it needs to send the message BEFORE the buffer is full and allow another command or two to be rcvd.
Just guessing.......

[Sebastianv650]

@ruggb I think you are mixing up the buffers. A message is sent when the buffer for incoming commands (not single chars!) is full. Marlin isn't sending messages after every single char..

[ruggb]

@Sebastianv650 I understand that - I wasn't speaking about characters, I was implying messages or commands - I think.

[Blue-Marlin]

Uhh. That hurts. You couldn't be wronger.
Marlin is sending an 'ok' when it has executed or queued a command. That's the signal for to host to send the next command. Most hosts make some assumptions about how deep Marlins buffers are and send 'some' code ahead.

Please look that up.

The problem is, the only one byte buffer in the UART. If you do not pick the byte before the next arrived, it's lost. If a new byte arrived a interrupt is issued and queued. The (standard) interrupt scheme of the AVRs does not allow interrupts to be interrupted. So if an (stepper/advanced) interrupt takes to long, a char is lost. For that we already check for new chars in the stepper interrupt (code cited above). It could make sense to do the same in the extruder/advanced interrupt if that takes too long.

[Sebastianv650]

The extruder ISR takes only a few single µs. In fact it is so short that I couldn't measure it.
I had an idea while I was reading your answer.. Maybe not a good one, but maybe we should think about that. What if we would do something like this in the beginning of the stepper ISR:

• Disable all ISRs except the UART ISR
• Enable global ISRs again: sei()
• If a UART event happens now, it can interrupt the stepper.
• At the end of the stepper ISR, enable all disabled ISRs again (restore the register saved before)

It wouldn't be as chaotik as a real non-blocking ISR, but no char should be lost..

[ruggb]

Marlin is sending an 'ok' when it has executed or queued a command.

@Blue-Marlin That is what my perception was. The question is, what happens if Marlin does not send an OK? - is there a timeout?

host sends cmd, marlin sends OK, host sends cmd, Marlin misses it, time out, host sends another cmd, Marlin sends OK, error generated because line number was for the missed one.
If not I can't see how this error is generated == Error:Line Number is not Last Line Number+1

If there is a timeout, then what I am saying is maybe just ensuring that Marlin can accept the next command b4 it sends the OK, and not sending the OK just because it has queued the command would solve the issue.

And if this doesn't make sense it is because I have no clue how this really works.

[thinkyhead]

I believe @thinkyhead had indicated in a previous thread that he thought he had the ISR as fast as he could make it

There always seems to be more room for optimizations. Pre-calculating values in the planner. Replacing division with multiplication in the ISR. Things like that. It's going to be helpful to keep profiling the stepper ISR to see where improvements can be made, and where it would be best to call into checkRx(). Maybe not at the start of the ISR but somewhere in the middle.

On that subject, I see that checkRx() is called for each loop in for (int8_t i = 0; i < step_loops; i++) { . . . }. And the call to checkRx() itself adds some overhead. Maybe it only needs to be called when i & 1 == 1?

Too bad it can't be called in between pulse start and pulse stop. It would eliminate the need for the MINIMUM_STEPPER_PULSE at that point. But I think a call to checkRx() there would actually make the pulses too long.

I can't see how this error is generated == Error:Line Number is not Last Line Number+1

If the character missed is within the line number, that will do it.
Otherwise I believe you'll get a checksum error instead.

[marekduciuc]

I had same Issue recently. due to bad USB cable i bought shielded one and all run nicely now.

[mj1911]

Hmm. I've been using Cura 4.0.0 beta and Slic3r 1.3.1-dev to send jobs over serial (USB) to an Ender 3. Maybe a few dozen prints, no errors. In Slic3r, noticed the "Line Number is not Last Line Number+1" message in the serial text, but it would only display it once upon connection to printer, and seemed to work fine after that. Never failed mid-print yet. So researching this error, it seemed like a big potential problem, so decided to build and upload the latest 1.1.9 Marlin bugfix fw. Now getting an endless supply of "Line Number is not Last Line Number+1" in Slic3r and it refuses to print anything. Prints fine from Cura though!

[AnHardt]

@mj1911
Code relevant for this has changed several time since this discussion - 2 years ago.
Please open a new issue for this. If possible with some logs around the error.

[uchobby]

In case it helps, I see this error as continuous when it happens, every message fails at 115200. I find that closing the slicer and resetting the printer clears the issue. This seems to occur only when I start the slicer program under some as yet not determined situations. I have seen it start just after a new print starts, the head will be as some random spot on the surface, and every message sent by the slicer is failing. So far this has only happened on the first layer.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.