Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jittering when plugin enabled #62

Closed
sbombay opened this issue Aug 1, 2018 · 33 comments
Closed

Jittering when plugin enabled #62

sbombay opened this issue Aug 1, 2018 · 33 comments

Comments

@sbombay
Copy link

sbombay commented Aug 1, 2018

Before reporting, check if your problem is here:
https://github.com/eyal0/OctoPrint-PrintTimeGenius/wiki/Common-problems

Please fill this out:

OctoPrint Version: 1.3.9

PrintTimeGenius Version (if you know):
latest as of 2 days ago

What did you try:

What happenned:
print head stops for milliseconds randomly, especially printing curves leaving blobs.

Had this happen on 2 printers. Deleted plugin and no more jittering or blobs with same gcode.
See OctoPrint forums/Get Help. Search for plugin name.
Others also seeing same issue. Mods reference known bug with this plugin.

What did you expect to happen:

If relevant, upload the PrintTimeGenius log and any problematic gcode files (you might need to rename them).

@eyal0
Copy link
Owner

eyal0 commented Aug 1, 2018

I dunno why this is happening anymore. I removed all the processing while printing so it shouldn't be slowing down yet somehow it still is. So strange! Can you send the log files? Are you trying to analyze files while printing? There is a setting for that and perhaps you need to leave it off.

@Thisismydigitalself
Copy link

#60 (comment)

@dnlbauer
Copy link

dnlbauer commented Aug 8, 2018

Im observing the same issue. I just updated PTG from 1.1.1 to 1.1.3. Suddly lots of jittering and short stops during the print. I disabled the plugin and started the same gcode file again -> way better print quality and no more jittering.

I will try to get a log file for the two prints once the one with the disabled plugin is finished and see if theres something interesting in it.

@talldonkey
Copy link

talldonkey commented Aug 8, 2018

Confirming sbombay's comment - I had a print last night that were basically two upright cylinders and they had blobs/zits everywhere, and I noticed that the motion was not smooth around the entire circle but jerky/stuttery as described in this issue. I did make sure the 'analyze files while printing' was unchecked and presumably off. I had freshly updated to 1.1.3 via Octoprint's built in updater just before that print.

@dnlbauer
Copy link

dnlbauer commented Aug 8, 2018

To follow up on this. I checked the log files but theres nothing suspecious in them.. No errors, warning or anything. To show how severe this problem is, here you can see the print time of the same gcode file with and without PTG 1.1.3 enabled.
With the plugin, print time is nearly twice as long due to the stuttering.

ptg_timing

@dnlbauer
Copy link

dnlbauer commented Aug 8, 2018

I wanted to get into detail on this so I checked several versions (1.1.3, 1.1.1, 1.0.9, 1.0.7, 1.0.6 and 1.0.1). On all versions, I observed the same jittering.

Therefore I moved back to version 1.1.3 and enabled debug logs for PTG to see if the analyzer is running while printing and if theres more details in the logs. However, suddenly the stuttering was gone! I uploaded a new .gcode file by drag&drop and using the CURA api to see if I can make it running, but still no stuttering. Everything suddenly works as intended. Kinda dissatisfying..

On a side note: I usually start my jobs through the CURA api so maybe there is an issue with PTG not recognizing this correctly and not aborting when the print starts? Just a thought..

@Thisismydigitalself
Copy link

@danijoo, from my experience when gcode being sent using Cura's API, PTG does not have enough time to do its calculations before printing starts. double check that you see the gold-star before printing starts cause if not, then this might be the reason you don't get jitters, e.g. it's not that it works better - it does not work at all.

#60

@eyal0
Copy link
Owner

eyal0 commented Aug 9, 2018

@Thisismydigitalself okay, that is a good hint! There are two things that happen a lot while printing:

  1. All input and output of the printer is searched for mcodes, like m203 and stuff, which sets acceleration settings. Those settings are given to marlin-calc to make the calculation even more accurate! However, I turned off those calculations during printing so the code is now just "if printing stop" so it's really as quick as can be and I hope that removed all jitter from there.
  2. Every appox 2 seconds, OctoPrint sends to PTG a new progress updates and PTG uses it to calculate the time remaining. That calculation only happens if there is a genius analysis (gold star). So maybe that is the slow part. And cura upload doesn't leave time for genius analysis, so PTG fallsback to using OctoPrint built in analysis, which is quick and causes no stuttering.

So I need to make the progress calculation faster. I'm sure I'll find something. I'll take a look soon and prepare a new release. Thanks to everyone for the help!

@eyal0
Copy link
Owner

eyal0 commented Aug 9, 2018

