Wrong estimated print times

[tomaae]

OctoPrint Version:
OctoPrint 1.4.2

PrintTimeGenius Version (if you know):
PrintTimeGenius Plugin (2.2.6)

What happened:
Many estimates by PrintTimeGenius are way wrong, often by hours. See example screenshots bellow with real print times.
I'm using PrusaSlicer2.2.0 and Prusa MK2

[eyal0]

I will need more information. Can you provide some of the print time genius log output?

[tomaae]

Sure, I have reanalyzed 3 of them:
plugin_PrintTimeGenius_engine.log

[eyal0]

In the log there is no M503 output, yet I expected to see the M503 in there. One possibility is that you haven't run M503.

Can you try going into the terminal on your printer while it isn't printing and type M503 and hit enter? It should output a list of your settings that start with an "M" like M900 or M200, M201, etc. After that, please try re-analyzing the files and look at the log output. Right now your log has this in it:

2020-10-22 21:05:34,116 Running: "/home/pi/oprint/bin/python" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" marlin-calc "/home/pi/.octoprint/uploads/Prusa_enclosure/hyperpixel4lcd-cover_v1_0.2mm_PETG_MK2S_5h10m.gcode" ""

I expected those final quotes to contain an excerpt from your M503 output. Running M503 once should be enough to fix that.

If the new time to print after analysis is not improved then send me the new logs and also one of the gcode files and I'll analyze it here on my computer and see what results I'm getting, to see if they match yours.

Thank you.

[tomaae]

I ran M503, but it didnt fixed the issue. Plugin found those values now, but time is still off.
I'm attaching both log and my latest print's gcode.
ledstrip_45angle_0.2mm_PETG_MK2S_5h18m(1).zip
plugin_PrintTimeGenius_engine(1).log

[eyal0]

I'll take a look! Let's see. In your log, I see the ledstrip:

Running: "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l" "/home/pi/.octoprint/uploads/Prusa_enclosure/ledstrip_45angle_0.2mm_PETG_MK2S_5h18m.gcode" "M92 X100.00 Y100.00 Z400.00 E161.30
M203 X500.00 Y500.00 Z12.00 E120.00
M201 X9000 Y9000 Z500 E10000
M204 S1500.00 T1500.00
M205 B20000 E2.50 S0.00 T0.00 X10.00 Y10.00 Z0.20
M207 F2700.00 S3.00 Z0.00
M208 F480.00 S0.00"

And it seems to have grabbed all the input from your M503. If you type M503, I suspect that you'll see details similar to what are above, yes?

In your ledstrip gcode there are some other M codes that will override the ones above and that should be fine.

Inside the gcode, near the end, I see this line:

; estimated printing time (normal mode) = 5h 18m 1s

That's PrusaSlicer's estimate.

marlin-calc also has an estimate and it's in the log:

