mcu: fix endstop probing

This patch addresses the issue reported in #6711 and on discourse. Specifically, when a homing or probing move is complete there may be a small deviation between the reported trigger steps and halt steps, depending on the user's configuration. As discussed in the issue, it was my believe that this deviation was likely due to the exclusion of oversampling in the reported trigger time when probing/homing.

I was able to reproduce and confirm this behavior, and in my tests this change resolves it. I do think it would be useful if some additional testers can pull this PR and confirm that it resolves the issue on their machines as well.

I will have conclusive results tomorrow, waiting for external test results :+1:

@miklschmidt if @Arksine's fix resolves the issue, can RatOS users look for a patch to RatOS or will we need to wait on @KevinOConnor? I have struggled with my V-Core 3 since I built it nearly two years ago and nothing has worked. This bug gives me hope of a resolution.....

@smnino RatOS is following klipper mainline, a real fix isn't available until it has been merged here. Afterwards, an update of Klipper will be all you have to do.

In the meantime, you can try putting this in the bottom override section of your printer.cfg, which should greatly reduce the chance of drift (the interpolation: True is to reduce the stepper noise, introduces a small inaccuracy but it's nothing compared to the status quo and it's not accumulating).

[stepper_z]
microsteps: 16
[tmc2209 stepper_z]
interpolate: True

[stepper_z1]
microsteps: 16
[tmc2209 stepper_z1]
interpolate: True

[stepper_z2]
microsteps: 16
[tmc2209 stepper_z2]
interpolate: True

You can further reduce the risk of drift by lowering your probe speed, and finally you can reduce the amount of drift accumulated by lowering your probe sample count.

[probe]
samples: 1
speed: 3

Another option is Beacon, which is unaffected by this bug, both in proximity and contact mode.

Thanks. The change here does not seem correct to me (at an initial review, it seems like it would introduce a regression).

There are two critical positions that are tracked during homing/probing operations: the trigger position and the halt position. The trigger position is the calculated position the toolhead was at when the endstop signal is first observed. The halt position is the position the toolhead is at when the toolhead stops moving after a homing/probing attempt.

The trigger position is calculated from the "trigger time" - which should be the time that the endstop is first observed to be in a triggered state. This is initially set in endstop.c:endstop_event() (uint32_t nextwake = e->time.waketime + e->rest_time), reported to the host in endstop.c:command_endstop_query_state(), and readjusted in mcu.py:home_wait() (self._mcu.clock_to_print_time(next_clock - self._rest_ticks)). Thus, we're effectively reporting the time from e->time.waketime - the time of the endstop event that first observed the endstop signal.

The halt position is used to determine where the toolhead position finally ended after the event - it's needed so that any following movements are correctly scheduled. So, for example, if the toolhead starts a probe at z=20, a trigger position is observed at z=4, the toolhead halts at position z=3.5 then the probe should report a measured height of 4 - probe_offset, and a following move to z=10 should move the toolhead up 6.5mm.

It looks like this PR would change the trigger time to be 45us after the initial observation of the trigger. Maybe I'm missing something, but that looks like it would introduce a regression.

I'm not sure I understand the issue being solved. It's normal for the halt position to differ from the trigger position. The positions can differ due to oversampling (the motor is still moving during the time that we are verifying the signal is not intermittent noise) and the positions can differ due to delays in propagating a trigger signal when using multi-mcu homing. So, seeing a difference between the two values is normal and not an anomaly.

It is, of course, possible there is a defect in this code. I think it would help if there was a Klipper log from the event so we could trace a specific event. That is, if we can identify a specific starting toolhead position, trigger time, ending toolhead position, and reported z height, then maybe we could identify the expected reported z height and expected final z commanded position - thus confirming a defect and possibly help identify what area of the code is defective.

Thanks again, -Kevin

@KevinOConnor I provided plenty of information for you to reproduce the issue, just like Arksine has done. All you need is a controller with an endstop and a stepper driver, doesn't matter if it's on X, Y or Z. The information you need is not present in a vanilla log, i posted the relevant pieces from the logging i added.

Let me try and explain the problem again by referencing a few of the points you made.

The trigger position is calculated from the "trigger time" - which should be the time that the endstop is first observed to be in a triggered state

Correct, which is why it's wrong. The steps generated within the 45us (hardcoded endstop oversampling values) window, after the first trigger, is added to the stepper position, so you need to subtract those before adding the step difference between trigger and halt time. That's why offsetting the trigger_time by the endstop oversampling time solves the issue. On single-mcu homing, there should not be any difference between trigger and halt.

