Marlin: Painfully slow homing.

[NiklasOlofsson]

Something happened in the recent commits.
G28 takes VERY long time. The first bump against the endstops is fast, but the second one is painfully slow.
Same with BLTouch, first probe fast, second takes like one minute.
What have changed or where do I change it to go faster? Using latest 1.1.x bugfix.

Edit: While printing, it does very hard clunking sound when changing direction or when it does the seam.
Movement feels a lot "harder" compared to before. Feels alot like it's doing the clunking sound when it changes direction.

Edit 2: Fast movements are way too fast. Ruining my print.

[Kaibob2]

I was just going to open an issue about exactly this.
When i sent G28 X for example the carriage travels towards the Xmin endstop in normal speed, then bumps 5mm backwards (everything normal up to here) then it travels again towards the Xmin endstop with inanely low speed.
When it reaches the endstop the second time Marlin starts scamming the host with endstops hit: X:0.00
This is the log:

SENT: G28 X0
READ: ok T:23.01 /0 B:22.54 /0 T0:23.01 /0 T1:22.27 /0 @:0 B@:0 @0:0 @1:0
READ: ok T:23.01 /0 B:22.54 /0 T0:23.01 /0 T1:22.27 /0 @:0 B@:0 @0:0 @1:0
READ: echo:Active Extruder: 0
Active Extruder: 0
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:busy: processing
busy: processing
SENT: M105
READ: echo:Active Extruder: 0
Active Extruder: 0
READ: X:0.00 Y:0.00 Z:5.00 E:0.00 Count X:0 Y:0 Z:7996
READ: ok
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: ok T:22.89 /0 B:22.77 /0 T0:22.89 /0 T1:22.19 /0 @:0 B@:0 @0:0 @1:0
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: echo:endstops hit:  X:0.00
endstops hit:  X:0.00
READ: echo:endstops hit:  X:0.00

homing_bump_divisor tested down to 2,2,2.

[NiklasOlofsson]

It moves like crazy now while printing. The printer moves and stuff on the table is falling over. ;-)
The print is ruined. Just need to kill it.

Tries to move too fast maybe?
https://www.youtube.com/watch?v=WCY7CF0_WJE

[Roxy-3D]

We need to find the commit that caused the problem!!!!

[bgort]

My guess is that all of the changes to use progmem fouled something up. See also #6988.

[Roxy-3D]

My guess is that all of the changes to use progmem fouled something up. See also #6988.

An easy way to verify this is do a M503 and see what numbers are being used for feed rate. If they don't match the Configuration.h number... That may be it.

[NiklasOlofsson]

Send: M503
Recv: echo: G21 ; Units in mm
Recv: echo: M149 C ; Units in Celsius
Recv:
Recv: echo:Filament settings: Disabled
Recv: echo: M200 D3.00
Recv: echo: M200 D0
Recv: echo:Steps per unit:
Recv: echo: M92 X80.00 Y80.00 Z400.00 E100.00
Recv: echo:Maximum feedrates (units/s):
Recv: echo: M203 X300.00 Y300.00 Z4.00 E25.00
Recv: echo:Maximum Acceleration (units/s2):
Recv: echo: M201 X0 Y0 Z0 E0
Recv: echo:Acceleration (units/s2): P R T
Recv: echo: M204 P1000.00 R2000.00 T2000.00
Recv: echo:Advanced: S T B X Z E
Recv: echo: M205 S0.00 T0.00 B20000 X5.00 Y5.00 Z0.20 E2.50
Recv: echo:Home offset:
Recv: echo: M206 X0.00 Y0.00 Z0.00
Recv: echo:Auto Bed Leveling:
Recv: echo: M420 S0 Z0.00
Recv: echo:Material heatup parameters:
Recv: echo: M145 S0 H200 B60 F170
Recv: M145 S1 H230 B110 F170
Recv: echo:PID settings:
Recv: echo: M301 P12.33 I0.51 D74.50
Recv: echo: M304 P234.88 I42.79 D322.28
Recv: echo:Z-Probe Offset (mm):
Recv: echo: M851 Z-0.40

[Roxy-3D]

Recv: echo: M203 X300.00 Y300.00 Z4.00 E25.00

These numbers look low. Z's max feed rate is 4 ???

Recv: echo:Maximum Acceleration (units/s2):
Recv: echo: M201 X0 Y0 Z0 E0

Max acceleration is 0.000 ????

[NiklasOlofsson]

4 feels good. It was 2 before but I changed it to 4 when I went trapezoidal.

With the working version:

Recv: echo:Maximum Acceleration (units/s2):
Recv: echo: M201 X3000 Y3000 Z100 E10000