2020-10-23 00:34:46,306 Result: {"estimatedPrintTime": 18928.351941785175, "printingArea":

That's in seconds. In hours, minutes, and seconds, it's 5 hours, 15 minutes, 28 seconds. So it looks like PrusaSlicer and marlin-calc are in pretty good agreement!

Ah, but here's the problem. The compensation. It seems that in one or many of your recent prints, they took way less time than expected. Like, off by 75%:

2020-10-23 00:34:46,682 Recent heat-up times in seconds: 120.85924274900754
2020-10-23 00:34:46,683 Average heat-up: 120.85924274900754 seconds
2020-10-23 00:34:46,684 Recent cool-down times in seconds: 0.5315373519988498
2020-10-23 00:34:46,684 Average cool-down: 0.5315373519988498 seconds
2020-10-23 00:34:46,684 Time spent printing, actual vs predicted: 3480.5264717300015/13839.968563850041
2020-10-23 00:34:46,684 Average scaling factor: 0.25148369778968477

So the estimate is getting decreased by a lot! That could happen if some previous print or prints reported much less time than marlin-calc reported, so it's trying to compensate.

This will fix itself over time but the easiest way for you is to just delete those old stats. In the PrintTimeGenius options, under "advanced", you should see a table of previous prints and compensation values. Just go ahead and wipe them out. That'll reset back to no compensation and it should fix your problem. You will need to re-analyze the files after you do that.

Let me know if that helps you. Thanks!

[tomaae]

Yes, I use cancel object plugin sometimes when I need just certain piece from a set that I have already sliced.
I have deleted compensation values and now the estimate looks fine.
What can be done here, so cancel object wont mess up estimates?

[eyal0]

Yes, I think that there is already a cancel object issue being tracked. It's really hard to do. The problem is that I'm calculating all the time to print ahead of time and I don't know how I could adjust it for which objects print and which don't.

Do you often use cancel object? Maybe I could at least not use prints with cancelled objects in the compensation database?

[tomaae]

I dont use it too often.
Yes, just not using prints where some objects were cancelled for compensation database would be a solution. If it can be done.

[eyal0]

We're talking about it here: paukstelis/Octoprint-Cancelobject#60

PTG doesn't have any way right now to know if cancelobjects got used so there's work to be done.

[rthomas6charter]

I'm noticing the same thing. This explains what's going on, but I very frequently realize I forgot something right after starting a print, cancel it, fix it, and start over, so I will pretty much always have bad data points in the "compensation" database. Seems like pausing a print to change filament might also throw a wrench in it and skew the compensation data the other direction.

What about excluding things that fall outside some kind of calculated statistical curve? Like, for instance, discard compensation data for any print where actual time is more than one standard deviation above or below the predicted time.
Python lib NumPy might handle most of the heavy lifting:

• https://datagy.io/python-standard-deviation/
• https://numpy.org/

That might get the estimation back on track faster than just waiting for enough "completed normally" prints to render the canceled (or paused) ones insignificant. Even a fixed percentage difference between estimated and actual might work as a basis for exclusion, i.e. only include compensation data from prints that completed within +/- 15% of the estimated time. That would basically just mean you're starting with an assumption that the estimates are normally somewhat accurate, and if they're far enough off at the start, then none of the compensation data ever gets considered.

[eyal0]

But prints that are cancelled shouldn't even show up in the compensation table.

Are you sure that cancelled prints are showing up in there? I've never been able to confirm it.

[mgfarmer]

I've been wondering for a while now why PTG is telling me that my 6 hour print is going to take 26 hours to complete until I found this issue. Now I know to delete the compensation data. For those of us where this compensation data gets scewed over time, maybe we could just have an option to disable compensation altogether?

[eyal0]

This is a good idea...

Currently, there are 3 values for compensation: Time to heat, time to print, and time to cool.

The time to heat is measured as the time from the start of the print until filament starts extruding.

The time to cool is measured as the time from the end of the extruding until the print is done.

All the rest of it is the time to print and that value is compared against the results of marlin-calc, the time estimator, to see how similar the print time is to the estimate. The average factor difference is incorporated into each print.

The print time compensation is causing trouble often for users and I think that it's causing more trouble than it is worth. Maybe what we can do is make each of those values either be automatically derived (as today) or let the user specify each one. Any value that is specified will override the automatic derivation. So, for example, if you're happy with the heating and cooling time measurements (in seconds), then you could just leave those blanks. But if you are unhappy with the factor applied to the printing then you could set that to 1, which means to multiple the result of marlin-calc by one. (Multiplying by 1 does nothing, of course!). Or set it to 1.05 if you want 5% added to the value each time. All this would be instead of the current method, which is taking an average of the last 5 prints.

This seems like a solution that will solve your problem and also provide flexibility for users.

Because the calculation is usually pretty good from marlin-calc and too many users have this problem with compensation, I think that the new default will be to have 1.0 for the scaling factor of the print time but have the heat up and cooldown times continue to be computed by the averages.

How does this plan sound?

If I create a version of PTG that does this, would one you like to test it out?

[mgfarmer]

Hi Eyal, Your plan sounds good to me. I'm always a fan a flexibility when it comes to software configuration. I'd be happy to try this out for you.

Question: Are the heat up/down compensation times stored per-target-temp, or does one setting apply to all target temperatures? For instance, would the heat up times for my PETG prints (with a much higher bed temp) affect the compensation values for my PLA prints (with a lower bed temp).

[eyal0]

@mgfarmer It's ready. If you want to try it, go into the plugin installation screen in OctoPrint, like normal, but put in this URL for the installation:

https://github.com/eyal0/OctoPrint-PrintTimeGenius/archive/refs/heads/compensation_values.zip

You do not need to uninstall PTG before you do this. All your old settings will be retained. You do not need to download that file; OctoPrint will download it for you when you provide the URL. When a future version of PTG is installed, it will install over this testing version and all settings will be retained.

After you do this, go into settings, PTG settings, then click on advanced and observe that you have the calculated compensation values there. If you delete them then they will be calculated as normal, using the average of previous prints. If you fill them in with a number then that will be used instead of the average. By default, the compensation for extruding is 1.0 and the rest are derived from averages. You can modify them or blank them out. Press "Save" to save your changes.

After that, future print time estimates will be affected, but only future ones. You can go back into settings and request for a file to be re-analyzed. After being analyzed, you can print the file and see the estimated print time. You will also see the effect of forcing compensation in the PTG plugin logs, which you can download and inspect. It will say "Forced".

Please try it out, let me know how it goes. Let me know if you have suggestions. Thanks.

[mgfarmer]

Sounds great. Thanks for the detailed instructions. I'll let you how testing goes.

…

On Fri, Feb 25, 2022, 4:36 PM Eyal ***@***.***> wrote: @mgfarmer <https://github.com/mgfarmer> It's ready. If you want to try it, go into the plugin installation screen in OctoPrint, like normal, but put in this URL for the installation: https://github.com/eyal0/OctoPrint-PrintTimeGenius/archive/refs/heads/compensation_values.zip You do not need to uninstall PTG before you do this. All your old settings will be retained. After you do this, go into settings, PTG settings, then click on advanced and observe that you have the calculated compensation values there. If you delete them then they will be calculated as normal, using the average of previous prints. If you fill them in with a number then that will be used instead of the average. By default, the compensation for extruding is 1.0 and the rest are derived from averages. You can modify them or blank them out. Press "Save" to save your changes. After that, future print time estimates will be affected, but only future ones. You can go back into settings and request for a file to be re-analyzed. After being analyzed, you can print the file and see the estimated print time. You will also see the effect of forcing compensation in the PTG plugin logs, which you can download and inspect. It will say "Forced". Please try it out, let me know how it goes. Let me know if you have suggestions. Thanks. — Reply to this email directly, view it on GitHub <#214 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AUUGZBHDZ3WJADHEC22WSADU5AOCNANCNFSM4S3HRJGA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were mentioned.Message ID: ***@***.***>

[lorenmcguire]

After reading through all these various comments and suggestions, nothing really matches what I am seeing. I don't often cancel print jobs, but everyone once in a while, it does happen. My issues is, looking at the OctoPrint screen, it states - Print time (ongoing) 28:37, Print time Left 1.5 Hours, Approx Total Print Time: 1.5 hours. I've seen some prints showing Approx Total Print time = 14.5 hours, Print Time (ongoing) 03:32:34, Print Time Left: 24.2 hours. How is it OctoPrint is showing over 10 hours more for the Print time Left than the Total Print time? This makes no sense. Even after printing a part for 28+min, the Print time Left can equal the Total Print Time Estimate? Something is wrong with the algorithm here. I realize this can be relative, but this is worse than Microsoft time for copying files, and that is really bad....

[eyal0]

You shouldn't be seeing approximate print time at all with Print Time Genius, only the exact print time.