It would help if I knew this: is the jittering a once-per-minute kind of thing or is it all the time? I mean, does it feel like the printer is just always in slomo or does it sppear that the printer is running smoothly for a while and then running poorly and then recovers? Any characterization of it would help. Someone uploaded a video once but I sadly can no longer access that video from the download site, maybe because it was too old.

@talldonkey
Copy link

talldonkey commented Aug 9, 2018 via email

@Thisismydigitalself
Copy link

Thisismydigitalself commented Aug 9, 2018

@eyal0 I was the one to upload two video files which you missed your 3 days window to download.
here they are again. links will expire in 3 days.

With_PTG: https://expirebox.com/download/8de351ff5a64016f527e1b61fdf7fe02.html
Without_PTG: https://expirebox.com/download/3b5eb6d96551ce49b9b3dd6d2fe2ddfc.html
These small "hiccups" you see in the print without your plug are not really hiccups - it's just the nozzle shifting to skirt's next shell. print is absolutely smooth.

@talldonkey
Copy link

talldonkey commented Aug 9, 2018 via email

@dnlbauer
Copy link

dnlbauer commented Aug 9, 2018

@talldonkey @Thisismydigitalself I can confirm all of that! As a workaround, it might help to disable "Automatically start print job after uploading" in cura OP settings and start it manually from octoprint ui once you have the star

@Thisismydigitalself
Copy link

@danijoo, nice workaround only if you want to load PTG. the purpose of this thread is to show there is an issue after PTG is loaded in the form of jitters all over the place. no matter how you load PTG - seeing the gold-star means troubles.

@eyal0
Copy link
Owner

eyal0 commented Aug 9, 2018

I'm sorry that the gold star means trouble. It's supposed to mean happiness!

I've tried 3 things:

  1. I've saved the progress so that I don't need to look it up every 2 seconds. Maybe that'll be faster.
  2. I have a faster interpolation for remaining time. That only runs every 60 seconds so I would expect that it isn't affecting you but I might as well. I hope that it helps, too.
  3. I added a warning to the settings screen about using debug mode. Debug mode outputs 1 line every 2 seconds to the log and that might be slowing things down.

By the way, do you have debugging on?

@eyal0
Copy link
Owner

eyal0 commented Aug 9, 2018

@Thisismydigitalself Could you try two things for me?

First, turn off debugging if you turned it on. The instructions are in the settings. Then try printing that same thing that you usually print to see if debugging output was the cause of the slowness. I added a warning in the settings about it now. I want to know if most of the problem was caused by debugging. In that case, the warning should help.

Second, try this new version that is a little more streamlined around the time estimation code. I hope that it'll be better!

https://github.com/eyal0/OctoPrint-PrintTimeGenius/archive/dev.zip

Let me know. If that does't do it then I'll figure out how to run a profiler and really measure where the CPU is wasting so much time!

@dnlbauer
Copy link

dnlbauer commented Aug 9, 2018 via email

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

@danijoo Okay. Well, let me know if you are able to install the link above and try it. Thanks!

@Thisismydigitalself
Copy link

@eyal0

I'm sorry that the gold star means trouble. It's supposed to mean happiness!

Eyal, Please accept my sincere apologies. never meant to sound negative but more like informative. all of us here wants PTG to shine and to make us happy!

I will try your updated dev version and report back. please note that even a small unnecessary hiccup that will take place every 60 sec instead of 2 sec is not something I personally will take lightly.

Thank you.

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

I don't want any hiccups, not even every 60 seconds. I hope that with these changes I have eliminated both! I have reduced the processing to a real minimum, I think.

If not, then I'll use a profiler to identify which lines are the worst offenders and try to fix those. But I don't see much space left for optimization.

We'll consider the problem solved when actual print time both with and without are the same.

I'm eager to here about your test results! Don't forget to turn off debugging if it is on.

@Thisismydigitalself
Copy link

My first impressions from dev 1.1.3 needs no words so instead I captured your gold-star in action:
https://expirebox.com/download/e6157e91b25e7e310936e902888eb769.html

looks promising.
Thank you.

@Thisismydigitalself
Copy link

Thisismydigitalself commented Aug 10, 2018

Just started a 3 hours print with 1.1.3 dev and gold-star'd g-code.
So far printhead moves as smooth as a baby tush.
img_20180810_143055

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

Now I just wish I knew which change it was that fixed the problem!

Probably it was saving the progress map locally. I used to fetch it from the metadata each time and I suspect that behind the scenes that was causing a read from the memory card each time.

I'll make a new version soon.

@Thisismydigitalself
Copy link

Thisismydigitalself commented Aug 10, 2018

When I started this print I was prompted that print will take 2.5 hours. i am now 2.5 hours in and still got 40 minutes to go - progress bar reads 80% done. BTW, How can PTG calculate estimated print time without taking into consideration firmware acceleration & jerk settings?

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