Sent M201 X3000 Y3000 Z100 E10000 to the new version. Same thing and this in the log:
Recv: echo:Warning: Homing Bump Divisor < 1

[Bob-the-Kuhn]

I'm getting really strange numbers when reading the home bump values out of PROGMEM.

[Kaibob2]

From 1.1.3

/**
 * Some planner shorthand inline functions
 */
inline float get_homing_bump_feedrate(AxisEnum axis) {
  int constexpr homing_bump_divisor[] = HOMING_BUMP_DIVISOR;
  int hbd = homing_bump_divisor[axis];
  if (hbd < 1) {
    hbd = 10;
    SERIAL_ECHO_START;
    SERIAL_ECHOLNPGM("Warning: Homing Bump Divisor < 1");
  }
  return homing_feedrate_mm_s[axis] / hbd;
}

From recent 1.1.x BugFix

/**
 * Some planner shorthand inline functions
 */
inline float get_homing_bump_feedrate(const AxisEnum axis) {
  const uint8_t homing_bump_divisor[] PROGMEM = HOMING_BUMP_DIVISOR;
  uint8_t hbd = pgm_read_byte(&homing_bump_divisor[axis]);
  if (hbd < 1) {
    hbd = 10;
    SERIAL_ECHO_START;
    SERIAL_ECHOLNPGM("Warning: Homing Bump Divisor < 1");
  }
  return homing_feedrate(axis) / hbd;
}

[Bob-the-Kuhn]

Looks like you can't do a const uint8_t PROGMEM homing_bump_divisor[] = HOMING_BUMP_DIVISOR; within a function. Moving it outside now returns the expected values.

[Roxy-3D]

Of course this is obvious... But we better check the rest of that commit for that syntax happening within a function.

[Kaibob2]

I can confirm, that when

/**
 * Some planner shorthand inline functions
 */
const uint8_t homing_bump_divisor[] PROGMEM = HOMING_BUMP_DIVISOR;
inline float get_homing_bump_feedrate(const AxisEnum axis) {

  uint8_t hbd = pgm_read_byte(&homing_bump_divisor[axis]);
  if (hbd < 1) {
    hbd = 10;
    SERIAL_ECHO_START;
    SERIAL_ECHOLNPGM("Warning: Homing Bump Divisor < 1");
  }
  return homing_feedrate(axis) / hbd;
}

homing works like it's supposed to.

[NiklasOlofsson]

Does it also fix the problem while printing?

[Roxy-3D]

This does kind of sound like a compiler bug. It seems like that should work within a function too.

My guess is putting a 'static' in front of it when it is within a function will also work. But I'm not setup at the moment to check that.

[Bob-the-Kuhn]

static const uint8_t PROGMEM homing_bump_divisor[] = HOMING_BUMP_DIVISOR; inside the function works. Delete the "static" and it fails.

Looks like the homing one is the only place it's missing.

[bgort]

Does that even need to be progmem? It was inside a function, so not using any SRAM until the function is called.

[Bob-the-Kuhn]

I just merged the fix for the homing issue.

Please let me know if that fixes everything. Could be another location I missed.

[Roxy-3D]

Yeah... This kind of looks and smells like a compiler bug. The static forces the storage to be with the global variables even though the scope of it is limited to inside the function.

Does that even need to be progmem? It was inside a function, so not using any SRAM until the function is called.

Almost for sure it does... The 'pre-initialized' values are in RAM and copied at execution time to where ever they are needed. I think if we compile it each way... You will see a different amount of RAM being used. Like I say... I can't test it right now... But my guess is this does save a few bytes of RAM.

[bgort]

Almost for sure it does... The 'pre-initialized' values are in RAM and copied at execution time to where ever they are needed. I think if we compile it each way... You will see a different amount of RAM being used. Like I say... I can't test it right now... But my guess is this does save a few bytes of RAM.

Okay. I haven't looked at this at all, but thought HOMING_BUMP_DIVISOR was a #define.

EDIT: Should finish my thoughts so they make sense to others. 😄 It was my understanding that predefined values in a function are stored in and then read from progmem on execution. Entirely possible I'm wrong.

[Bob-the-Kuhn]

At compile time they're moving the define values into FLASH.

[Roxy-3D]

Yes. But I think it is more a question of how the compiler generates code to handle 'pre-initialized' variables. (Thinky doesn't like that term. But I don't know what else to call it.) I believe the construct:

int some_func() {
int i=37;
char str="hello world";
...
}

