D576 Buffer Monitoring

[chendo]

Description

Note: This was originally M576, but has been changed to D576.

This PR adds M576, which adds the ability for Marlin to report buffer statistics.

 * M576: Return buffer stats, and optionally set auto-report interval.
 * Usage: M576 [S<seconds>]
 * 
 * When called, printer emits the following output:
 * "M576 P<nn> B<nn> PU<nn> PD<nn> BU<nn> BD<nn>"
 * Where:
 *   P: Planner buffers available 
 *   B: Command buffers available
 *   PU: Planner buffer underruns since last report
 *   PD: Maximum time in ms planner buffer was empty since last report
 *   BU: Command buffer underruns since last report
 *   BD: Maximum time in ms command buffer was empty since last report

This came out of my investigation into print quality issues after a combination of using Octoprint and Cura 4.7 (see Ultimaker/Cura#8321), which is detailed on my blog post, where I wanted a mechanism that gives me metrics on how often the Marlin buffers underrun during a print over USB.

I initially toyed with ADVANCED_OK, however it can only report the state of the buffers when the ok is sent, and I wanted to have timing data, as I figure measuring the maximum time the planner buffer was empty was a key indicator of stalls that result in print artifacts.

I tested this with my Ender 3 v2 and originally built against Smith3D's fork with some Ender 3 v2-specific improvements

I am unsure how to determine the performance impact of my modifications so I'd like some help with that. Normally, I would have liked to do the planner buffer underrun check when the block is dequeued, but it felt like a bad idea to add to the stepper ISR.

I've documented my process as well as the comparing the results of the M576 output between a 3DBenchy sliced in Cura 4.6.2 vs 4.7.1 here.

Benefits

Being able to have metrics on buffer underruns enables more objective measurements on whether or not attempts to ensure the buffers aren't underrunning are working as intended. Applications are able to monitor the output of this to inform the user that print quality is likely affected due to underruns, which has been requested for Octoprint here: OctoPrint/OctoPrint#3693.

Not adding more output to ADVANCED_OK helps with keeping down serial comms load on both ends.

Visualisation of M576 output when printing with Octoprint:

Cura 4.6.2:

Cura 4.7.1:

Configurations

This is enabled with #define BUFFER_MONITORING.

Related Issues

Should help diagnose/confirm issues that involve print quality or stuttering around curves that are resolved when printing off SD card.

• [BUG] Micro stutter on high speed print moves #16402
• [BUG] Stuttering printing curves #17231
• Bad printing of circles from PC #11622

To do

• Finalise output format - I'm not sold on the existing format and would like suggestions
• Add documentation and gcode entry
• Confirm to style guide
• Deduplicate strings?

[qwewer0]

Would this need an external timed command send, or is there a way to send a command at the start of the gcode file for continuous reporting, with settable interval? (e.g. M576 R2000 for reporting every 2 second)

[ellensp]

@qwewer0

 * M576: Return buffer stats, and optionally set auto-report interval.
 * Usage: M576 [S<seconds>]

[qwewer0]

My bad.

[rhapsodyv]

Did you try that test with the USART_RX_BUF_SIZE?

And set it to "Draft", if you are working on it yet ;-)

[chendo]

Did you try that test with the USART_RX_BUF_SIZE?

And set it to "Draft", if you are working on it yet ;-)

Nah not yet.

I changed it from Draft because I wanted some feedback and thought people may not look at it if it was still marked as draft heh

[Sebazzz]

Your blog post seem to indicate this only happens when printing over USB. As I understand it, it happens also when printing over SD card.

[chendo]

Your blog post seem to indicate this only happens when printing over USB. As I understand it, it happens also when printing over SD card.

If the gcode is too dense, then there will also be issues over SD card. I have seen Cura 4.7.1 generate gcode that spikes over 300 commands per second, which I have tracked using M576 with a test I did just yesterday, so haven't put that on a blog post yet. Data also showed that printing from SD tends to not have any planner underruns, but I still see print quality issues with 4.7.1, albeit it better than printing over USB.

The goal of this PR is to enable people to understand when underruns happen, although it does appear that Cura 4.7.1's print quality issues is due to a combination of the Ender 3 profile having too fine of a resolution because of a bug in a previous version of Cura that over-simplified curves: Ultimaker/Cura#6748

[sjasonsmith]

Two questions:

1. How did you choose the code M576? Is this already used by any other firmwares?
2. Who is the intended audience? Everyday users (or tools like Octoprint), or developers?
   If developers, maybe it should be changed to a D code to avoid future "G" conflicts.

[chendo]

@sjasonsmith M576 was not used, and I picked it because M575 is Set Serial baud rate, so it's somewhat related heh.

It's intended for tools to interpret for users to more objectively detect if buffer underruns are occurring due to whatever reason (gcode being too dense for a particular printer to handle, the process streaming gcode to the printer doesn't get to run when it needs to due to load, etc), rather than trying to look for the effects of buffer underruns on prints itself when it manifests as zits.

I used M576 to understand if various ideas in BufferBuddy (Octoprint plugin which tries to keep command buffers filled) was working as intended. I can kind of detect underruns by seeing if the planner/command buffer available amounts returned by ADVANCED_OK that would indicate the buffers were empty when the `ok was sent. However, it makes it difficult to accurately calculate how long the buffers were empty for, which M576 can do.

Considering that planner buffer underruns are bad, and is extremely likely to cause print quality issues if the planner buffer remains empty for too long, I feel like this M576 or another mechanism that allows surfacing to the host/user that underruns are happening would be useful.

[sjasonsmith]

Thanks for the explanation! I think what you’ve done is super interesting, hopefully some good improvements come from it.

[rhapsodyv]

I'm curious about USART_RX_BUF_SIZE. Did already tried it?

[chendo]

I'm curious about USART_RX_BUF_SIZE. Did already tried it?

@rhapsodyv I did for a bit, but reverted back to defaults to try to do my testing closer to default values to determine if the plugin will work for more printers. It did help with more commands inflight for uploading to SD, as I can only keep about 2-3 commands inflight at USAR_RX_BUF_SIZE at 64 as there is no backpressure as the command/planner buffers aren't being used when uploading to SD.

[rhapsodyv]

I'm curious about USART_RX_BUF_SIZE. Did already tried it?

@rhapsodyv I did for a bit, but reverted back to defaults to try to do my testing closer to default values to determine if the plugin will work for more printers. It did help with more commands inflight for uploading to SD, as I can only keep about 2-3 commands inflight at USAR_RX_BUF_SIZE at 64 as there is no backpressure as the command/planner buffers aren't being used when uploading to SD.

I'm insisting on USART_RX_BUF_SIZE is not because I dislike your PR. It's the contrary. You are doing a wonderful job uncovering uart buffer issues.
And I would like to see how different USART_RX_BUF_SIZE sizes behave, using your new monitoring tool :-)

[rhapsodyv]

About the M or D. If would be used only for specific cases, or for devs. Maybe we can make it as a D code, not M one.

[chendo]

Oh I didn't interpret it as dislike for the PR heh, I was explaining what I observed when I increased the buffer and why I went back to defaults for testing. Theoretically we can try to fill the serial buffer as well, but it seems harder to track its state, and serial RX overruns appears to cause commands to be truncated and trigger a resend, but due to existing commands inflight, the host cannot respond with the line being requested until the printer processes the commands inflight and also responds with resend requests, which actually increases overall latency between the line requested being resent, and increases the chance of buffers underrunning.

I've made an option in the plugin that sets a different target for commands inflight for uploading to SD card as without Marlin exposing serial buffer sizes/states, the risk/benefit to keeping buffers filled doesn't seem worth it.

I think it should be a general purpose gcode, and there appears to be many other gcodes in the same class that are M, like M111 set debug level, M430 power monitor, and M575 serial baud rate

[sjasonsmith]

I think we can wait for thinkyhead to decide what he likes for the G/D code.

[sjasonsmith]

@thinkyhead to know how to proceed with this I think we need two things from you:

1. Is this a feature we want to include?
2. Should we add an M code (currently M76 in this PR), or put it inside a D-code?

I personally favor a D-Code, because I feel like that helps communicate this is experimental and subject to change. Once we decide it is useful and its capabilities are more nailed down it could possibly be promoted to a G-code later.

[thinkyhead]

Did additional cleanup and added a CI test. It should pass, and then it will be merged shortly thereafter.

[slowbro]

Ah, I suppose this would require an update to Configurations, too. I'll get that going. Edit: NVM, I see you did it already.

[chendo]

Thanks for getting it merged in!