printer falter/stumble continuously cause of full host buffer

[TylonHH]

Nearly to the end of an 9 hr print the printer stops for miliseconds, even it's just an circle to print. I uploaded a video where you can see it. https://www.youtube.com/watch?v=ynJvZcNH8AI

Here are some top and htop I'm not familiar with it. Seems iut of mem?!?!

klippy.log.txt

What should I do now?

[TylonHH]

pi@octopi:~ $ free -m -t
             total       used       free     shared    buffers     cached
Mem:           859        733        126         15         65        481
-/+ buffers/cache:        186        673
Swap:           99          0         99
Total:         959        734        225

[KevinOConnor]

On Mon, Jan 08, 2018 at 09:59:51PM +0000, TylonHH wrote:

Nearly to the end of an 9 hr print the printer stops for miliseconds, even it's just an circle to print. I uploaded a video where you can see it. https://www.youtube.com/watch?v=ynJvZcNH8AI

Here are some top and htop I'm not familiar with it. Seems iut of mem?!?!

The memory looks fine.

It seems that the slicer did something goofy when generating the g-code for this model. The log indicates that there are periods where 15000 bytes are sent to describe a seconds worth of printer movement. That's something like 600 movement lines per second, where typically one would have no more than 10 to 20.

It appears that OctoPrint is unable to process these g-code bursts in a timely fashion and thus the printer runs faster that it can receive movement commands. Thus Klipper has to pause the printer to get more commands. We see this occassionaly with some slower processors - this is the first report I've seen on an RPi3.

Best solution would be to try and simplify the model so that the g-code doesn't contain these overly precise moves. As a short term work around, you could also add "buffer_time_high=15" to the "[printer]" section of the config - this will instruct Klipper to store a much larger buffer that should smooth out intermittent pauses from OctoPrint.

-Kevin

[jakep82]

I experienced the same thing tonight, and I had buffer_time_high=15 in printer.cfg. It paused for upwards of 10 seconds on several occasions.

klippy.log

[jakep82]

The part I was printing is fairly simple. The pauses occured near the end of the prints (I printed it several times) when it was only working on the round screw bosses.

https://www.thingiverse.com/thing:2175542

[KevinOConnor]

On Fri, Jan 12, 2018 at 06:36:51AM +0000, jakep82 wrote:

I experienced the same thing tonight, and I had buffer_time_high=15 in printer.cfg. It paused for upwards of 10 seconds on several occasions.

Unfortunately, you've hit the same issue with OctoPrint sending commands slower than the printer moves. Klipper is forced to pause and rebuild its buffer when this happens. (And, since the buffer size has been significantly increased, it takes much longer to rebuild its buffer.)

The beaglebone cpu is a little faster than the Raspberry Pi 1 and Zero, but it is significantly slower than a Raspberry Pi 2/3. It's common to see reports of stalls on the Beaglebone. (I suspect the model you are printing has a ton of vertexes around the circular parts that are causing the slicer to emit a ton of tiny moves which are slowing OctoPrint down.)

FYI, the graphstats debugging script is not smart enough to know you've increased buffer_time_high. If you change the top of the script so that it reads "MAXBUFFER=15." then it will better show the buffer being drained.

Finally, I've read that OctoPrint 1.4 is supposed to include a rewrite of the comms layer that should hopefully fix these issues. I've briefly explored some ways to bypass OctoPrint (eg, have Klipper directly read the g-code file), but I'm going to take a "wait and see" approach for now.

-Kevin

[BlackStump]

The Beaglebone is fine to print what stalls with Octoprint if Octoprint is bypassed. So it is a issue with Octoprint and high segmented circular models and a problem not easily fixed if you are not designing the model. I suspect some slicers are better then others on reducing the excessive tiny moves. Hopefully the release of Octoprint 1.4 reduces or fixes the issue. Plenty of info on the net about Octoprint eg https://groups.google.com/forum/#!topic/octoprint/sY-VbTcTtAI look at nop heads post

[jakep82]

This is unfortunate. I'll try some other slicers to see if they generate longer line segments to reduce this issue for now. I've seen the same issue in gcode generated from S3D and Slic3r so far. While I do have control over the STL files I generate, I also frequently print files made by other people where I have no control over the number of segments in curves.

[jakep82]

I've run into this issue on a several prints now unless I significantly reduce the complexity of the STL. It seems the Replicape developers resolved this recently by emulating print from SD so their firmware can read the gcode directly and bypass Octoprint. Hopefully this issue is resolved with Octoprint 1.4, but for now I'm going to test the latest Redeem release candidate to see if their workaround fixes the problem.

https://github.com/intelligent-agent/redeem/pull/26

[ghost]

Unfortunately, you've hit the same issue with OctoPrint sending commands slower than the printer moves. Klipper is forced to pause and rebuild its buffer when this happens. (And, since the buffer size has been significantly increased, it takes much longer to rebuild its buffer.)

The beaglebone cpu is a little faster than the Raspberry Pi 1 and Zero, but it is significantly slower than a Raspberry Pi 2/3. It's common to see reports of stalls on the Beaglebone. (I suspect the model you are printing has a ton of vertexes around the circular parts that are causing the slicer to emit a ton of tiny moves which are slowing OctoPrint down.)

FYI, the graphstats debugging script is not smart enough to know you've increased buffer_time_high. If you change the top of the script so that it reads "MAXBUFFER=15." then it will better show the buffer being drained.

Finally, I've read that OctoPrint 1.4 is supposed to include a rewrite of the comms layer that should hopefully fix these issues. I've briefly explored some ways to bypass OctoPrint (eg, have Klipper directly read the g-code file), but I'm going to take a "wait and see" approach for now.

Testing large (10 inch) obj format (not stl) perfect circle sliced from S3D also stutters using Repetier server with tty0tty, the stutters are the exact same (running of chromebook pentium quadcore). I really wish slicers implement g2/g3 arch like they used to. The fact that most slicers ditched it due to performance reason favoring 8 bit MCUs is short sighted imo.

Many argue that its not an issue to have insane amount of segmented lines to make a circle, but again these people don't have 12+ inch beds (moderately large circles looks very polygon, not smooth, bad for functional parts that requires coupling, including arts and figures). Either way this all happened at humble 80step/mm setup, I will give it another try at lower MS. For now, I call any slicer that doesn't use g2/g3 for amf/obj 3d models a "small trinket slicer" :D So far, only s3d maintains the same segmented line per mm^3 no matter how large the object is, its just the stutters on large / high speeds that prevents it from being useful. I'll also test with arduino due to see if its running out of move buffer. (?) Or probably klipper(host) limited lookahead buffer. Update:

With this stress test arc corners gcode using segmented line: g1 test.gcode.zip

[ghost]

Setup: Repetier Host with tty0tty, Core i7 6770HQ at 3.4ghz, same exact stutters in real life, here is the graph for reference compared to above (rpi zero):

Same gcode. Killed on second layer.

Update: Almost same graph with octoprint same setup as above (without tty0tty). Exact same "host buffer" stat pattern. Update 2: The difference in stuttering between Repetier-firmware and Klipper on my Ramps is like the following: Klipper stops 1/3 of the full arc for ~250 ms , sometimes between 1/3 and 1/5, but its entirely smooth after each stop. Repetier firmware: Guessing like 50ms full stop cycle on the entire arc from sdcard. Large vibrating sound, but it doesn't stop for long like klipper.

[lucashpandolfo]

Well. I've installed a cheap laser on my 3d printer and I was having the same issue sending an engraving job via octoprint. It would stutter and hang sometimes and the buffer_time was dropping to 0.

The last couple of hours I've been sending the jobs via 'echo myfile.gcode > /tmp/printer' and the buffer_time is constantly above 2s (same exact files) and the printer works fine. No stutter at all. Not sure if it's the same issue as yours, but octoprint was messing the prints with lots of moves in short times.

Cheers.

[ghost]

Thanks for the feedback. I just tried cat myfile.gcode > /tmp/printer, and here is the graph: (not reset from alst print though, look at time stamps):

Apparently host buffer seems ok :O, same stutters still... Gotta check my gcode if its defect, but S3D would be the blame here as I simply loaded OBJ file not STL. Update 2: NVM, gcode is clean, just reduced feedrate, less stutter but still. Update 3: Duet 0.6 w/Reprapfirmware does not stutter unless I open the web UI :P PS: The very smooth surface makes it very worth the trouble for me. I've never had this result before.

[KevinOConnor]

On Sat, Jan 27, 2018 at 02:10:49PM -0800, Talal A. wrote:

Thanks for the feedback. I just tried cat myfile.gcode > /tmp/printer, and here is the graph: (not reset from alst print though, look at time stamps):

If you'd like me to take a look at it, please attach the klippy.log file.

-Kevin

[jakep82]

It would be great if Klipper could be set up to emulate an SD card similar to what Redeem for the Replicape is doing now. Then Octoprint would just use M23 to hand the file off directly without getting in the middle and causing buffer under-runs. I switched to Reedeem for just this purpose, but after hours of frustration trying to make everything work correctly, I'm going to switch back to Klipper and try this manual approach to sending files directly to klippy.

[KevinOConnor]

On Sun, Jan 28, 2018 at 03:50:00AM +0000, jakep82 wrote:

It would be great if Klipper could be set up to emulate an SD card similar to what Redeem for the Replicape is doing now. Then Octoprint would just use M23 to hand the file off difectly without getting in the middle and causing buffer under-runs. I switched to Reedeem for just this purpose, but after hours of frustration trying to make everything work correctly, I'm going to switch back to Klipper and try this manual approach to sending files directly to klippy.

I would not recommnend using the "cat myfile.gcode > /tmp/printer" method - it can corrupt the command stream. If it's run without OctoPrint also running, then it will eventually fail because nothing reads the "ok" responses that Klippy produces. If it's run with OctoPrint also running, then when OctoPrint periodicaly sends M105 commands, they may get injected into the middle of g-code commands from myfile.gcode - thus causing corruption of those commands.

-Kevin

[jakep82]

