Bug: Printer pausing during print

[evilC]

🐞 bug report

Affected Version(s)

Snapmaker J1 - 2.6.2 firmware

Is this a regression? (optional)

No

To Reproduce

Steps to reproduce the behavior:

1. Print the attached GCODE (PLA)
   J1_XYZ 20mm pipe 2mm walls 20if solid traps 67.57g PLA.gcode.zip

Exception or Error (optional)
During printing, numerous statistics_slowdown_cnt warnings are seen

Expected behavior
Little to no of these warnings should be seen

Upon speaking to a Marlin dev (@EvilGremlin ) about this, he seems to think that three things are potentially responsible.

1. Snapmaker's Marlin build is using some non-optimal settings. He recommends the following changes:

#define ADVANCED_OK
#define BUFSIZE 16
#define TX_BUFFER_SIZE 64
#define RX_BUFFER_SIZE 512
#define HOST_ACTION_COMMANDS
#define HOST_PROMPT_SUPPORT
#define SERIAL_OVERRUN_PROTECTION
#define EMERGENCY_PARSER

2. Some of the settings in my PrusaSlicer config are causing too short segments. Namely Slice resolution, which I currently have set at 0. He recommends 0.0125 or higher. @leandrolima-nyc I am using a variant of yours, and I am unsure if I changed this, it may be worth you reviewing.

3. Too high resolution when I export from my CAD software. In Fusion360, I currently have "Refinement" set to high in mesh export options, I should try returning this to the default of medium.

[evilC]

I tried making tweaks to (2) and (3) above and it certainly helped.
The main problem that this pausing has been causing is that when it pauses, filament continues to ooze out of the nozzle, and then later on the nozzle hits this oozed out filament and causes a layer shift.
I have been trying to print off lots of copies of a part lately, and previous to this change, >75% of them were failing.
After making the changes mentioned, I managed to print 3 of them with no failures, which is basically unheard of.
However, when I left the 4th running overnight, I woke up to this monstrosity (Successful print on the right for comparison)

[OWKenobi]

Hi, I wanted to add to this discussion:

I have experienced the printer slowdown on a file of about 20MB of size, but it happened gradually. At 10MB, the first slight slowdowns happened, and got worse overtime. It basically stopped at every corner, oozing material.

My workaround: pulling the printer from the power line and rebooting it into power failure mode completely reset the faulty behavior and it began printing the rest in full speed. So maybe it looks like some buffer simply runs full that slows down the firmware during printing?

Can you test if this works for you?

[evilC]

@OWKenobi my issue is partly solved already - I lowered the quality of the STL mesh export, and I now also use Arc Welder when slicing. Both of these reduce the amount of instructions/sec that are sent to the printer. How long was your print BTW? "20MB" is not really an indication of data rate to print time ratio.
Also, I am not sure this method is an option for me, I print via Octoprint. Don't think resume on power loss is supported for that.

[OWKenobi]

Hi,
I was about 1 hour into the print when the problem started to occur, and it got worse from then. What strikes me in the face is the fact that the J1 can handle the data rate initially, and only over time come to a point that it can't handle it any longer. (I print a long shaft where every layer has the exact same shape, so obviously every layer consists of the same amount of data). This is not supposed to happen. It should have a constant data processing rate.

The long term problem is that, even if I workaround with stl mesh quality reductions works for medium sized models, the gradual printer slowdown accumulates and will eventually kill any huge print; inconveniently at the last layers, ruining the whole print. The only "security" I have right now is that I can print models under 10MB without issues (no matter the speed).

See this link for example videos:

https://drive.google.com/drive/folders/1AvEXkPHCzs0iW5xRAMYc1pJWzCzD_eFN?usp=sharing

[EvilGremlin]

You still didnt attach your full configs.
2.6.2 firmware - this version doesn't exist
I see your E is in relative coordinates - try with absolute.

[evilC]

