Keep stepcompress move history relative to current time #6439

EiNSTeiN- · 2023-12-27T20:55:17Z

Currently the stepcompress history is removed as soon as it's older than 30 seconds before the furthest move in the stepcompress queue. If the furthest move is long and will end more than 30 seconds in the future, then the stepcompress history will return a "future" stepper position rather than a past position.

I found this issue while trying to graph the output of extruder.find_past_position(print_time) with a 45mm move at 1.33mm/s, which puts it around 33.8 seconds, and it would give me a graph like this one:

Note the purple line (the expected extruder position) is constant for the first ~4 seconds of the move rather than providing the expected stepper position. With this fix applied, the graph is as expected:

This was reported, for example, in: https://klipper.discourse.group/t/filament-sensor-triggers-on-long-g0-e-command/3771. It's hard to track real world problems which can be caused by flushing the history too early but I've personally observed false positives with my BTT SFS v1 which might be related t this. I have a 350mm printer so long moves on top/bottom layers are to be expected when printing large parts at slow speeds, as we do with the first layer and the top infill.

…ory queue Signed-off-by: Francois Chagnon <fc@francoischagnon.net>

KevinOConnor

Thanks for working on this! In general, it looks good to me. See some minor comments below.

-Kevin

KevinOConnor · 2023-12-27T21:49:38Z

klippy/chelper/stepcompress.c

+void __visible
+steppersync_history_expire(struct steppersync *ss, uint64_t end_clock)


Should be static.

KevinOConnor · 2023-12-27T21:50:50Z

klippy/chelper/trapq.c

@@ -206,7 +204,7 @@ trapq_set_position(struct trapq *tq, double print_time
                   , double pos_x, double pos_y, double pos_z)
 {
    // Flush all moves from trapq
-    trapq_finalize_moves(tq, NEVER_TIME);
+    trapq_finalize_moves(tq, NEVER_TIME, 0);


This would introduce a subtle change in behavior. All places that fully cleared the history should continue to fully clear the history - thus trapq_finalize_moves(tq, NEVER_TIME, NEVER_TIME);

KevinOConnor · 2023-12-27T21:51:00Z

klippy/extras/force_move.py

@@ -86,7 +86,7 @@ def manual_move(self, stepper, dist, speed, accel=0.):
                          0., 0., 0., axis_r, 0., 0., 0., cruise_v, accel)
        print_time = print_time + accel_t + cruise_t + accel_t
        stepper.generate_steps(print_time)
-        self.trapq_finalize_moves(self.trapq, print_time + 99999.9)
+        self.trapq_finalize_moves(self.trapq, print_time + 99999.9, 0)


KevinOConnor · 2023-12-27T21:51:11Z

klippy/extras/manual_stepper.py

@@ -67,7 +67,7 @@ def do_move(self, movepos, speed, accel, sync=True):
                          0., cruise_v, accel)
        self.next_cmd_time = self.next_cmd_time + accel_t + cruise_t + accel_t
        self.rail.generate_steps(self.next_cmd_time)
-        self.trapq_finalize_moves(self.trapq, self.next_cmd_time + 99999.9)
+        self.trapq_finalize_moves(self.trapq, self.next_cmd_time + 99999.9, 0)


KevinOConnor · 2023-12-27T21:52:06Z

klippy/toolhead.py

-            self.trapq_finalize_moves(self.trapq, self.reactor.NEVER)
+            clear_history_time = self.reactor.monotonic() - MOVE_HISTORY_EXPIRE
+            self.trapq_finalize_moves(self.trapq, self.reactor.NEVER,
+                                      clear_history_time)


KevinOConnor · 2023-12-27T21:57:24Z

klippy/toolhead.py

@@ -289,13 +290,14 @@ def _advance_flush_time(self, flush_time):
        for sg in self.step_generators:
            sg(sg_flush_time)
        self.last_sg_flush_time = sg_flush_time
+        clear_history_time = self.reactor.monotonic() - MOVE_HISTORY_EXPIRE


The trapq times are relative to the "print_time", not the "system time". To go from a system time to a print_time use self.mcu.estimated_print_time(systime).

Done, I made everything a print time including the time provided to flush_moves and convert using print_time_to_clock rather than get_clock.

KevinOConnor · 2023-12-29T17:59:56Z

Okay, thanks. However, the flushing in DripModeEndSignal was not corrected. Also, it is confusing to use two different mechanisms to implement a full flush in force_move.py and manual_stepper.py (it would be preferable to consistently use either use "+ 99999.9" or "reactor.NEVER").