will have the pre-initialized values in RAM and just copy them to the given stack frame location when the function starts. I do not believe it does incremental assignments by doing a load-immediate of 37 and storing it at i's location in the stack frame.

[Kaibob2]

I can confirm, that with #6995 homing and printing works.

[Kaibob2]

Was there a change in the jerk algorithm recently? I upgraded from RCBugFix to 1.1.3 and the movements seem a little more hectical now.

[NiklasOlofsson]

Homing works here but it still does that clunking sound and moves very ... "hard"

[NiklasOlofsson]

Yes, The problem with leveling and printing is still there (as in my movie)

[Roxy-3D]

I bet we have similar code syntax within some other functions....

[Bob-the-Kuhn]

In configuration_store.cpp on about line 1135 change
planner.max_acceleration_mm_per_s2[i] = pgm_read_float(&tmp3[i < COUNT(tmp3) ? i : COUNT(tmp3) - 1]);
to
planner.max_acceleration_mm_per_s2[i] = pgm_read_dword_near(&tmp3[i < COUNT(tmp3) ? i : COUNT(tmp3) - 1]);

That variable is uint32_t everywhere except on that line so pgm_read_float needs to change to pgm_read_dword_near.

That fixes the _max acceleration is zero_ comment.

Does it also fix the clunking? You probably need to do the M502, M500, M501 sequence to see the change.

[NiklasOlofsson]

Always doing that. Printing atm, 99.37% ;)

[bgort]

At compile time they're moving the define values into FLASH.

Right, but my point - which I didn't make clear at first (I went back and edited) - was that as a 'static' value in a #define, it would have to be stored in progmem and then read out of progmem (flash, whatever you want to call it - it's all the same address space) when needed.

I thought that in cases of functions where the variables were 'set up' with initial values it pulled all of the necessary data/values from progmem onto the stack and then made use of it. Unless I've misunderstood something, which is what it sounds like Roxy is saying? So all initial values (to be clear, the 10 in int x = 10;) in all functions across the entire codespace are stored in SRAM regardless of whether they're being used? That's not what I thought at all, and I'm not sure how that makes sense, given the nearly-nil speed difference in accessing SRAM vs. PROGMEM (flash).

[NiklasOlofsson]

Sounds good. No clunking.

[Bob-the-Kuhn]

I've just merged the configuration_store.cpp fix.

[Roxy-3D]

Unless I've misunderstood something, which is what it sounds like Roxy is saying? So all initial values (to be clear, the 10 in int x = 10;) in all functions across the entire codespace are stored in SRAM regardless of whether they're being used? That's not what I thought at all, and I'm not sure how that makes sense, given the nearly-nil speed difference in accessing SRAM vs. PROGMEM (flash).

I was only expressing my thoughts about how it generates code... It is very possible I'm wrong. We probably have to look at the disassembled code (with the C statements as comments) to figure out its exact behavior.

[bgort]

Yeah, I'm not sure either, and it's certainly possible I'm wrong too. As you say, we can find out with a dissassembly/objdump, I'm sure.

[Bob-the-Kuhn]

The initial values are stored in PROGMEM as part of a load immediate type instruction.

If it's not used then the optimizing compiler will get rid of it.

Even some of the variables disappear with the optimizing compiler. At least they're not in the symbol table which means they spend their entire life on the stack or in a register.

[bgort]

That's what I thought/believed. I imagine the compiler reuses dupes, too, so that's probably why we don't see every value every time.

[Roxy-3D]

These might be part of this discussion? https://github.com/MarlinFirmware/Marlin/issues/6998 and https://github.com/MarlinFirmware/Marlin/issues/6988 .

[Bergerac56]

The last "bugfix" solves the problem on my printer . Interesting, it solves also another issue I had with G28 followed by a G1 X0 (Motor not respecting endstop X issue #6918). It seems to be a link.

[Bob-the-Kuhn]

That's unexpected. The bugs this fixes were only introduced yesterday or the day before.

[Bergerac56]

You are right. The bug #6918 was, in fact, solved in the release of the 6th and not in the release of today. Taking a release every day, I rechecked version per version. It started on the 25th of May and ended on the 6th of June. I did not check this specific item in the release of the 6th (I forgot). The release of the 8th was not the best for the printer and the Y belt. I had to do some mechanical homework (not a big deal...) and tested with the release of today. As the 2 bugs disappeared, I thought that the 2 problems were solved in the same bugfix version. Sorry for that. But, anyway, it works now. Thanks

[Kaibob2]

Same here.

[fiveangle]

@NiklasOlofsson - is there more to do here ?

[NiklasOlofsson]

No :-)

[fiveangle]

:)