Fix print hang with LA

[tombrazier]

Description

#25541 causes the MCU to hang and then reboot when using LA. This is reported on 32 bit MCUs and so cannot be caused by the changes to the AVR calc_timer_interval() code. The only other change was to bit shift the parameter to calc_timer_interval() rather than bit shift the result. This must now be causing a division by zero in some cases.

Since the change to the bit shift was only there for high speed edge cases with an AVR and only to increase the accuracy of the LA step timer interval, it can be reverted.

[Edit: But a better change would be to handle the division by zero which is only ever going to happen when the LA ISR interval is supposed to be greater than 1 second, which is an undesirable edge case that block E stepper movement. If calc_timer_interval() returns HAL_TIMER_TYPE_MAX (i.e. LA_ADV_NEVER) then as soon as a more reasonable ISR rate is generated, it will be applied.]

Related Issues

#25553

[thisiskeithb]

I’ll add those debug statements mentioned in #25553 (comment) & get them tested today to find out which call is causing the crash since it’s not a divide by zero bug.

Edit: It's this one:

Marlin/Marlin/src/module/stepper.cpp

Line 2387 in 28666f2

la_interval = calc_timer_interval(current_block->nominal_rate >> current_block->la_scaling);

Updated stepper.cpp: stepper.cpp.zip

And the updated diff:

diff --git a/Marlin/src/module/stepper.cpp b/Marlin/src/module/stepper.cpp
index 5c0034a..70f2f64 100644
--- a/Marlin/src/module/stepper.cpp
+++ b/Marlin/src/module/stepper.cpp
@@ -2254,7 +2254,17 @@ hal_timer_t Stepper::block_phase_isr() {
         #if ENABLED(LIN_ADVANCE)
           if (la_active) {
             const uint32_t la_step_rate = la_advance_steps < current_block->max_adv_steps ? current_block->la_advance_rate : 0;
+            SERIAL_EOL();
+            SERIAL_ECHO("Call 1 Start");
+            SERIAL_EOL();
             la_interval = calc_timer_interval((acc_step_rate + la_step_rate) >> current_block->la_scaling);
+            SERIAL_ECHOLNPGM("la_interval: ", la_interval);
+            SERIAL_ECHOLNPGM("step_rate: ", (acc_step_rate + la_step_rate) >> current_block->la_scaling);
+            SERIAL_ECHOLNPGM("asr: ", acc_step_rate);
+            SERIAL_ECHOLNPGM("lsr: ", la_step_rate);
+            SERIAL_ECHOLNPGM("las: ", current_block->la_scaling);
+            SERIAL_ECHO("Call 1 End");
+            SERIAL_EOL();
           }
         #endif
 
@@ -2326,7 +2336,17 @@ hal_timer_t Stepper::block_phase_isr() {
             const uint32_t la_step_rate = la_advance_steps > current_block->final_adv_steps ? current_block->la_advance_rate : 0;
             if (la_step_rate != step_rate) {
               bool reverse_e = la_step_rate > step_rate;
+              SERIAL_EOL();
+              SERIAL_ECHO("Call 2 Start");
+              SERIAL_EOL();
               la_interval = calc_timer_interval((reverse_e ? la_step_rate - step_rate : step_rate - la_step_rate) >> current_block->la_scaling);
+              SERIAL_ECHOLNPGM("la_interval: ", la_interval);
+              //SERIAL_ECHOLNPGM("step_rate: ", (acc_step_rate + la_step_rate) >> current_block->la_scaling);
+              //SERIAL_ECHOLNPGM("asr: ", acc_step_rate);
+              SERIAL_ECHOLNPGM("lsr: ", la_step_rate);
+              SERIAL_ECHOLNPGM("las: ", current_block->la_scaling);
+              SERIAL_ECHO("Call  2 End");
+              SERIAL_EOL();
 
               if (reverse_e != motor_direction(E_AXIS)) {
                 TBI(last_direction_bits, E_AXIS);
@@ -2384,7 +2404,17 @@ hal_timer_t Stepper::block_phase_isr() {
 
           #if ENABLED(LIN_ADVANCE)
             if (la_active)
+              SERIAL_EOL();
+              SERIAL_ECHO("Call 3 Start");
+              SERIAL_EOL();
               la_interval = calc_timer_interval(current_block->nominal_rate >> current_block->la_scaling);
+              SERIAL_ECHOLNPGM("la_interval: ", la_interval);
+              //SERIAL_ECHOLNPGM("step_rate: ", (acc_step_rate + la_step_rate) >> current_block->la_scaling);
+              //SERIAL_ECHOLNPGM("asr: ", acc_step_rate);
+              //SERIAL_ECHOLNPGM("lsr: ", la_step_rate);
+              SERIAL_ECHOLNPGM("las: ", current_block->la_scaling);
+              SERIAL_ECHO("Call 3 End");
+              SERIAL_EOL();
           #endif
         }
 
@@ -2706,7 +2736,17 @@ hal_timer_t Stepper::block_phase_isr() {
       #if ENABLED(LIN_ADVANCE)
         if (la_active) {
           const uint32_t la_step_rate = la_advance_steps < current_block->max_adv_steps ? current_block->la_advance_rate : 0;
+          SERIAL_EOL();
+          SERIAL_ECHO("Call 4 Start");
+          SERIAL_EOL();
           la_interval = calc_timer_interval((current_block->initial_rate + la_step_rate) >> current_block->la_scaling);
+          SERIAL_ECHOLNPGM("la_interval: ", la_interval);
+          //SERIAL_ECHOLNPGM("step_rate: ", (acc_step_rate + la_step_rate) >> current_block->la_scaling);
+          //SERIAL_ECHOLNPGM("asr: ", acc_step_rate);
+          SERIAL_ECHOLNPGM("lsr: ", la_step_rate);
+          SERIAL_ECHOLNPGM("las: ", current_block->la_scaling);
+          SERIAL_ECHO("Call 4 End");
+          SERIAL_EOL();
         }
       #endif
     }

la_interval was 571 when it failed. Here's some of the log I have before it rebooted (right after the purge line / after the move to the center of the bed):

log output:

Recv: Call 3 Start
Recv: la_interval: 209
Recv: las: 0
Recv: Call 3 End
Recv: ok
Send: N50 G1 X150.372 Y131.346 E.09582*97
Recv: ok
Send: N51 G1 X148.024 Y133.735 E.12833*102
Recv: Call 3 Start
Recv: la_interval: 571
Recv: las: 0
Recv: Call 3 End
[...]
Recv: 
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
[...]
Unexpected error while reading serial port, please consult octoprint.log for details: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:3997

[thinkyhead]

What is the effect of returning HAL_TIMER_TYPE_MAX? Apparently "never"…?

Of course, the very fastest that the Stepper ISR can run is set by STEPPER_TIMER_RATE (typically F_CPU / 8) so I don't know whether returning STEPPER_TIMER_RATE would produce more "realistic" results for the multi-stepping calculation that follows.

[thinkyhead]

la_interval was 571 when it failed. Here's some of the log I have before it rebooted (right after the purge line / after the move to the center of the bed):

Possibly the crash was caused by the serial print itself, so it would be best to test without those in the ISR. Values can instead be copied to a global and printed periodically in the main loop.

[tombrazier]

What is the effect of returning HAL_TIMER_TYPE_MAX? Apparently "never"…?

Yes, it means "never" but it also means "keep checking back in case la_interval has changed". See where nextAdvanceISR is set in Stepper::isr(). In thinking about all this I realise there is bug if step rates are momentarily really low, as they can be around the point the E stepper reverses during deceleration. In that case nextAdvanceISR may not get updated again for a long time even after step rates have increased dramatically.

Possibly the crash was caused by the serial print itself

I think this has been happening quite a lot which has confused tracking down the bug quite significantly. On AVR I have found that serial output from the stepper ISR works very well. But I guess different HALs handle serial differently.

[RV-from-be]

@tombrazier
I've been following this problem with interest which I also saw with my Creality v422 and v427 motherboards by enabling the L.A. I'm sorry this PR doesn't fix it. Printing always stops almost immediately. On the other hand, going back to this commit ee04743 and adding this PR, printing continues normally!

[tombrazier]

@RV-from-be I think there may be two issues. See here. Interestingly @ThomasToka also has a Creality mainboard that does not respond to this PR. Could you post the config and gcode you are using on your 4.2.7 board? I have one here so should be able to replicate it.

[ThomasToka]

Should i now add a120dfe

after i added the commit 241c062 and check again?

[RV-from-be]

@ThomasToka @tombrazier
I tested first with the PR 241c062 and this commit a120dfe without Input Shaping but LA activated > Printing always stops almost immediately (when printing the letters of the first layer of a benchy!).

Then I redid the test with the PR 241c062, and this commit ee04743 -> printing continuesd normally!

(UI -> Marlinui for E3V2)

[ThomasToka]

included this

// A fast processor can just do integer division
    return step_rate ? uint32_t(STEPPER_TIMER_RATE) / step_rate : HAL_TIMER_TYPE_MAX;

and now it works with the rest included also.

[RV-from-be]

included this

// A fast processor can just do integer division
    return step_rate ? uint32_t(STEPPER_TIMER_RATE) / step_rate : HAL_TIMER_TYPE_MAX;

and now it works with the rest included also.

@ThomasToka
What do you mean by: now it works with the rest included also? With this commit included ee04743?

[ThomasToka]

my print did not stop anymore after adding the mentioned line to the pr. am not on my desk now..

[ThomasToka]

ok users report some freezes frequently. cant deliver logs but the fact that it seems not to be all fixed.

can you guys say something what to revert to be safe?

[thisiskeithb]

@ThomasToka & @RV-from-be: It's not clear if you are testing with the latest code / have properly applied all patches.

Since this PR has been merged, please download bugfix-2.1.x to test with the latest code and let us know if you're still having this issue. Note: Other than applying your configurations, no other patches/code modification is required.

If you are still experiencing crashes, please leave a comment in #25553 and be sure to attach a ZIP file containing your Configuration.h, Configuration_adv.h, and G-code.