Estimated time shorter
Closed this issue · 16 comments
On my Klipper based modded Voron 2.4 I've had very low feedrate limits configured in SuperSlicer by accident as I did not recognize that they need to be entered in mm/min and thought it would be mm/s when I switch from Simplify3D to SuperSlicer.
Anyways - I would have expected klipper_estimator to calculate the time closely to the actual print time even with those weird settings.
In your program description you write:
If the timing is far off(e.g. more than a minute over a >12 hour print), this is considered a bug.
In my case the the actual print time was much longer than the forecast of kliper_estimator and so I wonder if there could be a logical problem if limits are set via GCODE?
This is my test gcode SuperSlicer v2.3.57 produces:
DinRailMount6.5mm-6.35279g-27m.gcode.zip
SuperSlicer v2.3.57 expects a print time of: 26m 59s
Klipper_estimator v1.5.0 calculates a print time of 28m 51s
Real print time took: 38m 49s
The picture of KlipperScreen shows the expected print time patched by klipper_estimator and the actually needed time to print:
My json dump-config looks like this:
{
"max_velocity": 500.0,
"max_acceleration": 10000.0,
"max_accel_to_decel": 10000.0,
"square_corner_velocity": 5.0,
"instant_corner_velocity": 1.0,
"move_checkers": [
{
"axis_limiter": {
"axis": [
0.0,
0.0,
1.0
],
"max_velocity": 30.0,
"max_accel": 1000.0
}
},
{
"extruder_limiter": {
"max_velocity": 60.0,
"max_accel": 600.0
}
}
]
}
In SuperSlicers printer settings tab I've had the following very weird limits configured:
- Maximum feedrate X: 500mm/min
- Maximum feedrate Y: 500mm/min
- Maximum feedrate X: 30mm/min
- Maximum feedrate E: 60mm/min
- Maximum acceleration X: 9000mm/s^2
- Maximum acceleration Y: 9000mm/s^2
- Maximum acceleration Z: 500mm/s^2
- Maximum acceleration E: 10000mm/s^2
- Maximum acceleration when extruding: 5000mm/s^2
- Maximum acceleration when retracting: 5000mm/s^2
- Maximum acceleration when traveling: 5000mm/s^2
- Maximum jerk X: 10mm/s
- Maximum jerk Y: 10mm/s
- Maximum jerk Z: 2.5mm/s
- Maximum jerk E: 2.5mm/s
- Minimum feedrate when extruding: 0mm/min
- Minimum travel feedrate: 0mm/min
In general is klipper_estimator able to calculate the influences of activated pressure advance and input shaper?
Before getting informed about your tool I've run these 2 commands on the Raspberry PI after gcode file upload:
sed -e '/\[include inputshaper.cfg\]/d' ~/klipper_config/printer.cfg > ~/klipper_config/printer.cfg.tmp
~/klippy-env/bin/python ~/klipper/klippy/klippy.py ~/klipper_config/printer.cfg.tmp -d ~/klipper/out/klipper.dict -o /dev/null -i ~/gcode_files/my_uploaded.gcode
and used the calculated time to automatically patch the gcode.
Like you see I had to disable the input shaper config section as the klippy dry-run failed when finding [mcu rpi] and [adxl345] sections in the printer.cfg file. The missing input shaper config resulted in a falsified but a little better estimation of 31m 8s for the upper example.
Thank you for the great work you put into addressing the klipper print time estimation problem!
Update:
Because I've configure SuperSlicer to
machine_limits_usage => time_estimate_only
The slicers speed parameters did not influence the gcode and so they should not influence the print time or the klipper_estimator calculatuon.
As the limits in printer settings seam to be irrelevant - here are my print settings -> speed settings:
I know you can also see them in my uploaded gcode, but maybe the screenshot makes them easier to analyze.
The configured travel speed of 700mm/s in slicer will be limited by the klipper/server side max velocity setting of 500mm/s
But I think the maximum travel speed is not reached on this small test part because the travel acceleration of 7500mm/s^2 is limiting it.
Hi!
Input shaper and pressure advance don't affect print time, as they are calculated on the planned output (the part klipper_estimator replicates).
I'll take a look tomorrow when I'm back home, thanks for a very thorough report :)
Can you send your print start macro as well?
If you could perform another test run and pay special attention to when the print time starts counting, that'd be very useful. In Fluidd with my own settings the total time includes heating, while "actual time" always matches the estimated time + 20 seconds (prime line etc).
Best regards
Lasse
Hello Lasse,
I'm using MainsalOS and the print time is staying at 0:00 until the actual print starts.
The heating process is part of my print start code and excluded from the actual print time.
In SuperSlicers 'Printer Settings' ->'Custom G-code' I have activated the checkbox 'Only custom Start G-code':
So the heating is not part of the Slicers Start G-Code.
As you can see in the picture my Slicers Start G-Code is:
PRINT_START EXTRUDER=[first_layer_temperature] BED=[first_layer_bed_temperature]
G90 ; use absolute coordinates
M83 ; use relative distances for extrusion
My Klipper PRINT_START macro looks like this:
[gcode_macro PRINT_START]
# Use PRINT_START for the slicer starting script - please customise for your slicer of choice
gcode:
{% set H = params.EXTRUDER|default(printer.save_variables.variables.default_hotend_temp)|float %}
{% set B = params.BED|default(printer.save_variables.variables.default_bed_temp)|float %}
G32 H{H} B{B} N ; home all axes and level gantry and do not cool down afterwards
G90 ; absolut positioning
G92 E0 ; Zero extruder
MSG MSG="Starting print ..."
MSG is just a small macro of mine reporting the text as M117 and M118:
[gcode_macro MSG]
gcode:
{% if 'MSG' in params %}
M117 {params.MSG}
M118 {params.MSG}
{% endif %}
The actual heat-up is handled in my G32 macro as I need to have a heated nozzle for a good reading of the Z-Endstop (coll.: 'sex bolt') which is activated with the nozzle. Here is my G32 macro:
[gcode_macro G32]
gcode:
{% set H = params.H|default(printer.save_variables.variables.default_hotend_temp)|float %}
{% set B = params.B|default(printer.save_variables.variables.default_bed_temp)|float %}
{% set X = params.X|default(printer.save_variables.variables.park_x)|float %}
{% set Y = params.Y|default(printer.save_variables.variables.park_y)|float %}
{% set Z = params.Z|default(printer.save_variables.variables.park_z)|float %}
{% set prevHotendTemp = printer.extruder.target|float %}
{% set prevBedTemp = printer.heater_bed.target|float %}
MSG MSG="Start heating bed to {B}C"
M140 S{B} ; start heating bed
{% if printer.configfile.settings.bed_mesh is defined %}
BED_MESH_CLEAR
{% endif %}
MSG MSG="Homing axis if not homed jet"
CG28 ; Home axis which have not been homed jet
MSG MSG="Wipe Nozzle"
#Sexbolt position: 233,359
G1 X245 Y359 F{printer.configfile.settings.stepper_x.homing_speed|float * 60}
G1 Z0 F{printer.configfile.settings.stepper_z.homing_speed|float * 60}
G1 X245 Y345 F{printer.configfile.settings.stepper_x.homing_speed|float * 60 // 2}
MSG MSG="Leveling Gantry"
QUAD_GANTRY_LEVEL
MSG MSG="Homing X and Y axis"
G28 X Y; Home X and Y axis again
MSG MSG="Parking extruder X{X} Y{Y} Z{Z}"
G90
G92 E0 ; Zero extruder
G1 X{X} Y{Y} Z{Z} F{printer.configfile.settings.stepper_x.homing_speed|float * 60}
{% if params.N is defined %}
MSG MSG="Wait for heating bed to {B}C"
M190 S{B}
{% endif %}
MSG MSG="Wait for heating hotend to {H}C"
M109 S{H}
G92 E0 ; Zero extruder
G1 E10.0 F{printer.save_variables.variables.default_retraction_speed|float // 5}
G92 E0 ; Zero extruder
MSG MSG="Wiping nozzle"
G1 Z0 F{printer.configfile.settings.stepper_z.homing_speed|float * 60}
G1 X245 Y359 F{printer.configfile.settings.stepper_x.homing_speed|float * 60 // 2}
G1 X350 Y359 F{printer.configfile.settings.stepper_x.homing_speed|float * 60 // 2}
MSG MSG="Homing Z axis with heated nozzle"
G28 Z; Home Z axis again
MSG MSG="Wiping nozzle"
G1 X245 Y359 F{printer.configfile.settings.stepper_x.homing_speed|float * 60 // 2}
G1 Z0 F{printer.configfile.settings.stepper_z.homing_speed|float * 60}
G1 X350 Y359 F{printer.configfile.settings.stepper_x.homing_speed|float * 60 // 2}
G1 Z5 F{printer.configfile.settings.stepper_z.homing_speed|float * 60}
{% if params.N is not defined %}
MSG MSG="Setting Bed Temp to {prevBedTemp}C"
M140 S{prevBedTemp} ; return to previous bed temp
MSG MSG="Setting Hotend Temp to {prevHotendTemp}C"
M104 S{prevHotendTemp} ; return to previous hotend temp
{% endif %}
G90 ; activate Absolute Positioniing
G92 E0 ; Zero extruder
MSG MSG="G32 done"
The CG28 macro is only a conditional G28 and only homes the axis which have not been homed jet:
[gcode_macro CG28]
description: Conditional G28 (home if not already homed)
gcode:
{% if params.X is defined %}
{% set X = params.X|float %}
{% set homeX = True %}
{% else %}
{% set homeX = False %}
{% endif %}
{% if params.Y is defined %}
{% set Y = params.Y|float %}
{% set homeY = True %}
{% else %}
{% set homeY = False %}
{% endif %}
{% if params.Z is defined %}
{% set Z = params.Z|float %}
{% set homeZ = True %}
{% else %}
{% set homeZ = False %}
{% endif %}
{% if not homeX and not homeY and not homeZ %}
{% set homeX = True %}
{% set homeY = True %}
{% set homeZ = True %}
{% endif %}
{% if homeX and "x" in printer.toolhead.homed_axes %}
{% set homeX = False %}
{% endif %}
{% if homeY and "y" in printer.toolhead.homed_axes %}
{% set homeY = False %}
{% endif %}
{% if homeZ and "z" in printer.toolhead.homed_axes %}
{% set homeZ = False %}
{% endif %}
{% if homeX and homeY %}
G28 X Y
{%elif homeX %}
G28 X
{%elif homeY %}
G28 Y
{% endif %}
{% if homeZ %}
G28 Z
{% endif %}
Please do not blame be for wring bad macro code. I'm pretty new to Klipper and so these are the first Klipper macros I ever wrote.
Kind regards,
Thomas
Forgot to mention: On this printer I do not use a prime line and go with a skirt instead. As the skirt is part of the gcode the slicer produces the time printing it is part of the counted print time.
The G32 macro parts which I call 'Wiping nozzle' moves the nozzle over a bras brush I have installed behind the print bed next to the se bolt.
The print I've started this afternoon is a longer one. The gcode got processed by klipper_estimator as SuperSlicer postprocess before uploading to the printer.
So you can see klipper_estimator estimated 5h 46m 38s of print time.
SuperSlicer estimated 5h 20m.
Currently the print is at 73% and took already 6h 4m 54s.
So something is completely wrong with my setup.
Here is the gcode I'm currently printing:
PrinterSideHandleLeft-89.1711g-5h20m.gcode.zip
The Klipper side dump-config is unchanged to the one from above.
The print settings speed I've pushed a little further to:
The machine limits are now updated and sent to the gcode:
Kind regards,
Thomas
Hi!
Something is definitely fishy, but I can't really figure out what could be causing it.
I just ran the gcode you sent me originally, and with a (slightly modified from my normal config), Klipper batch mode gives me:
INFO:root:Exiting (print time 1681.936s)
Which is 28m1.936s
While estimator gives me:
Sequences:
Run 0:
Total moves: 115770
Total distance: 105424.253mm
Total extrude distance: 2513.900mm
Minimal time: 27m59.361s (1679.361s)
Total print move time: 23m4.066s (1384.066s)
Total extrude-only time: 1m34.173s (94.173s)
Total travel time: 3m21.122s (201.122s)
Average flow: 3.601 mm³/s
Average flow (output only): 4.369 mm³/s
Phases:
Acceleration: 6m43.394s
Cruise: 14m24.943s
Deceleration: 6m51.023s
So a very slight discrepancy here, but I'm not sure that's real(Klipper does some other stuff around starting and stopping the toolhead that could explain it, I need to verify moves later).
Best regards,
Lasse
Hi!
I was able to verify the move sequence with my own config, though there was a small discrepancy caused by a missing lookahead offset(I've pushed an update for that).
So I have to admit, right now I'm not sure where to look :(
Best regards,
Lasse
Hello Lasse,
Thank you for the time you already spend analyzing it!
The second print finally took 7h 42m 32s while klipper_estimator estimated 5h 46m 38s.
This is really a huge difference and makes the information in the KlipperScreen an in the gcode overview list a little useless.
There has to be something in my configuration which drives the calculation nuts.
Unfortunately I'm totally new to klipper and can not support you in any way.
In Marlin when linear advance was enabled there was a lot of retraction and unretraction work going on and the acceleration of the E-axis was typically the limiting factor, which extremely slowed down the print progress and pushed the resulting print time far from the slicers estimations. I do not know how pressure advance is working compared to linear advance and so I can not project my knowledge here. I just read very often that linear advance in Marlin and pressure advance in klipper have the same goal of keeping the pressure linear in the nozzle and avoiding over-extraction at the end of an extraction.
As this slightly modified Voron 2.4 printer has a direct drive Galileo 1.5 extruder the compensation pressure advance has to manage is not huge. My relevant settings in printer.cfg for the extruder are:
max_extrude_only_velocity: 60
max_extrude_only_accel: 600
pressure_advance: 0.050 # 0.1
pressure_advance_smooth_time: 0.02
Because of torque problems and lost steps on high speed prints I replaced my mighty LDO-36STH20-1004AH stepper with an Fysetc G36HSY4407-6D-1200A stepper which can push the filament via the 7.5:1 ratio of the galileo extruder with much lower hotend temperatures that the LDO-36STH20-1004AH was able to handle with the same gear box. I know that in theory the LDO stepper has a much better datasheet, can handle more current, more velocity and even more acceleration. I tried 4 of those LDO steppers but ended up using the one from Fysetc.
Are you only using the data showed in dump-config to feed your klipper based estimation or are you fetching further information via moonraker API for feeding your algorithm?
Did I understand you right, that you are not expecting pressure advance to slow down the build?
Kind regards,
Thomas
Hi Thomas!
Pressure advance and input shaper in Klipper are implemented in the itersolver step, where trapezoidal planning moves are turned into actual steps. This step basically gets "ramps" with exact start and ending times, and so it can't affect the print time. Consequently, klipper_estimator doesn't implement it.
Printing in Klipper is fully "open loop": a path is generated and the machine is asked to execute it, but there's no feedback that can change the total time. This is also why klipper_estimator can be accurate down to the millisecond(as you can see from my example screenshot).
I've been looking over the code and I can't find anything that jumps out as being settable in Klipper but not in the tool.
Can you send me your full printer config, and then I will go over and verify that everything relevant is correctly read by klipper_estimator. If your config is multiple files you can either zip it, or, probably easier, just copy it from the top of your klippy.log. Klipper outputs the loaded config at the top when it starts up.
Best regards,
Lasse
Hello Lasse,
Thank you for explaining the differences in the way klipper is handling pressure advance compared to the marlin approach.
Here is the head of my klippy.log containing all the combined config lines:
klippy.log
Thank you so much for taking the time of analyzing it!
Kind regards,
Thomas
Hi Thomas!
Things just keep getting wierder. I just did a bench run with your config(after a few adaptations to get it to run with my MCU dictionary, single MCU, and no driver sections). I get:
- Klipper bench: 1730.658s
- Estimator: 1730.745s (1730.658s with 700mm/s limit)
I really can't figure out what would be causing your machine to be taking so much longer seemingly "out of the blue" :( Nothing jumps out at me when looking over the config. I'll have a think on what else could be going on here.
Best regards,
Lasse
Hi Lasse,
if the dictionary is making such a difference (I'm really green here on this field), is klipper_estimator able to fetch the dictionary from the Klipper host via API or how do you solve that the slicer side and the printer side dictionaries are in sync?
In the following post KevinOConnor provided a set of dictionaries for the different available MCUs:
Klipper "data dictionaries" for regression tests #1438
My printers main MCU is a BTT Octopus Pro 1.0 board which hast the stm32f446 MCU.
Because I do not know how import it ist that the dict files are up to date I add my dictionary from ~/klipper/out/klipper.dict here as well:
klipper_dict.zip
Keep my fingers crossed that my post here is of any help and not complete nonsense.
Kind regards,
Thomas
Hi Thomas!
The dictionary itself should have no impact on the final time, as it's merely used for emulating the MCU in benchmark mode. Indeed, re-running with the dictionary you just provided gives the exact same 1730.658s of time for me.
To confirm, I also just did a test with the other sample you sent me, and I get:
- Klipper bench: 20935.454s
- Estimator: 20869.598s
So here's actually a significant difference that I will look into. Still nothing like the hours difference you saw however.
I also noticed that the original config JSON has a velocity limit of 500 while your klippy.log shows 700.
Edit:
So I did a re-run with 700 mm/s in the config JSON, and with empty PRINT_START and PRINT_END macros(uncommented everything in them). This gives me:
- Bench: 20797.577s
- Estimator: 20797.577s
When re-running estimator on the original gcode with the 700 mm/s limit I get 1730.658s, exactly the same time as bench mode.
Best regards,
Lasse
Hi Lasse,
I'm still trying to figure out what is causing the slow downs compared to all estimations on my printer. I did try a lot (both slicer and Klipper wise) but have not found parameters which reduce the big estimation gap.
I just want to let you know that I'm sill searching for a reason and that I have not forgotten this ticket here.
Best regards,
Thomas
I'll close this for now, feel free to post any updates here and we'll re-open if relevant :)
Best regards
Lasse