-Kevin

EiNSTeiN- · 2023-12-29T21:02:50Z

klippy/chelper/trapq.c

@@ -190,10 +189,9 @@ trapq_finalize_moves(struct trapq *tq, double print_time)
    if (list_empty(&tq->history))
        return;
    struct move *latest = list_first_entry(&tq->history, struct move, node);
-    double expire_time = latest->print_time + latest->move_t - HISTORY_EXPIRE;


Just for the record I think we're now clearing the history in places where we wouldn't have before which is a change in behavior. When print_time is NEVER_TIME (or a large value) all the moves would get transferred to the history, but this code would still only clear 30s prior to the last move because of the math on this line. This is why I had the new parameter as 0 initially (to keep the history until this is called from the toolhead code).

Okay, I goofed. You are correct and I misread the original code. I think we do want to avoid a change in behavior here, because this is an area of the code where we really want to be able to use tools like git bisect if necessary.

If I'm reading the code correctly, the call in trapq_finalize_moves() doesn't need to flush the history (it can use 0), and the code in DripModeEndSignal doesn't need to flush (it can also use 0). However, the code in manual_stepper.py and force_move.py do need to fully flush (using the current + 99999.9 method) as nothing else will free the history (and nothing uses the history of these modules).

Does that sound correct?

Thanks.
-Kevin

If you mean trapq_set_position and not trapq_finalize_moves that looks correct to me (as in, it preserves the current behavior), however I'm not super familiar with this code. I left the other 2 calls with + 99999.9 to clear the history.

EiNSTeiN- · 2023-12-29T21:04:56Z

I made the last changes, this should be good to go if you're OK with my other comment

KevinOConnor · 2023-12-30T16:47:50Z

Thanks. I committed this PR along with commit 9847b44 on top.

-Kevin

KevinOConnor · 2023-12-30T17:53:41Z

I just realized that the new history flushing code would not do the right thing when in a debugging "batch mode" ( https://www.klipper3d.org/Debugging.html#translating-gcode-files-to-micro-controller-commands ). I pushed commit 25bc649 to address this.

-Kevin

…ipper3d#6439) Expire history relative to current time rather than last move in history queue Signed-off-by: Francois Chagnon <fc@francoischagnon.net>

Expire history relative to current time rather than last move in hist…

b983e7f

…ory queue Signed-off-by: Francois Chagnon <fc@francoischagnon.net>

EiNSTeiN- force-pushed the history_expire branch from cbef201 to b983e7f Compare December 27, 2023 21:08

KevinOConnor reviewed Dec 27, 2023

View reviewed changes

EiNSTeiN- added 3 commits December 27, 2023 17:53

Make steppersync_history_expire static

8ce5a1a

Remove all history rather than keeping it where appropriate

b688b3a

Use print time rather than system time for history expiry

120fe41

Clear trapq history consistently everywhere

6dc8d59

EiNSTeiN- commented Dec 29, 2023

View reviewed changes

Do not flush trapq history where appropriate

3ebea98

KevinOConnor merged commit d7f6348 into Klipper3d:master Dec 30, 2023
1 check passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Keep stepcompress move history relative to current time #6439

Keep stepcompress move history relative to current time #6439

EiNSTeiN- commented Dec 27, 2023

KevinOConnor left a comment

KevinOConnor Dec 27, 2023

KevinOConnor Dec 27, 2023

KevinOConnor Dec 27, 2023

KevinOConnor Dec 27, 2023

KevinOConnor Dec 27, 2023

KevinOConnor Dec 27, 2023

EiNSTeiN- Dec 27, 2023

KevinOConnor commented Dec 29, 2023

EiNSTeiN- Dec 29, 2023

KevinOConnor Dec 29, 2023

EiNSTeiN- Dec 29, 2023

EiNSTeiN- commented Dec 29, 2023

KevinOConnor commented Dec 30, 2023

KevinOConnor commented Dec 30, 2023

		void __visible
		steppersync_history_expire(struct steppersync *ss, uint64_t end_clock)

Keep stepcompress move history relative to current time #6439

Keep stepcompress move history relative to current time #6439

Conversation

EiNSTeiN- commented Dec 27, 2023

KevinOConnor left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

KevinOConnor commented Dec 29, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

EiNSTeiN- commented Dec 29, 2023

KevinOConnor commented Dec 30, 2023

KevinOConnor commented Dec 30, 2023