Yes, but if you have a buffer of 100 units, and every minute that the print runs, the printer can't quite keep up and thus the buffer fills up by 1 unit, then it will not be until 100 minutes in that the buffer fills and the printer needs to pause to wait for the buffer to clear before it can add a new command.
It sounds like you are right on the edge of the printer being able to keep the buffer from filling up, so my point was that if you used Arc Welder (It's built into the latest version of PrusaSlicer) when slicing, then it would probably compress the gcode enough to keep you just under that limit.
I am not saying it's an ideal solution, but as a workaround, it may at least allow you to print that part with no compromises.
It's also one of those things that you should use anyway, even if you don't specifically need it. It's going to result in smoother curves - ie better print quality.

[OWKenobi]

Hello EvilGremlin,
I also have 2.6.2 firmware, it does exist for J1 Printer: https://forum.snapmaker.com/t/snapmaker-j1-firmware-updates-and-downloads/29972

evilC, your theory sounds good, but actually I tried reducing the print speed by 50% and it still paused in the corners. I had to reduce to 30% to be able to print smoothly the rest of the model when the bug occurred. Also manually "pausing" and "resuming" the print didn't solve the issue; the pause should be enough opportunity to empty any movement queue.

That's why I believe the printer updates some internal list on every move inefficiently, and once this internal list reaches, let's say, 10.000 items, it will make the printer slow. Maybe some debug log, I don't know. And the longer I print, the worse it gets. That's why a simple pause doesn't resolve the issue, since the list/data structure/whatever doesn't get cleared, while a reboot solves it.

[EvilGremlin]

Wait. I'm blind. This is not vanilla marlin repo. Why the hell am i even here? What did i click wrong? Ah, mention sent email... Please don't do that.

[OWKenobi]

Hello,
I want to keep this issue alive with some more test results:

it seems that deleting all comments from the prusa gcode file solves the symptoms for me, leading to the conclusion that the processing of comments is faulty. But I was only able to test it with a model of about 17MB of size after deleting comments, so further testing with bigger files is needed.

You can use this script for post-processing your gcode file:

#!/bin/bash
# Get the filename from the first argument
filename="$1"
sed -i '/^;WIDTH:/d' "$filename"
sed -i '/^;WIPE/d' "$filename"

However, this only solves the symptoms, not the issue. Staff should have a look why these symptoms actually occur.

[evilC]

AFAIK, the comments are still sent to the printer, because if you watch the CLI (eg when printing via octoprint), you see the comments.
So if it is using precious buffer space to store comments, then deleting the comments would help make it not pause.
ie it does not have to be a bug in the processing of comments IMHO

[OWKenobi]

Hello evilC,

You are right, deleting the comments helps, but I disagree that this is not a bug: skipping a single line comment should NOT take 100+ms to process, and a reboot of the machine should NOT solve the problem. The fact that rebooting and resuming the print solves the problem indicates that there is a deep software issue of how the J1 deals with comments, that there is some really bad implemented queue or buffer that the software fails to clear from time to time.

Actually, there isn't even a reason to buffer comments at all - the J1 should just read and discard them, filling no buffer at all. My guess is that comments produce some kind of debug log, which is carried around and gets longer and longer, combined with a bad implementation, so it slows down everything till almost standstill. Which is a bug in itself, till it can have other side effects down the road. So it should be reviewed and fixed.

[evilC]

What makes you think that skipping a comment takes 100ms?

AFAIK, I think that buffering of comments is not Snapmaker code, it's stock Marlin code - as in, I think it is standard Marlin behavior to output comments to the terminal. If they were filtered out at the point of being put into the buffer, then this would not happen.

HOWEVER, upon thinking about it a little more, I am starting to come around to your line of thinking. What maybe ISN'T stock Marlin behaviour is to parse the comment line. I am pretty sure, for example, that the SnapMaker firmware looks inside comment lines for metadata (eg when starting a print from the screen, some of the data it shows on the screen is AFAIK gleaned from comments) - so maybe it's doing regexes and stuff on comments at print-time, and this slows things down

[OWKenobi]

  What makes you think that skipping a comment takes 100ms?

I observed the delay with my own eyes:

https://drive.google.com/drive/folders/1AvEXkPHCzs0iW5xRAMYc1pJWzCzD_eFN?usp=sharing

the same lines of gcode run smooth at the beginning of the print, and lag around 100ms at every corner at the end of the print. (maybe more)

If the problem was within stock Marlin code, this would mean that every Marlin based printer were affected by this slowdown, which is more than unlikely.

An excerpt of the gcode: nothing fancy, just standard G1s:

  [...]
  ;WIDTH:1.04611
  G1 F4074.448
  G1 X130.523 Y111.734 E.01991
  ;WIDTH:1.09241
  G1 F3890.922
  G1 X130.546 Y111.573 E.02085
  ;WIDTH:1.13872
  G1 F3723.216
  G1 X130.569 Y111.411 E.02193
  ;WIDTH:1.18503
  G1 F3569.37
  G1 X130.593 Y111.25 E.02275
  G1 X130.569 Y111.089 E.02275
  ;WIDTH:1.13872
  G1 F3723.216
  G1 X130.546 Y110.927 E.02193
  ;WIDTH:1.09241
  G1 F3890.922
  G1 X130.523 Y110.766 E.02085
  ;WIDTH:1.04611
  G1 F4074.448
  G1 X130.5 Y110.605 E.01991
  ;WIDTH:0.999803
  G1 F4276.145
  G1 X130.477 Y110.443 E.01909
  ;WIDTH:0.953497
  G1 F4498.85
  G1 X130.454 Y110.282 E.01804
  ;WIDTH:0.907191
  G1 F4680
  G1 X130.454 Y108.454 E.19216
  G1 X131.296 Y108.454 E.08851
  G1 X131.296 Y110.282 E.19216
  ;WIDTH:0.953497
  [...]

every printer handles a comment every 3 lines without stuttering. So should the J1.

P.S. I don't think the pure output to the terminal is the actual problem. I even rule out a periodic regex, since both operations have linear runtime and don't slowdown over time. It must be some overload implemented by Snapmaker.

But it looks we won't find the actual problem by guessing, I hope someone with knowledge of the actual source code will have a look at this.

[obertini78]

I faced this bug recently. Is there anyone working on it? Is there anyone working on the J1 firmware at all?
I'm happy to support with troubleshooting.
Cheers

[OWKenobi]

Hi,

there is a firmware update every 1/2 year with only some cosmetic changes, so don't bet on it.

My solution was to write a wrapper script that deletes all comments from the gcode file and append that to the postprocessing of prusa. ChatGPT should be able to write you a 2-liner that can handle that for you.

[obertini78]

Hi OWKenobi,
Thanks for your suggestion. My first action was to write a script as well.
However, I'm using the sm2uploader tool with OrcaSlicer and it uploads an empty file to the printer. I suspect this has to do with the post-processing part of sm2uploader (smfix). I can confirm my script works as intended.
This is happening even if I do not change the first part of the gcode until after the START_PRINT and I keep the gcode intact at the end, starting with the END_PRINT section.

[obertini78]

By the way, has anyone tried to disable or lower the level debug log? If the comments are part of what is saved as debug information, then maybe disabling debug log could be a workaround?

The command should be M2000 S8 D6. I'll try and post back.

[OWKenobi]

Hi obertini,

I'm sure you deleted too much from the file. It works together with smfix by not deleting ALL comments but just the most frequent ones:

#!/bin/bash

# Get the filename from the first argument
filename="$1"

# Replace most frequent occurrences of lines starting with ';' with an empty string
sed -i '/^;WIDTH:/d' "$filename"
sed -i '/^;WIPE/d' "$filename"

I am also interested in your findings.

[obertini78]

Hi there,

Reporting back on my experiment with M2000 S8 D6.

Briefly, it's not conclusive.

In more details, I tried a print with M2000 S8 D6 added to the start gcode and there was no slow down.
Unfortunately, when I removed the command from the gcode and tried to print again as control, no slow down anymore. I was not able to reproduce the slow down with the same gcode that was producing this behavior two days ago.
I'm wondering if it wasn't some electronic throttling for an obscure reason.

By the way, thanks to @OWKenobi for the suggestion on the script for the removal of some, most common, comments. It works now and I will keep using the script as a precaution.