Precisely measure time between two macro executions

I’m working on a macro that implements G10 (Retract) and G11 (Unretract) for finer control of the unretract length. My goal is to have a variable length of unretraction that depends on the time that has passed since the retraction. This is to help with very oozy nozzles like the Volcano.

The principle is inspired from the Scalable Extra Prime Cura plugin, that varies the extra length of unretraction based on how much the nozzle has traveled since the retraction. My intent is to turn this into a macro, so that it can be used regardless of slicer (so no longer limited to Cura, as long as the slicer supports firmware retractions), and to use travel time rather than travel distance, as time spent traveling is a much more accurate predictor of the amount of oozing.

I have most of the logic pinned down, but I’m having a hard time figuring out how to capture the retraction/unretraction timing precisely.

My first attempt was this (simplified to focus on timing):

[gcode_macro G10]
variable_last_retract_time: -1
gcode:
  SET_GCODE_VARIABLE MACRO=G10 VARIABLE=last_retract_time VALUE={printer.idle_timeout.printing_time}
  ; Retraction logic ...

[gcode_macro G11]
gcode:
  {% set last_retract_time = printer["gcode_macro G10"].last_retract_time %}
  {% set TIME_SINCE_LAST_RETRACT = printer.idle_timeout.printing_time - last_retract_time %}
  ; Unretraction logic ...

This basic implementation doesn’t work, because when G10 and G11 are called during a print, the commands get buffered, and the jinja tags get evaluated at buffer-time rather than execution-time. For instance, if the following gcode is executed:

; Retract
G10

; Travel
G1 X30 Y10 F800

; Unretract
G11

…both G10 and G11 will be evaluated before the intermediate travel has even begun. So the printer.idle_timeout.printing_time variable is not representative of the instant at which the retraction and unretractions happen, and TIME_SINCE_LAST_RETRACT is incorrect. Same story with other timing variables like printer.system_stats.cputime and printer.toolhead.estimated_print_time.

To address this issue, I attempted to use M400 (Finish moves) in two encapsulating macros, which forces Klipper to wait for any toolhead move to complete before evaluating the macros that capture timing information:

[gcode_macro _RETRACT]
variable_last_retract_time: -1
gcode:
  SET_GCODE_VARIABLE MACRO=_RETRACT VARIABLE=last_retract_time VALUE={printer.idle_timeout.printing_time}
  ; Retraction logic ...

[gcode_macro _UNRETRACT]
gcode:
  {% set last_retract_time = printer["gcode_macro _RETRACT"].last_retract_time %}
  {% set TIME_SINCE_LAST_RETRACT = printer.idle_timeout.printing_time - last_retract_time %}
  ; Unretraction logic ...

[gcode_macro G10]
gcode:
  M400
  _RETRACT

[gcode_macro G11]
gcode:
  M400
  _UNRETRACT

This approach fixes the issue, but M400 introduces a ~1s delay to execution, so for instance if the following gcode is executed:

; Extrude
G1 X30 Y10 E10 F800

; Retract
G10

… the toolhead will perform its move-extrude motion, pause for a second, then execute the retraction. This pause is enough for the pressure in the nozzle to push an excessive amount of molten plastic at the end of the extrusion. Without M400, there is no pause, but we’re back to the previous time-capturing issues.

Does anyone know if there’s another way to compare the real time that has passed between two macro executions? Is there any other way to force a gcode macro not to be buffered, without introducing any processing delay? Is there another way to capture timing in gcode, outside of Jinja templates? Would implementing this as an ‘extra’ module would make more sense and would provide access to real-time timing information?

Plan B is to calculate the unretraction amount from travel distance, but this would be less than ideal for multiple reasons.

As a side-note, I’m aware of [firmware_unretraction], but the commands it implements don’t allow the adjustment of unretract_extra_length between the G10 and G11 calls. Retractions are reset as soon as SET_RETRACTION is called and any subsequent call to G11 is ignored.

The trick is to take advantage of the fact that macros are merely evaluated when queued, but not actually executed until runtime. So have a separate macro that is dedicated to taking the time “snapshots,” doing the time calculations, and updating the last_retract_time variable. You could even put the variable in that separate timer macro. Then call the timer macro from within G10/G11 instead of M400.

Really appreciate your help, thanks.

