Time calculated incorrectly, even when clearing the compensation values

I have a couple of files that PTG calculates the time WAY over the actuals. This has happened in the past as well but I haven't noticed any sort of pattern. Both files were generated in Cura (4.12.1), printed by OctoPrint (1.7.3) and calculated by PTG (2.2.8).

The first file shows a duration of 1h 49m in Cura, 1h 20m in OctoPrint, but PTG shows 12h 36m. When I printed, it took approx. 1h 45m (forgot to check/write it down). Based on other comments, I went to the plug in, deleted all the compensation value entries, deleted the uploaded file and uploaded it again. Now it shows 11h 52m as the estimated time.

For a second file I have, Cura shows 6h 55m, Octoprint shows 5h 20m (which I feel is a little suspect), but PTG shows 47h 16m. Yikes.

I have attached a zip file with both gcode files and the PTG log. Happy to provide other info if needed.

PTG Time Calc Issue.zip

Definitely something unusual going on. In you log, I see this line on line 13:

Running: "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l" "/home/pi/.octoprint/uploads/Lightsaber/LIGHTSABER-HILT -210c -60c -C -6h55m.gcode" "M200 D0
M200 S0 D1.75
M92 X80.00 Y80.00 Z400.00 E143.30
M203 X500.00 Y500.00 Z5.00 E25.00
M201 X500.00 Y500.00 Z100.00 E1000.00
M204 P500.00 R500.00 T1000.00
M205 B20000.00 E5.00 S0.00 T0.00 X10.00 Y10.00 Z0.30"

And then the result:

2022-02-21 12:31:40,110 Result: {"estimatedPrintTime": 170177.626269612

That is 47.26 hours, which is way wrong. Now I will run the same thing on my computer:

└──> scons ./out/x86_64/marlin-calc.x86_64 && ./out/x86_64/marlin-calc.x86_64 ~/Downloads/calc_issue/LIGHTSABER-HILT\ -210c\ -60c\ -C\ -6h55m.gcode "M200 
D0
M200 S0 D1.75
M92 X80.00 Y80.00 Z400.00 E143.30
M203 X500.00 Y500.00 Z5.00 E25.00
M201 X500.00 Y500.00 Z100.00 E1000.00
M204 P500.00 R500.00 T1000.00
M205 B20000.00 E5.00 S0.00 T0.00 X10.00 Y10.00 Z0.30
"

My result is much better:

Analysis: {"estimatedPrintTime": 23751.32051992340348079, "printingArea": {"maxX": 150.69000244140625000, "maxY": 200.00000000000000000, "maxZ": 178.39999389648437500, "minX": 0.10000000149011612, "minY": 20.00000000000000000, "minZ": 0.20000000298023224}, "dimensions": {"width": 150.59000243991613388, "depth": 180.00000000000000000, "height": 178.19999389350414276}, "filament": {"tool0": {"length": 18343.31176756229251623, "volume": 44.12083532941506547}}}

About 6 and a half hours.

The only difference is that I am doing the calculation on my computer and not on a Raspberry Pi, but I don't see how that should make a difference...

If you have some technical skill and would like to investigate it some more, you can connect to the Unix prompt on your Raspberry Pi and type this in:

"/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l" "/home/pi/.octoprint/uploads/Lightsaber/LIGHTSABER-HILT -210c -60c -C -6h55m.gcode" "M200 D0
M200 S0 D1.75
M92 X80.00 Y80.00 Z400.00 E143.30
M203 X500.00 Y500.00 Z5.00 E25.00
M201 X500.00 Y500.00 Z100.00 E1000.00
M204 P500.00 R500.00 T1000.00
M205 B20000.00 E5.00 S0.00 T0.00 X10.00 Y10.00 Z0.30"

And then see if the result has that really big 170000seconds estimated time or not. And then you can try it by removing some of the M commands, like delete the M203 line or the M205 line or both and see if it makes a difference. Also, try without any of them:

"/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l" "/home/pi/.octoprint/uploads/Lightsaber/LIGHTSABER-HILT -210c -60c -C -6h55m.gcode"

Usually when we see really crazy estimates like you are see it is due to those M commands. If we can narrow down which one is the problem, maybe we can solve the problem?

Thanks.

I ran with the full command and got the same result. Before doing process of elimination with the M commands, I ran without any and got:

Analysis: {"estimatedPrintTime": 170085.11089933593757451, "printingArea": {"maxX": 150.69000244140625000, "maxY": 200.00000000000000000, "maxZ": 178.39999389648437500, "minX": 0.10000000149011612, "minY": 20.00000000000000000, "minZ": 0.20000000298023224}, "dimensions": {"width": 150.59000243991613388, "depth": 180.00000000000000000, "height": 178.19999389350414276}, "filament": {"tool0": {"length": 18343.31176756229251623, "volume": 44.12083532941506547}}}

Not sure what is going on. Then, earlier today, I was printing things that were short (~20-30min) and they came up showing something like 6 min but actually took the 20-30 min. The time remaining would start counting down, then just stop for a while, then count off a couple of seconds, then stop, off and on until the print was done.

I just printed something that Cura told me was 1h 7m. PTG logs have the following:

Running: "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l" "/home/pi/.octoprint/uploads/Lightsaber/BLADE-1-VASE -210c -spiral -brim -8lw -FL1a -1h7m.gcode" "M200 D0
M200 S0 D1.75
M92 X80.00 Y80.00 Z400.00 E143.30
M203 X500.00 Y500.00 Z5.00 E25.00
M201 X500.00 Y500.00 Z100.00 E1000.00
M204 P500.00 R500.00 T1000.00
M205 B20000.00 E5.00 S0.00 T0.00 X10.00 Y10.00 Z0.30"

Result: {"estimatedPrintTime": 4071.904063768389, ...

My math says that is 1h 8m, but what is shown in the Octoprint interface is 1h 14m. Why would there be a difference from what is in the log to what is shown on the screen?

I appreciate your help. Let me know if there are other things I can run on my end to help track down what might be going on.

It's really weird that the analysis is coming up with such a big number! I would not expect this. I can only think that maybe the marlin-calc program that you are running is somehow not compatible with your Raspberry Pi. Is there something interesting or unusual about your Raspberry Pi?

You could compile the code yourself and see if your own marlin-calc compiled is working better?

git clone https://github.com/eyal0/Marlin.git
cd Marlin/Marlin
scons -i
ll out/*/marlin-calc.*

Hopefully it will correctly compile a marlin-calc for you and you will find it. You can run that file instead of /home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/marlin-calc.armv7l and see if it gives better results? If you have never compiled code before then this will be a learning experience.

I'm unclear why when you run the code and I run the code we get different results. So weird!

My math says that is 1h 8m, but what is shown in the Octoprint interface is 1h 14m. Why would there be a difference from what is in the log to what is shown on the screen?

This is due to the compensation, heat up, or cool down. Please examine your log files for this:

2022-02-21 12:31:40,426 Recent heat-up times in seconds: 191.5450603920035, 204.8780409229803, 207.07666808995418, 204.84101527999155, 197.8658375729865
2022-02-21 12:31:40,432 Average heat-up: 201.2413244515832 seconds
2022-02-21 12:31:40,437 Recent cool-down times in seconds: 5.479438543028664, 7.510721052007284, 8.22977825900307, 7.544167093990836, 8.860126352024963
2022-02-21 12:31:40,441 Average cool-down: 7.524846260010963 seconds
2022-02-21 12:31:40,442 Time spent printing, actual vs predicted: 6601.533363825991/42741.778609269066, 1324.7923873140244/1263.7466973410537, 1318.7860321560293/1257.7859250404772, 1526.0315687819966/1462.4030338467521, 1489.389304545999/1426.3393815799018
2022-02-21 12:31:40,442 Average scaling factor: 0.2546211787037298

We see that heating and cooling add 208 seconds, which is about 3.5 minutes. You'll need to examine your own logs to see the compensated value.

Are you also seeing the same number of gcodes as I am?

Progress: 0.99986889707359750, 18353.04589842166751623, 23700.48308241336053470
Progress: 0.99986990481937144, 18353.04589842166751623, 23700.51186532593783340
Progress: 0.99987177634723734, 18353.04589842166751623, 23700.88424932186171645
Progress: 0.99987307202037523, 18353.31176756229251623, 23700.93544402233601431
Read up all remaining commands
Progress: 0.99987537543928717, 18353.31176756229251623, 23701.17811108900423278
Progress: 0.99987921447080697, 18347.31176756229251623, 23701.26217243287828751
Progress: 0.99988108599867298, 18345.31176756229251623, 23701.35185086156343459
Progress: 0.99988228569602289, 18343.31176756229251623, 23701.56489887576026376
Progress: 0.99988329344179683, 18343.31176756229251623, 23703.58704644766112324
Progress: 0.99988583680017873, 18343.31176756229251623, 23707.33107205417036312
Processed 651119 Gcodes and 25 Mcodes. 645874 blocks

651119 gcodes. The file is 659120 lines long, which is very similar to the number of gcodes, which we would expect.

I'll run a few more tests and upload a few more files but a few things I thought about:

Prior to me posting here, PTG (a year?) would do this every once in a while but there was no discernible pattern. I just chalked it up to something odd in the Gcode and while it was a nuisance, it wasn't end of the world.
A few days before posting, I had replaced my hot end so I went through Teaching Tech's calibration stuff and tried to dial in acceleration, feedrate, etc. I don't think there is anything I would have done there that would cause the oddities but things started being way out of whack after that. Maybe coincidence.
The last couple of prints seem to have calculated correctly as I don't get any very large or very small numbers, all within a few minutes of Cura's estimate.
I re-uploaded one of the small prints I previously did. Cura said 17m, PTG originally said 6m. When I uploaded this morning, PTG showed 22m. I may print it just to see.
For heating bed and hot end, I usually so those manually, get them to temp, then hit the print button. I have also had some prints lately that I didn't let the hot end or bed cool completely, just cleared the bed, manually reheated things and started another print. I'm not sure if that would cause any oddness with the compensation factors.

Not sure if it helps, but here is what my latest compensation values. I cleared them when this problem started based on reading in another issue so this is only for the last dozen or so prints. That last one seems huge.

I wonder if the first step is to uninstall and reinstall PTG. The follow up to the standard "have you turned it off and back on again" (i've already restarted the Pi a couple of times). But since the last few have been ok (no large or small numbers), I may just re-upload some of the files I was having issues with and see if anything has changed in the calcs. If so, that is where the real mystery begins as I haven't changed anything.

I'll run a few tests and report back. Thanks for all the input, support, and quick responses on this.

We can see that heating is taking around 200 seconds and cooling is 5 seconds. Remember that heating is the time from when you press the print button until there is extrusion. So even if the bed and nozzle are already hot, maybe you have other stuff going on like calibration or whatever. PTG doesn't care and it doesn't really matter what's going on there. PTG will use the average. You can see that the prediction is 13.1 because marlin-calc doesn't actually know how long your printer takes to heat and calibrate or whatever else. So it's just going to take all the time from the start of the print until the first extrusion and assume that all of that takes 200+ seconds, even though the calculation was 13.1s. The cooling will have a similar calculation.

I see that actual versus predicted are pretty close in all but the last one. Look at that prediction! So weird. I have no idea why that is happening. I'm glad that it resolved itself. Maybe I would be able to debug it if it were on my computer here but I don't even own a 3D printer, nor a Raspberry Pi or anything else so there's not much that I can do, I'm afraid.

eyal0 / OctoPrint-PrintTimeGenius

Time calculated incorrectly, even when clearing the compensation values #278