The positions can differ due to oversampling (the motor is still moving during the time that we are verifying the signal is not intermittent noise)

That movement seems to be reflected in the stepper position state that you're adding the trigger_step - halt_steps difference to. As i hinted at in my issue.

It looks like this PR would change the trigger time to be 45us after the initial observation of the trigger. Maybe I'm missing something, but that looks like it would introduce a regression.

The bug is real and proven (steps provided in the issue you locked). This fix is being verified. If you can prove it introduces a regression, we can look at that.

I do not understand what the underlying issue being reported is.

From the issue cited above:

Expected Behavior Trigger and halt positions should align without a consistent shift during probing operations. Unsure about multi-mcu setups, but the issue would be present there as well.

This is not a valid expectation. The halt_position and trigger_position will not always be the same. Great effort went into the code to handle the two positions not being the same. The code needs to handle these differences to get the correct results. Handling these two positions correctly is at the heart of multi-mcu homing.

On single-mcu homing, there should not be any difference between trigger and halt.

This is not correct. The halt_position and trigger_position can, will, and should differ even on single mcu homing.

The information you need is not present in a vanilla log, i posted the relevant pieces from the logging i added.

In the log snippets that you provided, I do not know what you are reporting is incorrect. It is true that the "trigger at" positions do not match the "halt at" positions, but this is expected and intentional.

Please provide a full klipper log showing the event. If you have to add log messages, then fine, but otherwise use unmodified pristine klipper code. Separate from that full log, please provide a snippet of the log that provides unexpected results and provide the values that you did expect it to report.

It is my expectation that providing a full log takes under 10 minutes. I've spent several hours reviewing code and running tests. Everything I've done so far on my printers produces the results that I expect. I can't continue spending time searching for something when I do not understanding what I'm looking for.

-Kevin

@KevinOConnor

This is not a valid expectation. The halt_position and trigger_position will not always be the same.

That's not what it says. Read the quote again. without a consistent shift during probing operations.

Great effort went into the code to handle the two positions not being the same.

Not great enough. The community has spent nearly a month performing tests to identify and locate the cause of this issue. Let me be absolutely clear why this sucks for a very very large number of klipper users out there, here's a very concrete example that should help your understanding:

64 microsteps, 1.8 degree steppers, 4mm rotation distance. That's a 100us steprate, 0.0003125mm per step. This consistently (it's chance based) produces 1 microstep of drift, because the steps generated within the the oversampling window ends up being added twice to the toolhead position. In a 15 x 15 bed mesh with 3 probe samples that's ~0.21mm of drift through the mesh. That's unusable.

This is proven, it's indisputable, it happens, you'll see it with the logging patch i've posted in my issue. Denying with no attempt at reproduction serves no purpose, it's just wasting everyone's time. This has already traveled across reddit and multiple discord servers and people are seeing flat first layers for the first time by just reducing their sample count and minimizing their step rate.

Look here: https://www.reddit.com/r/3Dprinting/comments/1g4643g/huge_bed_levelling_bug_discovered_for_klipper/?sort=top Or here: https://discord.com/channels/167661427862142976/167661427862142976/1295690398219501589 (you'll have to scroll a bit to get past the outrage of how this report has been treated) Or here: https://discord.com/channels/460117602945990666/460172848565190667/1296224904357613630 Or here: https://discord.com/channels/829828765512106054/829828766125522957/1295658226045419561

Here's a couple of them

This is not correct. The halt_position and trigger_position can, will, and should differ even on single mcu homing.

Yes it is. You're assuming that isn't already accounted for in stepper.get_mcu_position().

In the log snippets that you provided, I do not know what you are reporting is incorrect. It is true that the "trigger at" positions do not match the "halt at" positions, but this is expected and intentional.

Tell me exactly what you're expecting to cause a discrepancy here in single-mcu homing, other than steps generated during the endstop oversampling window.

Please provide a full klipper log showing the event. If you have to add log messages, then fine, but otherwise use unmodified pristine klipper code. Separate from that full log, please provide a snippet of the log that provides unexpected results and provide the values that you did expect it to report.

Please take the time to reproduce the issue. What is it gonna cost me to get you to spend the time to attempt a reproduction?