Bummer. I guess I'll tough it out with Redeem for a while longer. I hope Octoprint 1.4 isn't too far out, and I hope it fixes this issue. I've made a few prints with gcode that stutters on Klipper with Octoprint, and the same files print flawlessly on Redeem with SD emulation. The problem with Redeem is basically everything else is more complicated and doesn't work as well as Klipper.

[ghost]

@KevinOConnor Sorry, here is the log: klippy.tar.gz Desktop log with cat ^ I've lost the log with Repetier and octoprint will replicate soon. The errors later aren't related as you might have guessed as I just disconnected the mcu from my desktop after finishing as it was just a testing session.

[hg42]

instead of cat you could use a script like one of these: https://github.com/grbl/grbl/tree/master/doc/script

However, you would have to change some lines in the code to make it work (device/baudrate and may be some buffer length for the stream.py)

[ghost]

There is little to no difference between repetier and cat. I would say switch to repetier (too bad its closed source) or wait till Octoprint improves. (I'm a bit surprised it still did not considering the huge author patreon compared to repetier with small user base) Repetier also uses 3x less ram, and starts up immediately compared to octo, even on desktop (as server).

[benpye]

@KevinOConnor I'm tempted to try and design my own board for klipper. Do you know if the BCM2835 (1/Zero) should be fast enough if OctoPrint were not causing problems? I know that it's a little slower than the BB but I don't think that Redeem is running that close to full utilisation?

[KevinOConnor]

On Sun, Jan 28, 2018 at 10:28:11AM +0000, Talal A. wrote:

@KevinOConnor Sorry, here is the log:

I'm confused. The gcode file you posted indicates an ~15 minute print, but all of your graphs show about 5 minutes of printing activity.

In the log you sent, the second print (which I guess correlates with the cat method) does not show any buffer issues. (The only spike is just seconds before the print ends.) The other print shows one spike at the start of the print, but the rest of the buffer utilization during the print looks fine.

Separately, the graphstats.py program wasn't graphing some cases properly. That was the cause of the weird 100% host utilization at the start of your graphs. I've updated it (commit 47bb8b7c).

-Kevin

[lucashpandolfo]

Sorry, I'm late. I forgot to mention. Before cat-ing the gcode to /tmp/printer I disconnect octoprint and in another teminal leave 'tail -f /tmp/printer' running to receive all the 'ok' messages from the printer.

[KevinOConnor]

On Sun, Jan 28, 2018 at 04:24:05PM +0000, Lucas wrote:

Sorry, I'm late. I forgot to mention. Before cat-ing the gcode to /tmp/printer I disconnect octoprint and in another teminal leave 'tail -f /tmp/printer' running to receive all the 'ok' messages from the printer.

That should work, but has two big down sides:

• there's no status during the print (eg, no print temperatures)

• any errors Klipper raises will get ignored, which could cause a bad situation to deteriorate into a worse situation

-Kevin

[KevinOConnor]

On Sun, Jan 28, 2018 at 03:58:42PM +0000, Ben Pye wrote:

@KevinOConnor I'm tempted to try and design my own board for klipper. Do you know if the BCM2835 (1/Zero) should be fast enough if OctoPrint were not causing problems?

I don't own a Zero and it's been over a year since I tested with an RPi1. Others tell me it works (aside from OctoPrint print stalls).

Separately, the RPi3 cpu is something like 20 times faster than the RPi1 in real world terms. Given that the RPi3 isn't significantly more expensive, the RPi1/Zero don't seem like compelling choices to me.

-Kevin

[benpye]

@KevinOConnor It's really the dimensions of the Zero I find interesting. There is a compute module 3, but it is about as expensive as the Pi 3 and requires more supply rails as well as a somewhat expensive SODIMM socket.

[KevinOConnor]

FYI, I've uploaded a test branch (work-virtual-sdcard-20180202) with test code that supports basic virtual sdcard support to bypass OctoPrint's gcode parsing. To use it, see the updated config/example-extras.cfg file.

cd ~/klipper ; git fetch ; git checkout origin/work-virtual-sdcard-20180202 ; sudo service klipper restart

-Kevin

[jakep82]

This is awesome news! I will definitely install this weekend on my Replicape/BBB and report back with results.

[ghost]

Thanks alot no more stuttering on very complex parts! This is defiantly a game changer, and its pretty underestimated, I now have the quality of this without g2/g3 (btw thats on small object. let alone large stuff): http://static1.squarespace.com/static/55627b1be4b020bb00b2d516/t/55942122e4b0f2448bc042ca/1435771213707/Vectorslicing?format=1000w

I will repeat the tests fully and post them sd vs usb as you wanted a completed print log. Edit: I would feel bad using this + smooth circles in my printing farm (business) without donating, if there is any way to donate at any time, it would be nice to get notified.

[ghost]

I should also add that this will easily allow printer physical UI display printing, as klipper scans the directory, it will be completely untethered from octoprint. I'm working on a simple st7920 controller.

[KevinOConnor]

FYI, I've merged the virtual sdcard code into the master branch.

[jakep82]

I've made a couple dozen prints with no issues related to virtual SD. I'm glad to hear it was merged so I can switch back to master.