From my understanding, macros are evaluated and executed as they are buffered. At least in the sense that Klipper goes through the commands in the [gcode_macro] block and executes them one after the other until it meets a gcode command that has an internal loop (polling a sensor for instance), such as M400 or TEMPERATURE_WAIT. If one of the command is a macro itself, it is evaluated at that time and executed.

This can be confirmed with this macro:

[respond]
default_type: echo
default_prefix:

[gcode_macro LOG_TIME]
gcode:
    RESPOND MSG='{printer.idle_timeout.printing_time}'

… and the following gcode file:

LOG_TIME
G0 X100 F600
G0 X-100 F600
LOG_TIME

Klipper will evaluate and execute all four commands from the gcode file at pretty much the same time. The first LOG_TIME will output the current print time to the console, the two G0 commands will be converted to stepper commands and queued on the MCU, and the second LOG_TIME will run pretty much instantaneously, before even the first travel move has completed. The two time entries in the console will only be a few ms apart even if the travel moves take a few seconds to complete. The behavior doesn’t change if the RESPOND command is encapsulated into another macro.

If I understood your suggestion correctly, this is how the retraction macro would be re-worked:

[gcode_macro G10]
gcode:
  _CAPTURE_RETRACT_TIME
  ; Retraction logic ...

[gcode_macro G11]
gcode:
  {% set last_retract_time = printer["gcode_macro _CAPTURE_RETRACT_TIME"].last_retract_time %}
  {% set TIME_SINCE_LAST_RETRACT = printer.idle_timeout.printing_time - last_retract_time %}
  ; Unretraction logic ...

[gcode_macro _CAPTURE_RETRACT_TIME]
variable_last_retract_time: -1
gcode:
  SET_GCODE_VARIABLE MACRO=_CAPTURE_RETRACT_TIME VARIABLE=last_retract_time VALUE={printer.idle_timeout.printing_time}

… with gcode:

; Extrude
G1 X30 E10 F800

; Retract
G10

; Travel
G0 X30 F800

; Unretract
G11

But the _CAPTURE_RETRACT_TIME macro would still be evaluated and executed ahead of the extrusion being completed. Same with G11 which happens too early and computes TIME_SINCE_LAST_RETRACT before the travel move completes.

I still gave it a shot in case I was misunderstanding something, and unfortunately _CAPTURE_RETRACT_TIME did run before the first extrusion completed, as expected.

Am I missing something?

No, you’re right. I went through this a few months back while I was working on a complex set of macros to implement persistent state tracking of things like whether there is currently filament loaded in the hotend, and if so, which one. I also wanted to log how long it takes my print_start, print_end, and filament_change macros to run so I could get more accurate print time estimates.

The method I suggested is what ended up working for me for timing the macros, but on further reflection, that’s probably because those macros have temperature-change commands that block further execution of gcode until they complete.

It may be possible to hack together something that does what you want by using delayed_gcode. I have to confess that delayed_gcode sometimes confuses me but I recall seeing examples of it being used to ensure that certain events occur when you want them to rather than when the command is put into the queue.

This may not work but if it were me, I’d experiment and see if you can leverage having a macro that has a .1s initial duration but that continually updates itself to extend the delay by .1s until it’s “killed” with

UPDATE_DELAYED_GCODE ID=macro_name DURATION=0

Maybe that macro could be continuously adding its duration length to a variable, and then after it’s “killed,” the value of that variable would be within one duration unit of the total time the macro ran.

I can see how time measurements can be helpful in the functionality you developed. I’ve played around with delayed_gcode, but ultimately I can’t see a way to determine when the travels and extrusions end as it is mostly non-deterministic from Klippy’s (the host’s) end. It seems that even implementing this functionality as an ‘extra’ module wouldn’t necessarily provide the needed precision to achieve reliable time measurement between retract and unretract events. Digging further into the MCU logic might provide more insight, I might try delving into this later.

For now I’ve ported the Cura plugin to a post-processing script that can be used automatically with Slic3r, PrusaSlicer, OrcaSlicer, or independently. It serves its purpose and I can move on to the next thing.

Thanks again for your help!

hey mate did you ever get this working at all i am having the exact same problem with needing to have a scaleable unretract

Hello @andrewbaumann52 !

Obviously not. Else this thread would be marked Solved with a solution.

I recommend to open a new thread with all the requested information. Thank you.