M84 bad timeout

[VanessaE]

bugfix-1.1.x, commit de5f69b2852e0e2fadd02f3c5a8d19f41ab2194e

Description

M84 does not time out the motors' idle hold properly in accordance with its S parameter, if S4 or higher (values less than 4 do time-out in a few seconds as expected, though the exact amount of time is incorrect).

I normally exploit this to turn off X/Y/E at the end of a print (leaving Z turned on, as configured) by doing:

M84 S1
G4 S2
M84 S120

This does turn off the motors after a second or so, as expected, but then if I do any X/Y/E move, the 120-second timeout does not take place, so the affected motor remains powered.

Configs: Marlin-configs-20180405.zip

[VanessaE]

Correction: idle timeout doesn't seem to work at all by default, even without using an M84 command, even if I just reset the printer (or flash the firmware), reconnect, home one axis, jog it to its max position, and walk away. To be sure I wasn't jumping the gun, I set my little desktop timer for 2 minutes.

[thinkyhead]

Give this branch a run. It will print messages in manage_inactivity if there's a sleep interval set. Either it will say there are blocks queued, so the steppers can't sleep, or it will say that it tried to put the steppers to sleep.

https://github.com/thinkyhead/Marlin/archive/bf1_misc_fixes_apr_8.zip

[VanessaE]

I don't suppose you have that available as a patch against bugfix-1.1.x? I'm kinda hesitant to switch between branches/forks of Marlin because of the need to reconfigure.

Incidentally, it turns out that idle hold DOES eventually time out, but in some measure of hours, rather than seconds.

[thinkyhead]

It is identical except for some added logging. Just use your configs with it.

[VanessaE]

Got it.

Flashed your fork (with my configs in place), connected, homed X, jogged it a couple times, leaving it at its minimum position (home is at X-max), and figuratively walked away. I did not attempt to print anything. There was the usual boot-up spew, followed by several echo:Blocks queued!ok messages generated while home/jogging. After a bit less than three hours, the motor was still held firm, and no further messages were generated.

At that point, I got impatient. :smile: Out of curiosity, I reset the printer, homed X and Y, jogged them around a bit, and moved them to their midpoints, just in case the cause was leaving one axis at its limit (hence soft endstop), which is how a print normally ends in my config, but that didn't help. Exact same behavior as above, with SENDING:G0 X100.0 Y100.0 F18000 tacked on by Pronterface after. Nothing more was printed.

Yesterday evening, I noticed idle hold had timed out on its own about an hour after printing something.

So the actual timeout interval appears to be random.

[VanessaE]

It's a good thing I didn't need to print, by the way. Turns out that doing so just spills tons of "Blocks queued" messages, without printing anything (or doing anything else beyond the initial home/level/travel actions). Or at least, as soon as I saw the flood, I stopped the print.

[thinkyhead]

followed by several echo:Blocks queued!ok messages generated while home/jogging

As expected.

It's a good thing I didn't need to print, by the way

Indeed. I just want to see what's going on. You know, set a timeout interval, do a move to see what message pops out. Wait for the set timeout interval. See if any more messages appear. I wouldn't suggest doing any more than that with it given where the logging is set.

[VanessaE]

I'll try again later today, when I'm a little more patient :wink:

[thinkyhead]

Hmm. My testing shows that the feature works. I set M18 S5, did a small move in X, and after 5 seconds the steppers were disabled.

I've added some more logging which includes the set values. If you re-download my branch and test again (G28, M18 S5, G1 X10, wait…) this time the logging will include all this info:

SERIAL_ECHO_START();
SERIAL_ECHOLNPAIR("previous_move_ms = ", previous_move_ms);
SERIAL_ECHO_START();
SERIAL_ECHOLNPAIR("ignore_stepper_queue = ", int(ignore_stepper_queue));
SERIAL_ECHO_START();
SERIAL_ECHOLNPAIR("stepper_inactive_time = ", stepper_inactive_time);
SERIAL_ECHO_START();
SERIAL_ECHOLNPAIR("timeout ms = ", previous_move_ms + stepper_inactive_time);

If any of the output looks weird on your machine, that might tell us something.

[VanessaE]

M18? I wasn't aware of that command; http://reprap.org/wiki/G-code#M18:_Disable_all_stepper_motors (the site I usually go to for gcode info) does not indicate S being a valid parameter for it.

[VanessaE]

I re-downloaded your zip (from https://github.com/MarlinFirmware/Marlin/issues/10315#issuecomment-379534028) just now, extracted, added my configs, but couldn't compile it:

sketch/Marlin_main.cpp: In function 'float run_z_probe()':
Marlin_main.cpp:2249: error: 'Z_PROBE_LOW_POINT' was not declared in this scope
     const float z_probe_low_point = axis_known_position[Z_AXIS] ? -zprobe_zoffset + Z_PROBE_LOW_POINT : -10.0;
                                                                                     ^
exit status 1
'Z_PROBE_LOW_POINT' was not declared in this scope

[thinkyhead]

M18 and M84 are synonyms in Marlin. See http://marlinfw.org/docs/gcode/M018.html. I will update the RapRap wiki to bring it up to date.

You'll need to add Z_PROBE_LOW_POINT to your configuration to bring it up to date for 1.1.9. See the example configurations for its usage.

[VanessaE]

Ah, that's useful indeed. At least now I don't have to exploit M84 S + G4 to turn off X/Y/E.

After flashing, I connected and homed all, and....well... I've been waiting over 48 hours for idle hold to time out. Can you think of something I can do to ... irritate it? :smile:

[thinkyhead]

If you could run the branch from https://github.com/thinkyhead/Marlin/archive/bf1_misc_fixes_apr_8.zip and post the log output after...

G28    ; Home
M84 S5 ; Timeout after 5 seconds
G1 X10 ; Move X to set previous_move_ms

…and a wait of 5 seconds, that should provide us with the needed data regarding the variables noted above. If you don't see the message "Disabling steppers..." after 5 seconds it means the code is failing to detect the timeout.

[VanessaE]

Nope, "Disabling..." does not appear as expected. Here's the last of the debug spew:

echo:ignore_stepper_queue = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 32801
echo:previous_move_ms = 27811
echo:ignore_stepper_queue = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 32811
echo:previous_move_ms = 27822
echo:ignore_stepper_queue = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 32822
echo:previous_move_ms = 27832
echo:ignore_stepper_queue = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 32832

[thinkyhead]

Thanks for the log. It shows that the ms timeout is being set to 5000 after the last move. For example, when a move is done at 27832 the timeout tick is being set to 27832 + 5000 = 32832. Since the "Disabling…" message doesn't appear, one of the other conditions is preventing it. Sorry to keep dragging this out, but I'll want to add a little more logging that examines other possible causes. On the positive side, this is narrowing it down, so we'll surely find the exact cause soon.

[VanessaE]

No worries, just let me know.

[thinkyhead]

Added logging of the other conditions to https://github.com/thinkyhead/Marlin/archive/bf1_misc_fixes_apr_8.zip. As before…

G28    ; Home
M84 S5 ; Timeout after 5 seconds
G1 X10 ; Move X to set previous_move_ms

[VanessaE]

Noperz. :smiley:

Here's the last of the debug:

echo:previous_move_ms = 9188
echo:no_stepper_sleep = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 14188
echo:MOVE_AWAY_TEST = 1
echo:no_stepper_sleep = 0
echo:previous_move_ms = 9202
echo:no_stepper_sleep = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 14202
echo:MOVE_AWAY_TEST = 1
echo:no_stepper_sleep = 0
echo:previous_move_ms = 9217
echo:no_stepper_sleep = 0
echo:stepper_inactive_time = 5000
echo:timeout ms = 14217
echo:MOVE_AWAY_TEST = 1
echo:no_stepper_sleep = 0

[thinkyhead]

Well, I'm at a loss to explain it! All the conditions are in place for the steppers to sleep. The fact that you don't see "Disabling steppers..." at all goes against those values. Given that this simple code works fine in general, it's a complete conundrum.

Substituting your reported values gives us this…

void manage_inactivity(const bool ignore_stepper_queue/*=false*/) {
  . . .
  const millis_t ms = millis();
  . . .
  if (5000) {
    if (planner.has_blocks_queued())
      previous_move_ms = ms; // reset_stepper_timeout to keep steppers powered
    else if (true && !false && ELAPSED(ms, 9217 + 5000)) {
      // "Disable steppers..."
      . . .
    }
  }

[VanessaE]

Yeah, it's got me confused too, but recall that low S values DO work, sorta. I re-checked: M84 S1 times out in about 1 second, while S2 takes about 3 seconds, and S3 takes about 5 seconds. Values of 4 or greater need somewhere north of one minute -- I didn't bother to time it past that point.

[thinkyhead]

It sounds like something is messing with the timer used for millis. If you do a G4 S5 does it pause for 5 seconds, or is it longer?

[VanessaE]

It pauses for about 5 seconds -- tested by issuing that command mid-print.

[VanessaE]

I pulled up 1.1.6 to test something. I was right -- the automatic idle timeout (which is still broken in bugfix-2.0.x, at least as of commit 2ba198a6) works properly in that version; the default of 2 minutes is just about that, and M84 S10 times out in 10 seconds, as expected.

[thinkyhead]

Since I can't reproduce the error, I'm not sure how to go about debugging it. It's hard to know if you've solved something when it goes from "hey, it works" to "hey, it still works." But I'll compare 1.1.6 to the latest to see what differs.

[thinkyhead]

I think it's probably because when connected to a host the M105 command is resetting the timeout. Try removing this line in gcode.cpp…

void GcodeSuite::process_next_command() {
  char * const current_command = command_queue[cmd_queue_index_r];

  if (DEBUGGING(ECHO)) {
    SERIAL_ECHO_START();
    SERIAL_ECHOLN(current_command);
    #if ENABLED(M100_FREE_MEMORY_WATCHER)
      SERIAL_ECHOPAIR("slot:", cmd_queue_index_r);
      M100_dump_routine("   Command Queue:", (const char*)command_queue, (const char*)(command_queue + sizeof(command_queue)));
    #endif
  }

- reset_stepper_timeout(); // Keep steppers powered

  // Parse the next command in the queue
  parser.parse(current_command);
  process_parsed_command();
}

[VanessaE]

I guess it must have worked, because you already changed it in e366d55bc2ea9471397c1f414128de5e8171e660 before I could try it. :wink:

In any case, I'm at 48a15d1c now, and the timeout seems to be fine.

(Sorry it took so long to get back to this)

[thinkyhead]

I guess it must have worked

It was obvious once I spotted the error.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.