Probe move: trigger at {'stepper_z': -11527, 'stepper_z1': -11527, 'stepper_z2': -11527} -> halt at {'stepper_z': -11528, 'stepper_z1': -11528, 'stepper_z2': -11528}
Setting toolhead position to [149.09985573809195, 330.5031249993051, -2.802499999975006, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.802187
Stats 441.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=881207 bytes_read=235150 bytes_retransmit=9 bytes_invalid=0 send_seq=18808 receive_seq=18808 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000557 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2663 bytes_read=10206 bytes_retransmit=0 bytes_invalid=0 send_seq=415 receive_seq=415 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999538 adj=49999615 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6384 bytes_read=42612 bytes_retransmit=9 bytes_invalid=0 send_seq=711 receive_seq=711 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999733 adj=63999659 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3606 bytes_read=38205 bytes_retransmit=9 bytes_invalid=0 send_seq=479 receive_seq=479 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999757 adj=63999637 Octopus_V1.1_F446: temp=30.0 EBB42_v1.2_T0: temp=27.3 EBB42_v1.2_T1: temp=29.2 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9259 bytes_read=120085 bytes_retransmit=0 bytes_invalid=0 send_seq=953 receive_seq=953 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999658 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.595 memavail=415916 print_time=303.225 buffer_time=0.000 print_stall=0 extruder: target=0 temp=25.0 pwm=0.000 extruder1: target=0 temp=25.4 pwm=0.000
Stats 442.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=882201 bytes_read=235978 bytes_retransmit=9 bytes_invalid=0 send_seq=18855 receive_seq=18855 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000545 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2669 bytes_read=10222 bytes_retransmit=0 bytes_invalid=0 send_seq=416 receive_seq=416 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999540 adj=49999621 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6390 bytes_read=42712 bytes_retransmit=9 bytes_invalid=0 send_seq=712 receive_seq=712 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999732 adj=63999671 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3612 bytes_read=38305 bytes_retransmit=9 bytes_invalid=0 send_seq=480 receive_seq=480 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999757 adj=63999640 Octopus_V1.1_F446: temp=30.0 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=35.5  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9265 bytes_read=120441 bytes_retransmit=0 bytes_invalid=0 send_seq=954 receive_seq=954 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999652 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.647 memavail=415916 print_time=304.225 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.7 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9583, 'stepper_z1': -9583, 'stepper_z2': -9583} -> halt at {'stepper_z': -9584, 'stepper_z1': -9584, 'stepper_z2': -9584}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7971874999752924, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.796875
Probe samples exceed tolerance. Retrying...
Stats 443.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=883590 bytes_read=236868 bytes_retransmit=9 bytes_invalid=0 send_seq=18908 receive_seq=18908 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000535 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2675 bytes_read=10238 bytes_retransmit=0 bytes_invalid=0 send_seq=417 receive_seq=417 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999542 adj=49999659 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6396 bytes_read=42840 bytes_retransmit=9 bytes_invalid=0 send_seq=713 receive_seq=713 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999732 adj=63999699 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3618 bytes_read=38433 bytes_retransmit=9 bytes_invalid=0 send_seq=481 receive_seq=481 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999755 adj=63999668 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=36.5  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9271 bytes_read=120797 bytes_retransmit=0 bytes_invalid=0 send_seq=955 receive_seq=955 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999668 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.709 memavail=415916 print_time=305.232 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.9 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596} -> halt at {'stepper_z': -9597, 'stepper_z1': -9597, 'stepper_z2': -9597}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7959374999755737, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.795625
Stats 445.0: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=884897 bytes_read=237810 bytes_retransmit=9 bytes_invalid=0 send_seq=18963 receive_seq=18963 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=53 upcoming_bytes=0 freq=180000531 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2681 bytes_read=10254 bytes_retransmit=0 bytes_invalid=0 send_seq=418 receive_seq=418 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999545 adj=49999694 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6402 bytes_read=42940 bytes_retransmit=9 bytes_invalid=0 send_seq=714 receive_seq=714 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999734 adj=63999723 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3624 bytes_read=38533 bytes_retransmit=9 bytes_invalid=0 send_seq=482 receive_seq=482 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999755 adj=63999680 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.2 EBB42_v1.2_T1: temp=29.5 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9277 bytes_read=121153 bytes_retransmit=0 bytes_invalid=0 send_seq=956 receive_seq=956 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999699 adj=31999678 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.806 memavail=415916 print_time=306.458 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.2 pwm=0.000
Stats 446.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=885801 bytes_read=238576 bytes_retransmit=9 bytes_invalid=0 send_seq=19003 receive_seq=19003 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000536 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2687 bytes_read=10283 bytes_retransmit=0 bytes_invalid=0 send_seq=419 receive_seq=419 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999551 adj=49999736 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6408 bytes_read=43040 bytes_retransmit=9 bytes_invalid=0 send_seq=715 receive_seq=715 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999751 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3630 bytes_read=38633 bytes_retransmit=9 bytes_invalid=0 send_seq=483 receive_seq=483 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999759 adj=63999696 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.2 EBB42_v1.2_T1: temp=29.5 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9283 bytes_read=121509 bytes_retransmit=0 bytes_invalid=0 send_seq=957 receive_seq=957 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999679 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.7 sysload=0.12 cputime=47.916 memavail=415176 print_time=307.258 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.7 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9591, 'stepper_z1': -9591, 'stepper_z2': -9591} -> halt at {'stepper_z': -9592, 'stepper_z1': -9592, 'stepper_z2': -9592}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7931249999758547, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.792812
Stats 447.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=886992 bytes_read=239418 bytes_retransmit=9 bytes_invalid=0 send_seq=19052 receive_seq=19052 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000540 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2693 bytes_read=10299 bytes_retransmit=0 bytes_invalid=0 send_seq=420 receive_seq=420 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999557 adj=49999775 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6414 bytes_read=43182 bytes_retransmit=9 bytes_invalid=0 send_seq=716 receive_seq=716 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999744 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3636 bytes_read=38775 bytes_retransmit=9 bytes_invalid=0 send_seq=484 receive_seq=484 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999759 adj=63999718 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.6 raspberry_pi: temp=36.5  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9289 bytes_read=121865 bytes_retransmit=0 bytes_invalid=0 send_seq=958 receive_seq=958 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999701 adj=31999679 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.047 memavail=415176 print_time=308.237 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.4 pwm=0.000
Stats 448.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=887976 bytes_read=240220 bytes_retransmit=9 bytes_invalid=0 send_seq=19097 receive_seq=19097 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000536 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2699 bytes_read=10315 bytes_retransmit=0 bytes_invalid=0 send_seq=421 receive_seq=421 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999562 adj=49999829 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6420 bytes_read=43282 bytes_retransmit=9 bytes_invalid=0 send_seq=717 receive_seq=717 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999734 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3642 bytes_read=38875 bytes_retransmit=9 bytes_invalid=0 send_seq=485 receive_seq=485 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999761 adj=63999705 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=35.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9295 bytes_read=122221 bytes_retransmit=0 bytes_invalid=0 send_seq=959 receive_seq=959 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999701 adj=31999677 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.165 memavail=415192 print_time=309.237 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.6 pwm=0.000 extruder1: target=0 temp=25.1 pwm=0.000
Probe move: trigger at {'stepper_z': -9595, 'stepper_z1': -9595, 'stepper_z2': -9595} -> halt at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.791562499976133, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.791250
Stats 449.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=889257 bytes_read=241083 bytes_retransmit=9 bytes_invalid=0 send_seq=19146 receive_seq=19146 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000533 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2705 bytes_read=10331 bytes_retransmit=0 bytes_invalid=0 send_seq=422 receive_seq=422 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999568 adj=49999917 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6426 bytes_read=43382 bytes_retransmit=9 bytes_invalid=0 send_seq=718 receive_seq=718 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999736 adj=63999751 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3648 bytes_read=38975 bytes_retransmit=9 bytes_invalid=0 send_seq=486 receive_seq=486 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999760 adj=63999741 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.3 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9301 bytes_read=122577 bytes_retransmit=0 bytes_invalid=0 send_seq=960 receive_seq=960 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999702 adj=31999696 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.298 memavail=415192 print_time=310.263 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9595, 'stepper_z1': -9595, 'stepper_z2': -9595} -> halt at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7899999999764096, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.789687