It does take acceleration and jerk into account! If you look in the PTG debug output, you can see where the input to marlin-calc includes mcodes 200-205. Those are jerk and acceleration among other things.

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

After your print, look at the advanced settings and.compare the estimated printing time to the actual. Look at the part that doesn't include heating up or cooling down because those are nigh impossible to predict. Let me know if you're seeing estimates that are way off before compensation.

Also, now that there is no jitter, the compensation values might be bad because PTG is assuming jitter! You can delete old print history and then hit save.

If you copy paste that print history table here, I can take a look and see if anything looks wrong.

@Thisismydigitalself
Copy link

Is this of any help?

**Actual Predicted Compensated
20.3 10512.1 45.8
20.8 11376.5 30.6

And, to my question: I do not use my slicer's Acc & Jerk. i set it in my printer's Firmware so how can these be calculated by PTG?

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

When your printer starts up, OctoPrint sends an M503 command to it. The printer responds by outputting all the firmware settings. PTG scans each line that comes out of the printer and saves the relevant settings, like M200-M205 and M92. PTG gives those to marlin-calc when it runs.

To check if it's working, download the PTG logs and look for the call to marlin-calc. You should see your settings there. Let me know if they don't match the output of M503.

Your first print shows that it spent 10512.1 seconds extruding. The prediction was 9637.7 seconds. The second print says 11376.5 vs 10357.5. That's about 9% difference each time. It's consistently 9% so the compensation ought to get pretty good answers. We see that most recent print, after compensation, predicted 10637.2. Compared to 10578.2, that's an error of 0.5%. That's pretty great, I think!

Still, I would not expect a 9% error each time. Two possibilities that I can think of:

  1. The config isn't being recorded properly. Can you check your PTG log files and look for the line where it says that it's running "marlin-calc"? You ought to see a few lines like M200, M201, etc. Check if those match the values in your firmware. If you don't see those lines at all, let me know. You can just copy-paste your whole "Running: ... marlin-calc..." line to this issue.

  2. Maybe you're not using marlin? marlin-calc is a one-for-one simulation of a marlin printer. It runs actual marlin code (version bugfix-2.0.x) and adds up the time that is spent on each line. It should be really, really accurate. If you're using smoothieware or something else other than Marlin, let me know. If your version of Marlin is wildly different from the latest bugfix-2.0.x branch, let me know that, too.

Good luck!

@Thisismydigitalself
Copy link

Thisismydigitalself commented Aug 10, 2018

Thank you for your elaborated reply.
As mentioned before and as we discussed in my original issue, I use Smoothie:
#60 (comment)
#60 (comment)

i think i am starting to understand how Genius your PTG really is. i will do some homework and come back with more information for you.

Line 7:
2018-08-10 05:35:42,214 Disabled: "/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python2.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" "marlin-calc" "/home/pi/.octoprint/uploads/Vase_3_plein.gcode" "M204 S500