As explained in the issue, we accumulated 300 microns of drift this way, towards the nozzle, against gravity.

It is my expectation that providing a full log takes under 10 minutes. I've spent several hours reviewing code and running tests. Everything I've done so far on my printers produces the results that I expect. I can't continue spending time searching for something when I do not understanding what I'm looking for.

Similarly it should take you under 10 minutes to reproduce this issue. I and several other devs have spent several weeks researching this bug and running tests. Everything i've done so far on multiple peoples printers produces the results i did not expect. I can't continue running klipper when severe fundamental function impeding bugs are not taken seriously or given the time of day.

I do not understand what the underlying issue being reported is.

From the issue cited above:

Expected Behavior Trigger and halt positions should align without a consistent shift during probing operations. Unsure about multi-mcu setups, but the issue would be present there as well.

This is not a valid expectation. The halt_position and trigger_position will not always be the same. Great effort went into the code to handle the two positions not being the same. The code needs to handle these differences to get the correct results. Handling these two positions correctly is at the heart of multi-mcu homing.

On single-mcu homing, there should not be any difference between trigger and halt.

This is not correct. The halt_position and trigger_position can, will, and should differ even on single mcu homing.

The information you need is not present in a vanilla log, i posted the relevant pieces from the logging i added.

In the log snippets that you provided, I do not know what you are reporting is incorrect. It is true that the "trigger at" positions do not match the "halt at" positions, but this is expected and intentional.

Please provide a full klipper log showing the event. If you have to add log messages, then fine, but otherwise use unmodified pristine klipper code. Separate from that full log, please provide a snippet of the log that provides unexpected results and provide the values that you did expect it to report.

It is my expectation that providing a full log takes under 10 minutes. I've spent several hours reviewing code and running tests. Everything I've done so far on my printers produces the results that I expect. I can't continue spending time searching for something when I do not understanding what I'm looking for.

-Kevin

I have an example on what is happening. I had unklicky on my printer, and my back left corner was consistently off, I cant send a log for that one but I can send a picture of an engraved buildplate. Now I thought it was a hardware issue, like a twisted y axis or something But then I switched to beacon, which also has a y-offset so it should be affected by the exact same twist, I did not change any other hardware. And what do you think, the issue was gone, I didnt change anything reagarding kinematics, so if there was a twist, it is still there (y-offset for klicky: 25.00, y-offset for beacon: 18.50, both are on custom mounts and as close to the nozzle as possible so reduce the effect of a possible twist as much as possible, I also spent a lot of time making sure my frame is as square as possible to rule out any hardware issue) Also please ignore any sentiment you have towards any probes, I'm using those as a real world example since I noticed this behaviour and beacon does not use the probing code from klipper and there is no z-movement, so it should not be afected by the issue, which would confirm the issue

Also it was not a klicky issue, the klicky was extremely consistent, I could get it to a range of under 0.007 reliably But I am running 256 microsteps on z and a lot of points in the bed mesh All of this weird behaviour is completely explained with this bug report whether you want to hear it or not!

@Arksine confirmed:

Step check:

Probe move: trigger at {'stepper_z': -9598, 'stepper_z1': -9598, 'stepper_z2': -9598} -> halt at {'stepper_z': -9598, 'stepper_z1': -9598, 'stepper_z2': -9598}
Probe move: trigger at {'stepper_z': -9600, 'stepper_z1': -9600, 'stepper_z2': -9600} -> halt at {'stepper_z': -9600, 'stepper_z1': -9600, 'stepper_z2': -9600}
Probe move: trigger at {'stepper_z': -9602, 'stepper_z1': -9602, 'stepper_z2': -9602} -> halt at {'stepper_z': -9602, 'stepper_z1': -9602, 'stepper_z2': -9602}
Probe move: trigger at {'stepper_z': -9599, 'stepper_z1': -9599, 'stepper_z2': -9599} -> halt at {'stepper_z': -9599, 'stepper_z1': -9599, 'stepper_z2': -9599}
Probe move: trigger at {'stepper_z': -9608, 'stepper_z1': -9608, 'stepper_z2': -9608} -> halt at {'stepper_z': -9608, 'stepper_z1': -9608, 'stepper_z2': -9608}
Probe move: trigger at {'stepper_z': -9614, 'stepper_z1': -9614, 'stepper_z2': -9614} -> halt at {'stepper_z': -9614, 'stepper_z1': -9614, 'stepper_z2': -9614}
Probe move: trigger at {'stepper_z': -9588, 'stepper_z1': -9588, 'stepper_z2': -9588} -> halt at {'stepper_z': -9588, 'stepper_z1': -9588, 'stepper_z2': -9588}
Probe move: trigger at {'stepper_z': -9597, 'stepper_z1': -9597, 'stepper_z2': -9597} -> halt at {'stepper_z': -9597, 'stepper_z1': -9597, 'stepper_z2': -9597}
Probe move: trigger at {'stepper_z': -9604, 'stepper_z1': -9604, 'stepper_z2': -9604} -> halt at {'stepper_z': -9604, 'stepper_z1': -9604, 'stepper_z2': -9604}

Z position:

Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7828124999774584, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7828124999777275, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7834374999779965, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7831249999782663, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7846874999753144, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7890624999755853, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.78531249997586, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.7843749999761314, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])
Setting toolhead position to [149.34077585040984, 330.14558375978254, -2.785624999976402, 0.0] (was: [149.34077585040984, 330.14558375978254, -7.0, 0.0])

I'm attempting to get Rat Rig HQ to gather 200 samples before and after the fix.

Unfortunately, this doesn't seem to make much if any difference for me. I suppose I could try using a Beacon but, I'm not hopeful that would work either.

On Oct 16, 2024, at 7:56 PM, Mikkel Schmidt @.***> wrote:

[stepper_z] microsteps: 16 [tmc2209 stepper_z] interpolate: True

[stepper_z1] microsteps: 16 [tmc2209 stepper_z1] interpolate: True

[stepper_z2] microsteps: 16 [tmc2209 stepper_z2] interpolate: True You can further reduce the risk of drift by lowering your probe speed, and finally you can reduce the amount of drift accumulated by lowering you probe samples.

[probe] samples: 1 speed: 3

Unfortunately, this doesn't seem to make much if any difference for me. I suppose I could try using a Beacon but, I'm not hopeful that would work either.

Beacon would (and does) work great as it doesn't change the Z height for the scan.

3 days so far, on a PR that fixes a big problem, yet there seems to be no interest in understanding the issue, or fixing it, when can this be expected to be actually validated and properly reviewed?

Quite a bit of work has gone into trying to reproduce a problem without success. We need more information to figure out the underlying problem. See https://klipper.discourse.group/t/bug-accumulating-microstep-shift-during-probe-moves-related-to-endstop-oversampling/19429/3 .

Separately, it is important to me that all messages on the Klipper forums have an upbeat tone, be cordial, and give the benefit of the doubt that all collaborators are trying their best to improve the software. Some of the messages in this thread have not met that expectation. Please keep all messages polite and on-topic. I understand there is some frustration, but expressing that frustration here will not help get this issue solved.

-Kevin

Thanks for the feedback on this PR. It appears that we may be closing in identifying on the issue, however as Kevin stated more testing and data is necessary. Initially I was operating under the assumption that the trigger time should match the time of the "trigger sync" event. After reading Kevin's response and further discussion I concur with his logic. The trigger time (and therefore the trigger position) should be when the endstop event is first observed, and oversampling should be excluded.

To better understand the drift issue I took another look Mikkel's data:

Probe move: trigger at {'stepper_z': -11527, 'stepper_z1': -11527, 'stepper_z2': -11527} -> halt at {'stepper_z': -11528, 'stepper_z1': -11528, 'stepper_z2': -11528}
Setting toolhead position to [149.09985573809195, 330.5031249993051, -2.802499999975006, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.802187
Stats 441.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=881207 bytes_read=235150 bytes_retransmit=9 bytes_invalid=0 send_seq=18808 receive_seq=18808 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000557 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2663 bytes_read=10206 bytes_retransmit=0 bytes_invalid=0 send_seq=415 receive_seq=415 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999538 adj=49999615 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6384 bytes_read=42612 bytes_retransmit=9 bytes_invalid=0 send_seq=711 receive_seq=711 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999733 adj=63999659 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3606 bytes_read=38205 bytes_retransmit=9 bytes_invalid=0 send_seq=479 receive_seq=479 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999757 adj=63999637 Octopus_V1.1_F446: temp=30.0 EBB42_v1.2_T0: temp=27.3 EBB42_v1.2_T1: temp=29.2 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9259 bytes_read=120085 bytes_retransmit=0 bytes_invalid=0 send_seq=953 receive_seq=953 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999658 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.595 memavail=415916 print_time=303.225 buffer_time=0.000 print_stall=0 extruder: target=0 temp=25.0 pwm=0.000 extruder1: target=0 temp=25.4 pwm=0.000
Stats 442.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=882201 bytes_read=235978 bytes_retransmit=9 bytes_invalid=0 send_seq=18855 receive_seq=18855 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000545 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2669 bytes_read=10222 bytes_retransmit=0 bytes_invalid=0 send_seq=416 receive_seq=416 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999540 adj=49999621 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6390 bytes_read=42712 bytes_retransmit=9 bytes_invalid=0 send_seq=712 receive_seq=712 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999732 adj=63999671 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3612 bytes_read=38305 bytes_retransmit=9 bytes_invalid=0 send_seq=480 receive_seq=480 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999757 adj=63999640 Octopus_V1.1_F446: temp=30.0 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=35.5  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9265 bytes_read=120441 bytes_retransmit=0 bytes_invalid=0 send_seq=954 receive_seq=954 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999652 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.647 memavail=415916 print_time=304.225 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.7 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9583, 'stepper_z1': -9583, 'stepper_z2': -9583} -> halt at {'stepper_z': -9584, 'stepper_z1': -9584, 'stepper_z2': -9584}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7971874999752924, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.796875
Probe samples exceed tolerance. Retrying...
Stats 443.9: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=883590 bytes_read=236868 bytes_retransmit=9 bytes_invalid=0 send_seq=18908 receive_seq=18908 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000535 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2675 bytes_read=10238 bytes_retransmit=0 bytes_invalid=0 send_seq=417 receive_seq=417 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999542 adj=49999659 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6396 bytes_read=42840 bytes_retransmit=9 bytes_invalid=0 send_seq=713 receive_seq=713 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999732 adj=63999699 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3618 bytes_read=38433 bytes_retransmit=9 bytes_invalid=0 send_seq=481 receive_seq=481 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999755 adj=63999668 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=36.5  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9271 bytes_read=120797 bytes_retransmit=0 bytes_invalid=0 send_seq=955 receive_seq=955 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999668 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.709 memavail=415916 print_time=305.232 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.9 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596} -> halt at {'stepper_z': -9597, 'stepper_z1': -9597, 'stepper_z2': -9597}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7959374999755737, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.795625
Stats 445.0: gcodein=0  mcu: mcu_awake=0.003 mcu_task_avg=0.000007 mcu_task_stddev=0.000004 bytes_write=884897 bytes_read=237810 bytes_retransmit=9 bytes_invalid=0 send_seq=18963 receive_seq=18963 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=53 upcoming_bytes=0 freq=180000531 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000021 bytes_write=2681 bytes_read=10254 bytes_retransmit=0 bytes_invalid=0 send_seq=418 receive_seq=418 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999545 adj=49999694 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6402 bytes_read=42940 bytes_retransmit=9 bytes_invalid=0 send_seq=714 receive_seq=714 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999734 adj=63999723 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3624 bytes_read=38533 bytes_retransmit=9 bytes_invalid=0 send_seq=482 receive_seq=482 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999755 adj=63999680 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.2 EBB42_v1.2_T1: temp=29.5 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9277 bytes_read=121153 bytes_retransmit=0 bytes_invalid=0 send_seq=956 receive_seq=956 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999699 adj=31999678 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.8 sysload=0.13 cputime=47.806 memavail=415916 print_time=306.458 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.2 pwm=0.000
Stats 446.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=885801 bytes_read=238576 bytes_retransmit=9 bytes_invalid=0 send_seq=19003 receive_seq=19003 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000536 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2687 bytes_read=10283 bytes_retransmit=0 bytes_invalid=0 send_seq=419 receive_seq=419 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999551 adj=49999736 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6408 bytes_read=43040 bytes_retransmit=9 bytes_invalid=0 send_seq=715 receive_seq=715 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999751 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3630 bytes_read=38633 bytes_retransmit=9 bytes_invalid=0 send_seq=483 receive_seq=483 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999759 adj=63999696 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.2 EBB42_v1.2_T1: temp=29.5 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9283 bytes_read=121509 bytes_retransmit=0 bytes_invalid=0 send_seq=957 receive_seq=957 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999700 adj=31999679 coil_temp=23.9 refs=0 mcu_temp=26.38 supply_voltage=2.996 chamber: temp=23.7 sysload=0.12 cputime=47.916 memavail=415176 print_time=307.258 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.7 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9591, 'stepper_z1': -9591, 'stepper_z2': -9591} -> halt at {'stepper_z': -9592, 'stepper_z1': -9592, 'stepper_z2': -9592}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7931249999758547, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.792812
Stats 447.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=886992 bytes_read=239418 bytes_retransmit=9 bytes_invalid=0 send_seq=19052 receive_seq=19052 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000540 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2693 bytes_read=10299 bytes_retransmit=0 bytes_invalid=0 send_seq=420 receive_seq=420 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999557 adj=49999775 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6414 bytes_read=43182 bytes_retransmit=9 bytes_invalid=0 send_seq=716 receive_seq=716 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999744 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3636 bytes_read=38775 bytes_retransmit=9 bytes_invalid=0 send_seq=484 receive_seq=484 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999759 adj=63999718 Octopus_V1.1_F446: temp=29.8 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.6 raspberry_pi: temp=36.5  heater_bed: target=0 temp=23.3 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9289 bytes_read=121865 bytes_retransmit=0 bytes_invalid=0 send_seq=958 receive_seq=958 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999701 adj=31999679 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.047 memavail=415176 print_time=308.237 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.4 pwm=0.000
Stats 448.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=887976 bytes_read=240220 bytes_retransmit=9 bytes_invalid=0 send_seq=19097 receive_seq=19097 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000536 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2699 bytes_read=10315 bytes_retransmit=0 bytes_invalid=0 send_seq=421 receive_seq=421 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999562 adj=49999829 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6420 bytes_read=43282 bytes_retransmit=9 bytes_invalid=0 send_seq=717 receive_seq=717 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999735 adj=63999734 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3642 bytes_read=38875 bytes_retransmit=9 bytes_invalid=0 send_seq=485 receive_seq=485 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999761 adj=63999705 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.4 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=35.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9295 bytes_read=122221 bytes_retransmit=0 bytes_invalid=0 send_seq=959 receive_seq=959 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999701 adj=31999677 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.165 memavail=415192 print_time=309.237 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.6 pwm=0.000 extruder1: target=0 temp=25.1 pwm=0.000
Probe move: trigger at {'stepper_z': -9595, 'stepper_z1': -9595, 'stepper_z2': -9595} -> halt at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.791562499976133, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.791250
Stats 449.0: gcodein=0  mcu: mcu_awake=0.007 mcu_task_avg=0.000008 mcu_task_stddev=0.000006 bytes_write=889257 bytes_read=241083 bytes_retransmit=9 bytes_invalid=0 send_seq=19146 receive_seq=19146 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180000533 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000011 bytes_write=2705 bytes_read=10331 bytes_retransmit=0 bytes_invalid=0 send_seq=422 receive_seq=422 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=49999568 adj=49999917 toolboard_t0: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=6426 bytes_read=43382 bytes_retransmit=9 bytes_invalid=0 send_seq=718 receive_seq=718 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999736 adj=63999751 toolboard_t1: mcu_awake=0.002 mcu_task_avg=0.000014 mcu_task_stddev=0.000009 bytes_write=3648 bytes_read=38975 bytes_retransmit=9 bytes_invalid=0 send_seq=486 receive_seq=486 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=63999760 adj=63999741 Octopus_V1.1_F446: temp=29.9 EBB42_v1.2_T0: temp=27.3 EBB42_v1.2_T1: temp=29.4 raspberry_pi: temp=36.0  heater_bed: target=0 temp=23.4 pwm=0.000 beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=9301 bytes_read=122577 bytes_retransmit=0 bytes_invalid=0 send_seq=960 receive_seq=960 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999702 adj=31999696 coil_temp=23.9 refs=0 mcu_temp=26.39 supply_voltage=2.996 chamber: temp=23.8 sysload=0.12 cputime=48.298 memavail=415192 print_time=310.263 buffer_time=0.000 print_stall=0 extruder: target=0 temp=24.8 pwm=0.000 extruder1: target=0 temp=25.3 pwm=0.000
Probe move: trigger at {'stepper_z': -9595, 'stepper_z1': -9595, 'stepper_z2': -9595} -> halt at {'stepper_z': -9596, 'stepper_z1': -9596, 'stepper_z2': -9596}
Setting toolhead position to [149.09985574058396, 330.5045240575398, -2.7899999999764096, 0.0] (was: [149.09985574058396, 330.5045240575398, -7.0, 0.0])
probe at 149.100,330.505 is z=-2.789687

It appears that there is a consistent 4 - 5 steps (1.25 -1.5 microns) of drift after each sample. This is more drift than the single step deviation difference between the "trigger steps" and "halt steps" can account for. Further we can see that the trigger steps are consistently under 9600 steps, which is presumably the sample_retract_dist (3mm). This suggests potential movement error, where it takes fewer steps to descend than it does to lift. I have tried to reproduce this specific phenomena locally and thus far have been unable to do so on my machines.

That said, this patch appears to at least mitigate the issue for some users, so it could be useful to look at what the downstream impact is of the change introduced in this PR. When looking at line 354 in probe.py we can see that the probe retracts relative the position returned by the homing move:

https://github.com/Klipper3d/klipper/blob/b89d552387da9734292a182c7040c418996ca350/klippy/extras/probe.py#L340-L356

This is the "trigger position", which in the data above is 1 step higher than the "halt position". Thus the full distance retracted is sample_retract_dist + 1 step. When testing with the changes in this PR, the trigger position and halt position are the same, so the additional step is omitted. One quick way to test if this additional step is causing an issue is to remove the step from the sample_retract_dist. So for example, using Mikkel's configuration, we could do something like the following:

PROBE SAMPLES=10 SAMPLE_RETRACT_DIST=2.9996875

Since this PR isn't the correct solution to the issue, I'm going to go ahead and close it and move further discussion to the discourse thread. I intend to continue to attempt to reproduce the specific drift issue and provide further feedback there.

Klipper3d / klipper

mcu: fix endstop probing #6712