Line 6364:
2018-08-10 11:25:47,826 Disabled: "/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python2.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" "marlin-calc" "/home/pi/.octoprint/uploads/AIROSOL_V2_v3.gcode" "M204 S500
M221 S105"
2018-08-10 05:37:11,867 Failed to estimate, ignoring.
Traceback (most recent call last):
File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_PrintTimeGenius/init.py", line 132, in estimate
statisticalTotalPrintTime, statisticalTotalPrintTimeType)
File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_PrintTimeGenius/init.py", line 106, in _genius_estimate
if (progress > self._metadata["analysis"]["firstFilament"] and
KeyError: 'firstFilament'

...
...

I don't want to dump my smoothie settings now as i don't trust the system to be robust and predictable while i am in the middle of yet another 3 hours print. i will check those later.

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

Oh no, bummer, why "disabled"? That means that it didn't run marlin-calc. Even if you're using Smoothieware, you should still run marlin-calc because it's better than nothing. Just hit the reset Analyzers button and that will put everything back in order.

The log line for marlin-calc actually spans multiple lines. That's why the "M204 S500 is missing a closing quotation. Can you grab the few lines that follow that line, too, until the next log message that starts with a date and time? It should show even more M commands.

Sorry that I forgot that you're using Smoothieware. I can't keep track of all the bugs!

Someone made a smoothieware simulator called gcodestat. He claims that it's accurate down to, like, just seconds. I have considered adding it and I even have an issue open for it but it would be a good bit of work and I want to really make sure that it's a good idea first. That means that I need someone to run gcodestat on a file that has been printed and show that the estimate is so much better than the one marlin-calc is providing. Show me that and I'll be convinced that adding gcodestat is a good idea.

So, how do we prove that gcodestat is any good? Download and run it on some gcode files and see how it does compared to the actual printer. I already have experience running gcodestat so if you don't want to do it, just send a gcode file here and I can run gcodestat and give you the result. For example, the one that took 10578.2 seconds or the one that took 11427.9 seconds. For accurate results, I'd need all the stuff that gcodestat asks for like jerk and acceleration and junction deviation and stuff. If you send me the output of M503, I can pull those out of there, I think, and use them.

Or run gcodestat yourself and let me know how close it is. Up to you!

If we find that gcodestat is awesome for Smoothieware then my next steps are:

  1. Make a way to detect smoothieware. I would find a way to get that from the M503 output.
  2. Modify gcodestat to output the fileprogress table. That's what puts the gold star on the analysis. It's a mapping from % of file complete to remaining time. It lets us get accurate remaining time line-by-line.
  3. Put it all together.

@eyal0
Copy link
Owner

eyal0 commented Aug 10, 2018

Also, if you can't M503 right now, the M503 output was sent to marlin-calc and recorded in the log, so you can just get the rest of those "Running marlin-calc" lines and that'll work. M204 S500... what's the rest?

Or, if you modified the firmware yourself, maybe you have it in some file there?

Good luck!

@Thisismydigitalself
Copy link

Thisismydigitalself commented Aug 11, 2018

Hello again, After 10 hours prints i had some time to look a bit deeper (and also updated to latest 1.1.4). I Sent M503 manually. first thing to notice is that the Acceleration (M204) in PTG log is different than that of my firmware and M92 which is nowhere to be found. My firmware acceleration is set to 750 and in PTG log file reads S500. i can look for other settings but it seems there is an issue here. i can check the rest later today. Correct me if I'm wrong but it seem that PTG does not work in my case.

BTW: what mechanism sends M503 before printing? i don't see it in OctoPrint nor in your plug settings. does this happens behind the scenes during connection?

My M503 dump below (M200 set to 0 but not found in PTG log):

Recv:
Recv: ok
[...]
Send: N103 M503*39
Recv: ; config override present: /sd/config-override
Recv: ;Steps per unit:
Recv: M92 X159.53000 Y159.53000 Z159.53000
Recv: ;Acceleration mm/sec^2:
Recv: M204 S750.00000

Recv: ;X- Junction Deviation, Z- Z junction deviation, S - Minimum Planner speed mm/sec:
Recv: M205 X0.10000 Z-1.00000 S0.00000
Recv: ;Max cartesian feedrates in mm/sec:
Recv: M203 X666.66669 Y666.66669 Z666.66669
Recv: ;Max actuator feedrates in mm/sec:
Recv: M203.1 X626.00000 Y626.00000 Z626.00000
Recv: ;Optional arm solution specific settings:
Recv: M665 L397.1900 R157.0741
Recv: ;WCS settings
Recv: G54
Recv: ;Digipot Motor currents:
Recv: M907 X1.75000 Y1.75000 Z1.75000 A0.70000
Recv: ;Home offset (mm):
Recv: M206 X0.00 Y0.00 Z0.00
Recv: ;Trim (mm):
Recv: M666 X0.000 Y0.000 Z0.000
Recv: ;Max Z
Recv: M665 Z500.000
Recv: ;E Steps per mm:
Recv: M92 E6000.0000 P57988
Recv: ;E Filament diameter:
Recv: M200 D0.0000 P57988
Recv: ;E retract length, feedrate:
Recv: M207 S3.0000 F2700.0000 Z0.0000 Q6000.0000 P57988
Recv: ;E retract recover length, feedrate:
Recv: M208 S0.0000 F480.0000 P57988
Recv: ;E acceleration mm/sec��:
Recv: M204 E150.0000 P57988
Recv: ;E max feed rate mm/sec:
Recv: M203 E50.0000 P57988
Recv: ;PID settings:
Recv: M301 S0 P40.0000 I3.0960 D129.0000 X255.0000 Y255
Recv: ;Max temperature setting:
Recv: M143 S0 P300.0000
Recv: ;PID settings:
Recv: M301 S1 P204.9000 I9.6550 D1087.0000 X255.0000 Y255
Recv: ;Max temperature setting:
Recv: M143 S1 P150.0000
Recv: ;Probe feedrates Slow/fast(K)/Return (mm/sec) max_z (mm) height (mm):
Recv: M670 S10.00 K300.00 R0.00 Z500.00 H20.00
Recv: ;Probe offsets:
Recv: M565 X0.00000 Y0.00000 Z0.00000
Recv: ;Load saved grid

@eyal0
Copy link
Owner

eyal0 commented Aug 11, 2018

Okay. First, I want to move this to a new issue because I feel like the jittering has been solved. I don't want people to come here and think that there is still an issue. So I'll open a new issue: #66

I'll write more there.

@eyal0 eyal0 closed this as completed Aug 11, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants