Marlin: Pausing at bilinear grid boundaries

[thinkyhead]

Continuing from #8573 —

@tcm0116 : My issue is definitely unrelated to this one. Mine is occurring at the bilinear grid boundaries as the printer is coming to a complete stop as it crosses the boundary. It seems to be a function of the amount of change in Z over the grid and the speed of the movement.

[coolio986]

I have a 600mm x 600mm printer which I just recently turned off UBL (bilinear) because of this issue. While mine didn't come to a complete stop, it did slow down for a brief period then speed back up when crossing boundaries.

When rapid traverse across boundaries the printer would slow, then speed back up. (rapid traverse is 300mm/s)

It also sometimes did this when printing at 100mm/s.

I believe this slow down is a function of z jerk with z acc/dec. I'm using FW version 1.1.3.

In previous versions of the firmware, when this boundary cross would happen, the watchdog would timeout and force the processor to reset.

My 2c.

[Roxy-3D]

I have a 600mm x 600mm printer which I just recently turned off UBL (bilinear) because of this issue.

UBL and (bilinear) are two different bed leveling schemes. Both are mesh bashed. Did you turn off UBL because you had this problem? Both UBL and Bi-Linear usually do a bi-axis interpolation. But they are not the same animal.

[tcm0116]

My travel speed is more like 120-160. The issue seems to be more pronounced
at higher speeds and at larger changes in z at the grid boundary.

UBL and (bilinear) are two different bed leveling schemes. Both are mesh
bashed.

I think the issue is with the Planner, and is being exposed by any
mesh-based leveling system.

[Roxy-3D]

I think the issue is with the Planner, and is being exposed by any
mesh-based leveling system.

I'm printing above those speeds with UBL. I don't see it. But the machine I have doing that has a 20x4 LCD Display and not a graphical display.

[tcm0116]

@Roxy-3D can you try building a mesh that has a somewhat excessive amount
of deviation? For example, put a 1-2mm thick plate on opposite corners of
your bed such that the mesh ends up like a hyperbolic paraboloid? Then,
command high-speed travel moves across the bed.

[thinkyhead]

I've posted a new feature that might shed more light on the behavior. The PR linked above adds SEGMENT_LEVELED_MOVES option for all three forms of mesh leveling. Set this option to use delta-style segmentation instead of breaking up moves on mesh boundaries. If it also exhibits interesting pauses then it may point towards a common cause.

[AnHardt]

From my perspective a 'slow down' at the mesh lines is duty.
Z is changing direction - so the junction has to be stepped at junction speed. Junction speed should be a function of the angle between the connected lines. (sharp angles require a low speed (down to 0) - flat angles can be done with higher speeds)
The problem in this issue is - we get much slower junction speeds than we expect, The junction angle is very flat, so we expect a near zero change of speed at the junction. If change of Z-speed is smaller than Z-jerk we do not expect any slowdown at the junction.
So what can go wrong?

• Too low Z-jerk?
• Empty paner buffer - no buffer line to connect with?
• Buffer full, but segments in planer buffer are too short. If jerk and acceleration is low it needs to change several buffer lines to reach junction speed. Calculating this can last a while. Eventually longer than it needs to step the lines in the buffer?
• Wrong calculation in the planner?
• ...

Tests:
Alter z-jerk. Do you see a difference?
Alter acceleration.
At Deltas play with DELTA_SEGMENTS_PER_SECOND and or MIN_STEPS_PER_SEGMENT.
Test different feedrates.

[Roxy-3D]

can you try building a mesh that has a somewhat excessive amount of deviation? For example, put a 1-2mm thick plate on opposite corners of your bed such that the mesh ends up like a hyperbolic paraboloid? Then, command high-speed travel moves across the bed.

Well... Here is an easier way to do test that... Assuming you have UBL running, do

• G29 P0 (zero the mesh)
• G29 Q1 T (create a diagonal step across the mesh)
• G1 X0 Y100
• G1 X200 Y100 (Do you see the pause or slow down at the step?)

For reasonable changes in mesh point values, I don't see any slow down. But in the above example my printer's Z-Axis is not fast enough to allow the X movement to continue at the same speed. I don't see it stop. But I see it slow dramatically for the step.

I suspect @AnHardt is correct:

From my perspective a 'slow down' at the mesh lines is duty.
Z is changing direction - so the junction has to be stepped at junction speed. Junction speed should be a function of the angle between the connected lines. (sharp angles require a low speed (down to 0) - flat angles can be done with higher speeds)

And in the above example... You do see that behavior.

[thinkyhead]

We still have that commented-out junction code sitting in the planner that actually does compare the angles. Since (I believe) it includes a couple of sqrt calculations, maybe it should be implemented only for Z, and only on direction changes. Or… maybe all we need is to make the existing logic smarter.

Where's the point in the code where the behavior manifests? And what are examples of numbers fed to that part of the code that cause this?

[thinkyhead]

Somewhere in this loop…

// Now limit the jerk in all axes.
LOOP_XYZE(axis) {
  // Limit an axis. We have to differentiate: coasting, reversal of an axis, full stop.
  float v_exit = previous_speed[axis], v_entry = current_speed[axis];
  if (prev_speed_larger) v_exit *= smaller_speed_factor;
  if (limited) {
    v_exit *= v_factor;
    v_entry *= v_factor;
  }

  // Calculate jerk depending on whether the axis is coasting in the same direction or reversing.
  const float jerk = (v_exit > v_entry)
      ? //                                  coasting             axis reversal
        ( (v_entry > 0.f || v_exit < 0.f) ? (v_exit - v_entry) : max(v_exit, -v_entry) )
      : // v_exit <= v_entry                coasting             axis reversal
        ( (v_entry < 0.f || v_exit > 0.f) ? (v_entry - v_exit) : max(-v_exit, v_entry) );

  if (jerk > max_jerk[axis]) {
    v_factor *= max_jerk[axis] / jerk;
    ++limited;
  }
}

[tcm0116]

We still have that commented-out junction code sitting in the planner that actually does compare the angles

I wonder if the CORDIC method could be used to optimize the junction code

[thinkyhead]

@tcm0116 AFAIK, the AVR math and trig functions are pretty optimal IEEE implementations. At least, in tests around delta kinematics we couldn't optimize sqrt better than built-in. And

Here's what GRBL is now doing, with just 1 sqrt and no trig:
https://github.com/grbl/grbl/blob/master/grbl/planner.c#L326-L405

[thinkyhead]

What's the result if we naively ignore direction change and only consider the plain difference in speed? Presumably if a direction change is occurring the junction speed should already be low, but not necessarily coming to a full stop.

- // Calculate jerk depending on whether the axis is coasting in the same direction or reversing.
- const float jerk = (v_exit > v_entry)
-     ? //                                  coasting             axis reversal
-       ( (v_entry > 0 || v_exit < 0) ? (v_exit - v_entry) : max(v_exit, -v_entry) )
-     : // v_exit <= v_entry                coasting             axis reversal
-       ( (v_entry < 0 || v_exit > 0) ? (v_entry - v_exit) : max(-v_exit, v_entry) );
+ // Calculate jerk as a simple change in speed, regardless of direction change
+ const float jerk = v_exit > v_entry ? v_exit - v_entry : v_entry - v_exit; // i.e., FABS(v_exit - v_entry)

Will this have undesired consequences? It might lead to fewer instances of BLOCK_BIT_START_FROM_FULL_HALT being set.

[Roxy-3D]

At least, in tests around delta kinematics we couldn't optimize sqrt better than built-in. And

Agreed. But the difference is we only need a few digits of precision for the square root. And especially if we make sure the final calculations always round down the resulting speed.

[thinkyhead]

An integer fixed-point square root might also be faster…
http://web.archive.org/web/20080303101624/http://c.snippets.org/snip_lister.php?fname=isqrt.c

[Roxy-3D]

Yeah!!!! That looks like the ticket! I changed the code some what to play with it...

#include "stdafx.h"
#include <conio.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include "snipmath.h"

#define BITSPERLONG 32
#define TOP2BITS(x) ((x & (3L << (BITSPERLONG-2))) >> (BITSPERLONG-2))

void usqrt(unsigned long x, struct int_sqrt *q)
{
    unsigned long a = 0L;                   /* accumulator      */
    unsigned long r = 0L;                   /* remainder        */
    unsigned long e = 0L;                   /* trial product    */

    int i;

    for (i = 0; i < BITSPERLONG; i++)   /* NOTE 1 */
    {
        r = (r << 2) + TOP2BITS(x); x <<= 2; /* NOTE 2 */
        a <<= 1;
        e = (a << 1) + 1;
        if (r >= e)
        {
            r -= e;
            a++;
        }
    }
//  memcpy(q, &a, sizeof(long));
    q->sqrt = a >> 16;
    q->frac = a & 0xffff;
}

int main(void)
{
    int i;
    unsigned long l = 0x3fed0169L;
    struct int_sqrt q;

    for (i = 0; i < 150; ++i)
    {
        usqrt(i, &q);
        printf("sqrt(%3d) = %2d, remainder = %2d\n",
            i, q.sqrt, q.frac);
    }
    usqrt(l, &q);
    printf("\nsqrt(%lX) = %X, remainder = %X\n", l, q.sqrt, q.frac);

    getch();
    return 0;
}

sqrt(118) = 10, remainder = 56543
sqrt(119) = 10, remainder = 59553
sqrt(120) = 10, remainder = 62550
sqrt(121) = 11, remainder = 0
sqrt(122) = 11, remainder = 2972
sqrt(123) = 11, remainder = 5933
sqrt(124) = 11, remainder = 8882
sqrt(125) = 11, remainder = 11818
sqrt(126) = 11, remainder = 14743
sqrt(127) = 11, remainder = 17657
sqrt(128) = 11, remainder = 20559
sqrt(129) = 11, remainder = 23449
sqrt(130) = 11, remainder = 26329
sqrt(131) = 11, remainder = 29197
sqrt(132) = 11, remainder = 32055
sqrt(133) = 11, remainder = 34902
sqrt(134) = 11, remainder = 37738
sqrt(135) = 11, remainder = 40563
sqrt(136) = 11, remainder = 43378
sqrt(137) = 11, remainder = 46183
sqrt(138) = 11, remainder = 48977
sqrt(139) = 11, remainder = 51762
sqrt(140) = 11, remainder = 54536
sqrt(141) = 11, remainder = 57300
sqrt(142) = 11, remainder = 60055
sqrt(143) = 11, remainder = 62800
sqrt(144) = 12, remainder = 0
sqrt(145) = 12, remainder = 2725
sqrt(146) = 12, remainder = 5442
sqrt(147) = 12, remainder = 8149
sqrt(148) = 12, remainder = 10847

[Bob-the-Kuhn]

I have not been able to reproduce this issue. Could someone post a configuration & a gcode file that has this issue?

[Roxy-3D]

Bob... I can't reproduce the exact issue either. But this will cause something very similar to happen:
Assuming you have UBL running, do

• G29 P0 (zero the mesh)
• G29 Q1 T (create a diagonal step across the mesh)
• G1 Z.5
• G1 X0 Y100
• G1 X200 Y100 (Do you see the pause or slow down at the step?)

[thinkyhead]

Could someone post a configuration & a gcode file

I'm assuming that the cause is something like Andreas proposed, where the change in Z direction at a mesh boundary is causing BLOCK_BIT_START_FROM_FULL_HALT to get set. I don't think it's a result of the planner getting starved or blocked.

Presumably to get this to manifest you have to first set up a mesh that has a high point between two low points (or _vice-versa_). Then, with leveling enabled, run some G-code that does moves crossing that line several times from several different points and angles, trying different feedrates.

I'd be curious to know whether the issue is more common when crossing in a straight line vs diagonally, or if it occurs more when crossing near confluences of the grid lines. Also, whether it mostly affects shorter moves (i.e., moves that start closer to the grid line).

---

@Roxy-3D The G29 Q1 test mesh is probably more extreme (1cm) than the usual case. What if the diagonal line is only 1-2mm offset instead of 9.99?

[thinkyhead]

Yeah!!!! That looks like the ticket! I changed the code some what to play with it...

Great! Next we should compare speeds to sqrt running on AVR. It might end up being possible to do delta inverse kinematics entirely in terms of integer/steps.

[tcm0116]

I did some testing using a fairly recent version of bugfix-1.1.x, and have some interesting results.

Here's the grid generated by G29 using bilinear leveling:

Bilinear Leveling Grid:
      0      1      2
 0 +0.188 -0.057 -0.042
 1 +0.415 +0.060 -0.160
 2 +0.470 +0.078 -0.225
 3 +0.690 -0.002 -0.547

With leveling active, regardless of X, I experienced stops during the following movement commands at the maximum feedrate of 160 mm/s. What's interesting is that I could get it to stop at 95mm and 175mm during shorter movements, but it only stopped at 175mm during long movements. Another interesting finding is that even with ENABLE_LEVELING_FADE_HEIGHT and the fade height set to 10mm, I stops were still happening with Z=10mm and Z=50mm. I even tried to set the Z jerk to 20, but it still stops.

Y90 -> Y100 - stops around 95mm
Y170 -> Y180 - stops around 175mm
Y0 -> Y270 - stops around 175mm

Here's my configuration file: Configuration.zip

I'll try and find some time to see if BLOCK_BIT_START_FROM_FULL_HALT is getting set, but it might not be for a few days.

[tcm0116]

Quick update. I added some printouts for when BLOCK_BIT_START_FROM_FULL_HALT is being set. During the movements described above, it it being set twice for each movement in the else condition of if (moves_queued > 1 && previous_nominal_speed > 0.0001), meaning that we're not even computing the jerk. It looks like there might be an issue with previous_nominal_speed.

[thinkyhead]

Another interesting finding is that even with ENABLE_LEVELING_FADE_HEIGHT and the fade height set to 10mm, I stops were still happening with Z=10mm and Z=50mm.

With today's patches, above the fade height there will no longer be segmented movement…

[thinkyhead]

Sounds like previous_nominal_speed is falling below 0.0001 somehow. With today's patches, it checks for a value below 0.000001 (closer to zero) instead. I wonder if that will make any difference.

Of course, it could also be due to moves_queued being only 1. It seems that once BLOCK_BIT_START_FROM_FULL_HALT has been set, it doesn't get cleared. So I assume it means that the block being prepared is too late to do anything about the exit speed of the previous block.

[Bob-the-Kuhn]

I didn't see anything unusual with Roxy's setup. The only time I saw the X step rate change was when the Z axis stepping changed (as expected).

Here's the Seleae logic analyzer capture. You can load this into the Seleae software if you want to see the details.
UBL crossing diagonal.logicdata.zip

Channels:
X step (top)
Z step
Z direction
stepper ISR (toggles each time it's entered)
check for new block

X when Z step starts

X when Z direction changes

[tcm0116]

I was incorrect about previous_nominal_speed. It's actually the moves_queued > 1 check. I think this needs to be changed to moves_queued > 0 because moves_queued is set after the current move has been removed from the queue, so checking for > 1 would actually mean that there are two movements queued after the current one. In the case of a move that consists of two segments only, this will result in BLOCK_BIT_START_FROM_FULL_HALT being set for both segments.

I've done a little testing with moves_queued > 0, and it does fix the issue of BLOCK_BIT_START_FROM_FULL_HALT being set for both movements. However, I'm still getting a stop between the segments, and it's somewhat violent. From what I can tell, safe_speed is limiting the final_rate of the first movement, which causes it to come close to a stop, but the second movement's entry_speed is at full speed. As such, it's decelerating at the end of the first movement and then trying to instantaneously reach full speed for the second movement. I'm going to try and investigate a bit further, but I'm almost out of time for the evening.

[tcm0116]

Hmmmm. I think the second issue I ran into is because Planner::reverse_pass() only runs if movesplanned() > 3. Without the reverse pass, I don't think the entry and exit speeds will be harmonized.

I think I've just uncovered a flaw in the planner design when a movement consists of only 2 segments.

[Roxy-3D]

So I assume it means that the block being prepared is too late to do anything about the exit speed of the previous block.

I could be wrong. But all of the mesh based bed leveling systems have a stutter when you give them a big first move. The problem is any big move gets broken up into smaller segments. Any subsequent moves that get sent to the planner can have the calculations done to combine things. But the move in process can't be modified. And that causes a stutter...

[thinkyhead]

So maybe if we could give the planner a cue ahead of a set of moves that it should wait for one or two more blocks to arrive before it hands the first block over to the stepper ISR. Maybe as a general policy, if the planner is down to a single move, it should not allow it to go to the stepper ISR for a fraction of a second…

[AnHardt]

About Bobs diagrams (https://github.com/MarlinFirmware/Marlin/issues/8595#issuecomment-348073135):

What do we see?
Let's begin with the second one.
We see a deceleration to jerk-speed (stop), change of direction, followed by an acceleration from jerk-speed (stop). Acceleration/deceleration and jerk are the same on both sides of the stop - i assume determined by Z.
In the first diagram we see about the same.
The differences are:
In the first half we have no Z-steps. There is no change in direction of Z, but it begins to move. So there is an angle and deceleration to junction-speed is required. Junction-speed is z-jerk because z starts from 0.
In the first halve X determines jerk and deceleration - in the second half Z.

All is well here - as expected!

[AnHardt]

About the 'fist move in planner buffer can't be connected' problem, @tcm0116 is talking about.
An old problem what we knowed about, but forgot.
Different strategies have been thought about:

• Wait until buffer is full. -> Will not print single moves.
• When buffer empty, start delayed. -> Pauses in every 'blocking_move', really bad stuttering and slowdown when buffer runs dry.

A new idea could be:

• When buffer empty split the first move in half. -> Unknown consequences! (But maybe.)

[AnHardt]

Here we have a Z-slow-down.

Speed change in X seems to be a tiny bit less dramatic. Here again X seems to dominate acceleration and jerk in the right part.

For reference the other cases again.

[tcm0116]

Why does there need to be 4 moves planned before Planner::reverse_pass() will run? Since we're only really concerned with the junction velocity of two connected movements, shouldn't you only need 2 moves planned?

[AnHardt]

I think:
First move is planned and immediately executed by the stepper interrupt - so blocked for further changes.
While block one is stepping, the next line is produced. With only one block we can't work with - there is no optimisation possible.
If block nr. 3 is produced and block one is still running, we now have 2 blocks (one junction) to optimize - and we should do that.

[AnHardt]

First block:
| _ |
|/ \|
or
|/\|

Add second block:
| _ | _ |
|/ \|/ \|
or
|/\|/\|

Add third block
| _ | _ | _ |
|/ \|/ \|/ \|
or
|/\|/\|/\|

Now we can optimize to
| _ | __|__ |
|/ \|/  |  \|
or
|  | /|\ |
|/\|/ | \|

[tcm0116]

So, it sounds like this issue is independent of bed leveling. I suspect you
could replicate it with bed leveling disabled by sending two G1 commands in
rapid succession.

What about delaying the first movement after a stop for just long enough to
let any additional movements be planned, if any?

[AnHardt]

See https://github.com/MarlinFirmware/Marlin/issues/8595#issuecomment-348138944

[tcm0116]

So then, what if a flag was provided to buffer_line indicating that more moves are pending (such as during a segmented move), which would then delay the first move? In that case, the delay would only need to be until the after the third move is buffered, which shouldn't be very long. This would resolve the stuttering issue if the buffer runs dry since non-segmented G0/G1 movements wouldn't be delayed.

[tcm0116]

Although that doesn't directly solve my problem where only two segments are executed. For that to work, Planner::reverse_pass() would be to run after the second segment is buffered, and then the fist segment could be released for execution.

[AnHardt]

The first block problem is a heritage from grbl - has been there for ever.
It just hasn't been that visible.
Wenn sending a move manually, it's hard to send a further move fast enough.
When a g-code file begins after a break it usually sends long straits where we expect a slowdown at the end, or it begins with little moves, where the nozzle after the first move hasn't picked up enough speed to make the slowdown noticeable.
New with this grid-levelling is a near full stop from full speed at a place you can't see/expect an angle.

[AnHardt]

I suppose delaying the execution of the first buffer line until the second one is planned (not a fixed time), in combination with splitting the first move into two parts (when the buffer is empty) can solve the problem without disturbing delays. The second move could immediately be optimized with the second part of the first move.
This 'just' has to be written and tested.

[AnHardt]

Normal first move:
|/\|
Splitted first move:
|/|\|
Run execution.
Add second move:
|/|\|/\|
optimize:
| |_|_ |
|/| | \|
or, if not at full speed:
| |/|\ |
|/| | \|

[AnHardt]

An open question is what to do if the second move arrives late - the first half of the first move is already used up.

|\|/\|

Will result in a stop.
EDITED:
What is acceptable. Making pauses in between sending moves justifies breaks in the movement.

[tcm0116]

I don't think there's anything that can be done about that. In my opinion,
we should only perform this optimization for segmented movements were we
know that enough segments will be planned in rapid succession, and not
unsegmented moves.

[AnHardt]

From the conceptual standpoint it's advisable to clean that problem out at the deepest possible level. Else you have to deal with it again and again in every new segmented move.

[Roxy-3D]

A new idea could be:
When buffer empty split the first move in half. -> Unknown consequences! (But maybe.)

This is a very clever idea...

I suppose delaying the execution of the first buffer line until the second one is planned (not a fixed time), in combination with splitting the first move into two parts (when the buffer is empty) can solve the problem without disturbing delays. The second move could immediately be optimized with the second part of the first move.

Yes. But here is small modification to the idea. As the very first line to Planner::buffer_line() we do this:

void Planner::_buffer_line(const float &a, const float &b, const float &c, const float &e, float fr_mm_s, const uint8_t extruder, bool no_break_up) {
  if (!blocks_queued() && !no_break_up) {
     float aa, bb, cc, ee;
      aa = (a+current_position[X_AXIS])/2.0;
      bb = (b+current_position[Y_AXIS])/2.0;
      cc = (c+current_position[Z_AXIS])/2.0;
      ee = (e+current_position[E_AXIS])/2.0;
      _buffer_line(aa, bb, cc, ee, fr_mm_s, extruder, 1);
  }

That will cause a 'small delay' as the first half of the line is scheduled. And we may be able to use the no_break_up flag to indicate there is another 1/2 of the move coming down soon, so don't schedule this yet until it can be joined to the next move.

[tcm0116]

We'd also have to pass a flag to _buffer_line to tell it to delay execution
of the first segment until after the second segment is buffered and the
optimization is performed.

[thinkyhead]

When buffer empty split the first move in half. -> Unknown consequences! (But maybe.)
This is a very clever idea...
But here is small modification to the idea.

Yes, I like this approach too. Except, split the move into a longer move followed by a shorter move, so it takes more time for the first move to finish and thus gives the planner more time to get a third move to chain to the small second move.

[thinkyhead]

void Planner::_buffer_line(const float &a, const float &b, const float &c, const float &e, float fr_mm_s, const uint8_t extruder, bool no_break_up) {
  if (!blocks_queued() && !no_break_up) {
     float aa, bb, cc, ee;
      aa = (a+current_position[X_AXIS])/2.0;
      bb = (b+current_position[Y_AXIS])/2.0;
      cc = (c+current_position[Z_AXIS])/2.0;
      ee = (e+current_position[E_AXIS])/2.0;
      _buffer_line(aa, bb, cc, ee, fr_mm_s, extruder, 1);
  }

Unfortunately the overhead for this solution would be kind of high. The current_position is not in sync with planner._buffer_line. The move is from the previous planner.position (in steps units) to the new position — after converting to steps units.

So, we need to have a planner._buffer_steps function which contains most of _buffer_line, that takes the new move in steps units. The _buffer_line function will do the conversion to steps and then jump to _buffer_steps. This allows the first move to be split in half and queued in terms of steps with the least amount of added overhead.

[tcm0116]

Planner has a internal position variable that truly is the current
position.

[thinkyhead]

See if #8608 has a positive effect … once it passes Travis, of course.

[AnHardt]

The PRs are still changing to fast. Will have a look in the morning.

For now:
Splitting asymmetric feels not good to me.
Let's assume an ordinary first move. Not reaching it's target speed, so accelerating until the mid then decelerating to zero (not optimized until now)

|   /\   |
|  /  \  |
| /    \ |
|/      \|
After symmetric splitting it will look like:
| /\ | /\ |
|/  \|/  \|
After optimizing this (can only done with stepper interrup waiting for this and modified optimizer)
|   /|\   |
|  / | \  |
| /  |  \ |
|/   |   \|
An asymmetric (3/4) splitted move would look like:
|  /\  |  |
| /  \ |  |
|/    \|/\|
After optimizing:
|   /\ |  |
|  /  \|  |
| /    |\ |
|/     | \|
Up to now this is looking very similar. But now we should start the stepping and can't
work with the first part anymore. Now we add the next bock, same duration, still not 
reaching target speed.
|   /|\   |   /\   |
|  / | \  |  /  \  |
| /  |  \ | /    \ |
|/   |   \|/      \|
optimized:
|    |   /|\       |
|    |  / | \      |
|    | /  |  \     |
|    |/   |   \    |
|   /|    |    \   |
|  / |    |     \  |
| /  |    |      \ |
|/   |    |       \|
vs. (3/4)
|   /\ |  |   /\   |
|  /  \|  |  /  \  |
| /    |\ | /    \ |
|/     | \|/      \|
optimized:
|      |  | /\     |
|      |  |/  \    |
|   /\ | /|    \   |
|  /  \|/ |     \  |
| /    |  |      \ |
|/     |  |       \|
reaching only 3/4 topspeed.

If stepping does not wait for optimizing the splitted move we'll win nothing. Still (this time the first part of) the first move will end at zero speed.

[thinkyhead]

I've pre-merged the general fixes from #8608 and #8611, and now those PRs only contain the planner first-move patch.

[thinkyhead]

I thought it would work out more like this:

First move is BUSY so can't chain. (Exit speed is 0 or max-jerk.)

|  __  ||  ____||____  |
| /  \ || /    ||    \ |
|/    \||/     ||     \|
  BUSY

So if we add 2 moves...

|  ____||_   |
| /    || \  |
|/     ||  \ |
  BUSY

...the next added move has a chance to modify the 2nd move and chain.

|  ____||____||____  |
| /    ||    ||    \ |
|/     ||    ||     \|
  BUSY

[thinkyhead]

Just made an important change: Don't call stepper.wake_up until both moves have been added.

[AnHardt]

You are also right! The difference is in the the moves. Yours reach the wanted feedrate (long enough) mine do not.
Have to get up early. More tomorrow.

[AnHardt]

Now we have to check if recalculate(), especially reverse_pass(), forward_pass(), recalculate_trapezoids() are working on the new extended range of blocks (likely dependent on, if steppers are running or not.)

Else looking better and better.

[tcm0116]

recalculate() only looks at the BUSY flag, which isn't set until the
stepper class gets the block, which shouldn't happen until the steppers
wake up. Something that might need to be considered is if the steppers can
be woken up for any other reason. It might be a better idea to set a flag
in that first block that will indicate that the block shouldn't be
processed. The flag could then be set once recalculate() has processed the
block.

[thinkyhead]

The difference is in the the moves. Yours reach the wanted feedrate (long enough) mine do not.

One way to "cheat" would be to have the first move reduce its feedrate so that it is guaranteed to take at least 50ms (for example). It would end up only applying to smaller, faster moves.

xyzlen ? min(fr_mm_s, xyzlen << 4) : fr_mm_s; // duration under 1/16th of a second

---

  // Always split the first move into one longer and one shorter move
  if (!blocks_queued()) {
    constexpr int32_t prop[] = { 3, 4 };
    #define _BETWEEN(A) position[A##_AXIS] + ((target[A##_AXIS] - position[A##_AXIS]) * prop[0]) / prop[1]
    const int32_t between[XYZE] = { _BETWEEN(X), _BETWEEN(Y), _BETWEEN(Z), _BETWEEN(E) },
                  xyzlen = SQRT(
                    sq((between[X_AXIS] - position[X_AXIS]) * steps_to_mm[X_AXIS]) +
                    sq((between[Y_AXIS] - position[Y_AXIS]) * steps_to_mm[Y_AXIS]) +
                    sq((between[Z_AXIS] - position[Z_AXIS]) * steps_to_mm[Z_AXIS])
                  );
    // Make sure this move takes no less than 0.0625s
    _buffer_steps(between, xyzlen ? min(fr_mm_s, xyzlen << 4) : fr_mm_s, extruder);
  }
  _buffer_steps(target, fr_mm_s, extruder);

  stepper.wake_up();

[tcm0116]

What happens if it's a short move? A short move when the buffer is empty
could also be problematic with this split first move concept.

[thinkyhead]

Well the thing that generates stutters is a starved planner. The very problem is that the only remaining move in the buffer finishes too quickly, leading to complete stops between segments on a delta. The buffer isn't supposed to get starved, especially when there are many rapid short moves happening, as on a delta. With deltas, except for very few instances, the planner buffer should be saturated.

The "minimum time" change I'm proposing for testing would not prevent the starvation that led to the buffer getting empty, so there would still be the stutter before the first new move. However, it would cause the re-start to give a little extra time for the planner buffer to gain some blocks and likely reduce stuttering.

As another option, instead of having a pure DONT_PROCESS flag on the blocks, we might add a counter where 0 means go ahead and process, otherwise decrement. This would effectively delay a block for some number of stepper ISRs. But this might be more "stuttery" than having it start earlier but go slightly slower, as above.

The patch above would only affect very short moves —under 1/16th of a second— and only in the case of an already-starved (or empty) planner buffer.

[tcm0116]

I wonder if we're trying to solve a bigger problem than we really have.
This is only really an with high-speed segmented travel movements when
starting from a stop. As such, a solution for that problem is all that's
needed.

Since it's always with segmented moves, then we don't really need to
segment the first movement further. A flag could be passed in the call to
buffer_line, to indicate that the line is the first of a series. The
planner could go ahead and buffer that movement, and if there are no
buffered movements, set the DONT_PROCESS flag, which would prevent it from
being provided to the stepper class. As the planner of guaranteed to
receive additional segments, the DONT_PROCESS flag can just remain set
until the next segment is received and recalculate() has been run. This
should provide a very minimal delay without additional stuttering in the
event of a starved planner.

[Roxy-3D]

Well the thing that generates stutters is a starved planner. The very problem is that the first move in the buffer finishes too quickly, leading to complete stops between moves.

That is not what I'm seeing. When telling the printer to make a long move when it is idle.... There is a stutter at the first mesh line it crosses. That isn't because the planner is out of moves. It is because the second segment of the long move can't be joined to the first segment.

And in fact... with the Max7219 LED's... You can see the planner has at least a half dozen moves in the queue by the time it gets to the first mesh line.

[AnHardt]

@Roxy-3D
Right. Exactly that problem I want to solve here. Against too short buffer-lines we have MIN_STEPS_PER_SEGMENT. Against not having enough "time" in the buffer we try to fight with SLOWDOWN and delayed screen updates. Maybe these concepts can be improved, but now and here I want to solve the other problem as god as possible.

@tcm0116
My thumbsup her was i bit early. reverse_pass() for example is not looking like it could work with only two buffer-lines.
if (movesplanned() > 3)

@thinkyhead

Well the thing that generates stutters is a starved planner. ...

Yes. A starved planner is also a reason for stuttering, but this problem here is independent from that. With the current code there is NO possibility to execute a first buffer line not ending at zero speed. Completely independent from the question if this is part of a segmented line or not, if it's short or long, if it's slow or fast. (Did you get the idea at all?)

I'll have a few hours this evening to look more detailed into recalculate().

[tcm0116]

forward_pass() and recalculate_trapezoids() look like they'll run with only
two buffered lines. I'll try to find some time to play with it and see how
it really works.

[thinkyhead]

When telling the printer to make a long move when it is idle.... There is a stutter at the first mesh line it crosses. That isn't because the planner is out of moves. It is because the second segment of the long move can't be joined to the first segment.

Right. When the planner is empty (or runs out of moves, becoming empty) the last-executed move always comes to a full-stop. What we're addressing is that this also occurs on the first move whenever the buffer is empty, because the first block gets processed by the stepper ISR before the planner has a chance to chain another block. Once a move goes to the ISR it is unusable to do chaining, and thus the first move in any set of two is likely to stutter.

This isn't something we pay attention to very often, but run this G-code on a Cartesian:

G28 X Y
M420 S0
G4 S1
G1 X10 Y10
G1 X20 Y20

This will very often produce two moves instead of one smooth movement!

The reason we don't notice this during printing is that the planner is saturated most of the time. This is something that I've seen on SCARA robots - a weird "stutter" whenever starting a move, especially from full-extension. It actually happens on deltas, but it is usually imperceptible and we all ignore it because all moves on delta (except Z-only) are very small. But a delta might do it more obviously too:

G28
M420 S0
G4 S1
G1 Z200
G1 Z100

[Roxy-3D]

Would it make sense to add a parameter to the Planner::buffer_line() to tell it not to start the move until told to do so? All of the mesh based systems could, at the end of the movement routine call Planner::buffer_line() and say "Do the buffered moves..."

[thinkyhead]

(Did you get the idea at all?)

My code addresses that specifically. Sorry for bringing up the point about starved buffer, but my patch aims to address starvation also.

[thinkyhead]

If the planner can't do a reverse-pass with fewer than three segments, then I can modify the code to add 3 segments instead of just 2. The Planner::recalculate function runs as part of adding a line to the buffer, so by adding one more segment we should get the reverse_pass "for free."

[Roxy-3D]

Are you saying it can join a line already in motion to the next line that was added later?

[thinkyhead]

By adding two moves before starting the ISR, the first move is chained to the second.

|  ____||_   |
| /    || \  |  stepper.wake_up()
|/     ||  \ |

The second move will not be blocked by the stepper ISR until the first block is done processing. Thus, the main loop has a chance to add a 3rd move, and a 4th, and so on.

|  ____||____||____  |
| /    ||    ||    \ |
|/     ||    ||     \|
  BUSY
|  ____||____||______||____  |
| /    ||    ||      ||    \ |
|/     ||    ||      ||     \|
  BUSY   BUSY

As long as that first move gives enough time for the planner to get another move in it, the print job loop will be able to keep it filled, forward-reverse passes are possible, and the speed will stay constant.

[tcm0116]

then I can modify the code to add 3 segments instead of just 2

I think to @Roxy-3D's point, I think this should only be done if the move
is not already segmented. Given the way delta movements are segmented, a
very slow movement will result in very short segments, which is already
causing issues. Attempting to then further segment the first segment just
won't work. For leveled movements that are already segmented, additional
segmentation is unnecessary (unless there aren't enough segments).

[thinkyhead]

Attempting to then further segment the first segment just won't work.

I think it might. The segmentation here is essentially harmless, and the min-time concept should provide just enough "magic" to cure the stuttering that can occur at too-fast delta speeds.

[thinkyhead]

result in very short segments, which is already causing issues

Actually, no, the problem is that any first segment fed to the empty planner comes to a full stop, whether long or short doesn't matter.

As for starvation, that can be caused by "very short segments" being fed into the planner, or the parser/sd/serial being delayed by something like a screen update. It is not related to the size of the segments in the blocks that are fed _to the ISR_. The issue is entirely at the higher (_planner_) level (fed from the main loop).

We did a bunch to address starvation by throttling/optimizing graphical display updates, and that's the highest level where starvation can be addressed.

[AnHardt]

@thinkyhead
Now i'm convinced you got it.

Splitting into three segments seems to be unnecessary.
I hope to be right here. "Next is previous in reverse order" -> confusing!

@@ -259,30 +259,28 @@ void Planner::reverse_pass_kernel(block_t* const current, const block_t *next) {
  * recalculate() needs to go over the current plan twice.
  * Once in reverse and once forward. This implements the reverse pass.
  */
 void Planner::reverse_pass() {

-  if (movesplanned() > 3) {
+  // Make a local copy of block_buffer_tail, because the interrupt can alter it
+  uint8_t tail = block_buffer_tail;

+  if (movesplanned() > 3) {
     block_t* block[3] = { NULL, NULL, NULL };
-
-    // Make a local copy of block_buffer_tail, because the interrupt can alter it
-    // Is a critical section REALLY needed for a single byte change?
-    //CRITICAL_SECTION_START;
-    uint8_t tail = block_buffer_tail;
-    //CRITICAL_SECTION_END
-
     uint8_t b = BLOCK_MOD(block_buffer_head - 3);
     while (b != tail) {
       if (block[0] && TEST(block[0]->flag, BLOCK_BIT_START_FROM_FULL_HALT)) break;
       b = prev_block_index(b);
       block[2] = block[1];
       block[1] = block[0];
       block[0] = &block_buffer[b];
       reverse_pass_kernel(block[1], block[2]);
     }
   }
+  else if ((movesplanned() == 3) && (!TEST((&block_buffer[tail])->flag, BLOCK_BIT_BUSY))) {
+  reverse_pass_kernel(&block_buffer[next_block_index(tail)], &block_buffer[tail]);
+  }
 }
+ // EDITED 


 // The kernel called by recalculate() when scanning the plan from first to last entry.
 void Planner::forward_pass_kernel(const block_t* previous, block_t* const current) {
   if (!previous) return;

block_buffer_head is already increased?

[tcm0116]

else if ((movesplanned() = 3) && (!TEST(block_buffer[tail]->flag, BLOCK_BIT_BUSY))) {
  reverse_pass_kernel(block_buffer[next_block_index(tail)], block_buffer[tail);
}

This seems a bit dangerous since the movement is in process and could possibly finish before this finishes executing.

[thinkyhead]

I sort of like the idea of having a "hold for more segments" flag, for those instances where we _know_ there will be several segments added. That extra flag would tell Planner::_buffer_line not to split the first move in two, but instead, just don't call stepper.wake_up() unless there are >2 moves in the planner. The flag would be set when adding segments and cleared when done.

I have a patch for that concept which I can post shortly.

---

Planner::reverse_pass
block_buffer_head is already increased?

The head gets incremented after calculate_trapezoid_for_block but before recalculate. The last lines of _buffer_block are…

  calculate_trapezoid_for_block(block, block->entry_speed / block->nominal_speed, safe_speed / block->nominal_speed);
  block_buffer_head = next_buffer_head;
  COPY(position, target);
  recalculate();

---

This seems a bit dangerous since the movement is in process and could possibly finish before this finishes executing.

It might be, but also it seems like it wouldn't be effective. The tail block is the oldest one in the queue and during most of its lifetime it is BUSY. The very last chance to modify the tail block is when the stepper ISR calls get_current_block to start processing it. The ISR keeps the block BUSY while doing the steps, and finally increments the tail pointer when it finishes it. On the next ISR call it will start to process the new tail. That small space between ISRs is the only window where the tail won't be BUSY.

[thinkyhead]

a "hold for more segments" flag, for those instances where we know there will be several segments added

Here's what that looks like… https://github.com/MarlinFirmware/Marlin/pull/8608/commits/6f5e763f16f38d48767b92936b12da886e44cc76

[tcm0116]

Why not make doing_segmented_move a parameter to buffer_line that defaults
to false? This would eliminate all of the times you have to manually set it
to false.

And, as a redundancy to not calling stepper.wake_up(), you could return
NULL in get_current_block if (doing_segmented_move && movesplanned() <= 2).

[Roxy-3D]

Why not make doing_segmented_move a parameter to buffer_line that defaults
to false? This would eliminate all of the times you have to manually set it
to false.

Actually... It does better than that. If that extra parameter defaults to false that allows various pieces of code to control the behavior. As it turns out... only the very last move of UBL's motion routine changes. Everything else would get joined together.

      FINAL_MOVE:
      ...
      if (isnan(z0)) z0 = 0.0;

      planner._buffer_line(end[X_AXIS], end[Y_AXIS], end[Z_AXIS] + z0, end[E_AXIS], feed_rate, extruder);

      if (g26_debug_flag)
        debug_current_and_destination(PSTR("FINAL_MOVE in ubl.line_to_destination()"));

      set_current_from_destination();
      return;
    }

(Actually... there is one other place that changes. If the queue is full in the planner and a line can't be added, we probably want to kick off the move. Otherwise it could get stuck and wait forever.)

[AnHardt]

@tcm0116

else if ((movesplanned() = 3) && (!TEST((&block_buffer[tail])->flag, BLOCK_BIT_BUSY))) {
  reverse_pass_kernel(block_buffer[next_block_index(tail)], block_buffer[tail);
}

This seems a bit dangerous since the movement is in process and could possibly finish before this finishes executing.

Im relative sure !TEST((&block_buffer[tail])->flag, BLOCK_BIT_BUSY)) states "tail is not stepped jet" or
with your words "movement is not in progress". And stays that way until we start stepping here:

    _buffer_steps(between, fr_mm_s, extruder); 
  } 
  _buffer_steps(target, fr_mm_s, extruder); 

  stepper.wake_up(); // !!!!!!!!!!!

} // buffer_line() 

when we finished planing.

[thinkyhead]

Why not make doing_segmented_move a parameter to buffer_line that defaults to false? This would eliminate all of the times you have to manually set it to false.

Because that adds more overhead than having a global flag. The less any new code impacts performance the better.

[thinkyhead]

Im relative sure !TEST((&block_buffer[tail])->flag, BLOCK_BIT_BUSY)) states "tail is not stepped jet" or with your words "movement is not in progress". And stays that way until we start stepping here:

No, the BUSY flag is set at the moment the block is first grabbed inside the ISR. So, you have to prevent the stepper ISR from being called before you test the BUSY flag and you can only re-enable it when done modifying the block.

/**
 * The current block. NULL if the buffer is empty.
 * This also marks the block as busy.
 * WARNING: Called from Stepper ISR context!
 */
static block_t* get_current_block() {
  if (blocks_queued()) {
    block_t* block = &block_buffer[block_buffer_tail];
    #if ENABLED(ULTRA_LCD)
      block_buffer_runtime_us -= block->segment_time_us; // We can't be sure how long an active block will take, so don't count it.
    #endif
    SBI(block->flag, BLOCK_BIT_BUSY);
    return block;
  }
  else {
    #if ENABLED(ULTRA_LCD)
      clear_block_buffer_runtime(); // paranoia. Buffer is empty now - so reset accumulated time to zero.
    #endif
    return NULL;
  }
}

[thinkyhead]

IOW, it seems like this is needed to prevent the block from being grabbed and made BUSY after the bit is tested, but before reverse_pass_kernel gets called…

else if (movesplanned() == 3) {
  CRITICAL_SECTION_START;
    const uint8_t tail = block_buffer_tail;
    if (!TEST(block_buffer[tail].flag, BLOCK_BIT_BUSY))
      reverse_pass_kernel(block_buffer[next_block_index(tail)], block_buffer[tail]);
  CRITICAL_SECTION_END;
}

I'm not entirely up on how the stepper ISR manages speed through the move, but I think that once it starts processing a block, it could be bad to change the speed ramps… But maybe the block processor is more tolerant?

Or, is reverse_pass_kernel only changing the next block in the queue, making it safe even if the block starts?

[thinkyhead]

I note that the order of the blocks here is reversed from usual…

reverse_pass_kernel(block_buffer[next_block_index(tail)], block_buffer[tail]);

Should it be this instead?

reverse_pass_kernel(block_buffer[tail], block_buffer[next_block_index(tail)]);

I assume that next_block_index(tail) is the next block that would be processed after the next-or-active (tail) block.

Anyway, we shouldn't forget that block_buffer_tail is hard to catch in flight before the tail block goes BUSY. The tail block has a very short non-BUSY lifespan between ISRs, so will reverse_pass definitely be called at the appropriate time? We need 100% determinism. So, to review how the tail pointer works:

• When the planner is empty (and the stepper ISR is disabled) block_buffer_tail doesn't change, so it can be processed any time before the ISR wakes up.
• The block_buffer_head increments as soon as a block is added to the buffer. This allows the stepper ISR to grab the tail block next time it runs.
• The block_buffer_tail remains the same when the stepper ISR calls get_current_block and marks the block BUSY. The current tail block is (almost) always the one being processed.
• The block_buffer_tail advances at the end of the ISR when it's done stepping. The tail now points to the next (not yet busy) block. (If there is no next block it will be equal to block_buffer_head).

Can the idea be summed up as: Blocks placed in an empty buffer shouldn't be taken up by the ISR until they've been marked as having all their junctions worked out?

---

In terms of total processing, it probably would end up a bit less if it were possible to add several blocks to the planner before running the trapezoid generator on the whole group, instead of how it works now where it apparently always does a forward and reverse pass on each new junction. Putting aside the extra processing involved in creating these extra blocks, my little scheme of splitting up the first move into 2-3 smaller blocks does seem to already ("economically") fit the bill.

[AnHardt]

After finding

@@ -1234,11 +1234,11 @@ void Planner::_buffer_steps(const int32_t target[XYZE], float fr_mm_s, const uin
         safe_speed = maxj;
       }
     }
   }

-  if (moves_queued > 1 && !UNEAR_ZERO(previous_nominal_speed)) {
+  if (moves_queued && !UNEAR_ZERO(previous_nominal_speed)) {
     // Estimate a maximum velocity allowed at a joint of two successive segments.
     // If this maximum velocity allowed is lower than the minimum of the entry / exit safe velocities,
     // then the machine is not coasting anymore and the safe entry / exit velocities shall be used.

     // The junction velocity will be shared between successive segments. Limit the junction velocity to their minimum.

and disabling the stepper interrupt for planing the splitted move
```diff
@@ -1381,24 +1381,22 @@ void Planner::_buffer_line(const float &a, const float &b, const float &c, const

// DRYRUN ignores all temperature constraints and assures that the extruder is instantly satisfied
if (DEBUGGING(DRYRUN))
position[E_AXIS] = target[E_AXIS];

• // Always split the first move into one longer and one shorter move
• // Always split the first move into two
  if (!blocks_queued()) {
• constexpr int32_t prop[] = { 3, 4 };
• #define _BETWEEN(A) position[A##_AXIS] + ((target[A##_AXIS] - position[A##_AXIS]) * prop[0]) / prop[1]
• const int32_t between[XYZE] = { _BETWEEN(X), _BETWEEN(Y), _BETWEEN(Z), _BETWEEN(E) },
• xyzlen = SQRT(
• sq((between[X_AXIS] - position[X_AXIS]) * steps_to_mm[X_AXIS]) +
• sq((between[Y_AXIS] - position[Y_AXIS]) * steps_to_mm[Y_AXIS]) +
• sq((between[Z_AXIS] - position[Z_AXIS]) * steps_to_mm[Z_AXIS])
• );
• // Make sure this move takes no less than 0.0625s
• _buffer_steps(between, xyzlen ? min(fr_mm_s, xyzlen << 4) : fr_mm_s, extruder);
• DISABLE_STEPPER_DRIVER_INTERRUPT(); // There is no block to step anyway.
• #define _BETWEEN(A) position[A##_AXIS] + ((target[A##_AXIS] - position[A##_AXIS]) >> 1)
• const int32_t between[XYZE] = { _BETWEEN(X), _BETWEEN(Y), _BETWEEN(Z), _BETWEEN(E) };
• _buffer_steps(between, fr_mm_s, extruder);
• _buffer_steps(target, fr_mm_s, extruder);
• ENABLE_STEPPER_DRIVER_INTERRUPT();
• }
• else {
• _buffer_steps(target, fr_mm_s, extruder);
  }

• _buffer_steps(target, fr_mm_s, extruder);

  stepper.wake_up();

  } // _buffer_line()
  `` it started working reliably and as expected - even when my changes inreverse_pass()` are reverted.

Grbl added an additional variable where they store the index to where revers- and from where forward- passes and recalculations are meaningful.

[thinkyhead]

After finding …

That first change is interesting! Have we been overly-cautious up to now?

and disabling the stepper interrupt for planing the splitted move

That makes good sense. And now it's simple! Maximizes the chance of having two long-enough moves that they won't be auto-joined or dropped.

Grbl added an additional variable where they store the index to where revers- and from where forward- passes and recalculations are meaningful.

Interesting! Would we gain anything by following their example?

[thinkyhead]

@AnHardt — So, seeing as we fell back to your original idea, and it works well, I have no qualms about dropping the doing_segmented_move flag and assuming that there are no other complications. Essentially, it just needs the extra block, plus permission to chain them, plus a guarantee that the stepper ISR (even in slowest mode) won't steal the first block as soon as it's added. I think we have a winner. And the simpler the better. I will merge the simplified PRs shortly.

[thinkyhead]

Merged the very simplified #8608 and #8611. Please test and see if these help. In the process of following up on this issue (and #8573) some other bugs around the planner were discovered and fixed, old obsolete code was stripped, and some consolidation was done. Hopefully printing results will be better on several fronts, in addition to these fresh patches.

[AnHardt]

Have we been overly-cautious up to now?

No. When we know about having a first block ending at zero speed and knowing we can't alter it, it makes perfect sense to always start the second block at zero speed.
For a splitted first move this assumption simply is not valid anymore.

[oldmcg]

When I was measuring performance of UBL delta segmentation on 8-bit CPU I added some code to time each segment being added to planner queue.

Here is output from one run using feedrate of 50mm/s and delta_segments_per_second of 200, using long 70mm linear moves with only 4 direction reversals (real angle changes). The times are time it takes to add a move to the planner, ignoring times when planner is already full (depth 15) and waiting for steppers to catch up.

DeltaSegmentsPerSecond:      200
LastSegmentFeedrate:      50.000mm/s (0.833mm/m)
LastSegmentLength:         0.250mm
TimePerSegmentAtRate:      5.000ms
AvgDeltaKinetmatics:       0.321ms,   2240 samples
AvgBufferLineAtDepth[ 0]:  1.680ms,      2 samples
AvgBufferLineAtDepth[ 1]:  2.240ms,      2 samples
AvgBufferLineAtDepth[ 2]:  2.624ms,      2 samples
AvgBufferLineAtDepth[ 3]:  2.686ms,      2 samples
AvgBufferLineAtDepth[ 4]:  2.644ms,      2 samples
AvgBufferLineAtDepth[ 5]:  3.777ms,     20 samples
AvgBufferLineAtDepth[ 6]:  4.022ms,   1164 samples
AvgBufferLineAtDepth[ 7]:  3.957ms,     93 samples
AvgBufferLineAtDepth[ 8]:  3.978ms,     65 samples
AvgBufferLineAtDepth[ 9]:  4.022ms,     70 samples
AvgBufferLineAtDepth[10]:  4.025ms,     88 samples
AvgBufferLineAtDepth[11]:  4.071ms,     60 samples
AvgBufferLineAtDepth[12]:  4.061ms,     58 samples
AvgBufferLineAtDepth[13]:  4.157ms,     60 samples
AvgBufferLineAtDepth[14]:  4.301ms,    128 samples

AvgBufferLineNotFull:      4.032ms,   1816 samples
AvgBufferLineFull:         5.201ms,    424 samples
FullToNotRatio:            0.233

Note how quickly planner fills up to depth of 6 and then time to queue a move to planner increases to point (around 4ms) where can't really queue moves fast enough to stay ahead of steppers. The delta sqrt computations were frequently blamed, but they only account for around 0.3ms per segment. The real computational overhead is the planner queuing many segmented moves.

For a many-segmented move in a single linear direction, it doesn't make a lot of sense to do angle-based planner calculations. Even on a delta where an X/Y linear move can result in a tower stepper slowly coming to stop and then changing direction, the movement is fluid enough that I suspect all planner angle-changing computations could be simply skipped. Maybe the linear acceleration computations could also be streamlined for segmented moves.

I think adding planner queuing function to queue subsequent segmented moves in same linear direction as previous segment that would skip bulk of planner direction/speed change computations would greatly improve ability for higher segments per second without stuttering.

[tcm0116]

Even on a delta where an X/Y linear move can result in a tower stepper slowly coming to stop and then changing direction, the movement is fluid enough that I suspect all planner angle-changing computations could be simply skipped.

This is an interesting thought. However, there would still need to be at least some sort of detection of the change in direction for a Delta machine. Otherwise, the planner wouldn't know to decelerate for the change in direction. But, to your point, perhaps on Delta machines, we could replace the jerk computation with a simple check for the change in direction.

[oldmcg]

As the tower approaches the direction change due to linear x/y motion of head, it slows to almost no linear movement before changing direction and then smoothly accelerates the other way. This is with a constant speed X/Y linear motion.

I suspect that the X/Y feedrate necessary to cause a tower direction change to require acceleration limitation would be very large. So much so, that I think it's worth having a compile-time option to ignore completely and try it to see how many segments per second it will go without stuttering, and then see what X/Y feedrate it would take to cause excessive jerk in tower direction change.

Then the limit could be placed on max x/y feedrate instead of recomputing at every single buffered segment.

[thinkyhead]

The real computational overhead is the planner queuing many segmented moves.

The process of adding a single segment does seem to involve a lot of processing! I'm sure there are various opportunities to optimize, especially once we know where the greatest overhead comes from.

Note how quickly planner fills up to depth of 6 and then time to queue a move to planner increases to point (around 4ms)

Interesting. The first move is cheapest at 1.68ms, then the next 4 are around 2.5ms, then the 5th jumps up to 3.7ms, then the rest take around 4ms. I assume a lot of that time is taken up by the trapezoid generator. It looks like there is extra junction scanning, forward and reverse, that keeps costing more until you have about 6 blocks in the planner.

where can't really queue moves fast enough to stay ahead of steppers.

Meaning the individual segments are taking about 4ms each to finish, I guess… Of course this is going to be variable depending on config settings like segments-per-second. If the segments take too little time the planner will get starved, and if they take much longer it starts to limit segments-per-second.

---

Optimization Opportunities

It would be good to find out, what is the most costly aspect of adding a new move to the planner. Is it the junction handling? If so, are there calculations that can be cached in the blocks so they don't need to be repeated?

The delta sqrt computations … only account for around 0.3ms per segment

If the delta calculations don't cost too much that's good. My guess is that the biggest cost probably comes from scanning through the block buffers, which aren't efficiently cached by the CPU. It might cost less time in the junction calculations if that information was stored in its own buffer separate from the blocks.

---

I see that every segment added to the planner (with XY movement) does a costly length calculation:

block->millimeters = SQRT(
  #if CORE_IS_XY
    sq(delta_mm[X_HEAD]) + sq(delta_mm[Y_HEAD]) + sq(delta_mm[Z_AXIS])
  #elif CORE_IS_XZ
    sq(delta_mm[X_HEAD]) + sq(delta_mm[Y_AXIS]) + sq(delta_mm[Z_HEAD])
  #elif CORE_IS_YZ
    sq(delta_mm[X_AXIS]) + sq(delta_mm[Y_HEAD]) + sq(delta_mm[Z_HEAD])
  #else
    sq(delta_mm[X_AXIS]) + sq(delta_mm[Y_AXIS]) + sq(delta_mm[Z_AXIS])
  #endif
);

This calculation can be skipped by having the caller include the mm length of the move in the block when it is already known (as it is with segmented moves). It might even make sense to pass in the delta_mm values, since these can be invariant when doing segmented straight lines.

[thinkyhead]

see what X/Y feedrate it would take to cause excessive jerk in tower direction change.

Inertia in the effector has to be taken into account too. Even when the tower carriages are all moving smoothly, fast direction changes in the effector may still lead to excessive jerkiness and some loss of accuracy at the end of the nozzle.

[thinkyhead]

Apparently the changes I committed weren't so safe after all, and are causing weird issues. I'll revert them for now until we figure out how to do this "split first planner move" patch in a way that doesn't lead to any weird side-effects.

[thinkyhead]

One of these changes might solve the issue. Please try each one and see if it helps:

- if (moves_queued && !UNEAR_ZERO(previous_nominal_speed)) {
+ if (moves_queued > 1 && !UNEAR_ZERO(previous_nominal_speed)) {

---

   // Always split the first move in two so it can chain
   if (!blocks_queued()) {
+    previous_nominal_speed = 0;
     DISABLE_STEPPER_DRIVER_INTERRUPT();

---

-   #define _BETWEEN(A) (position[A##_AXIS] + target[A##_AXIS]) >> 1
+   #define _BETWEEN(A) (position[A##_AXIS] + target[A##_AXIS]) / 2

Since I've reverted the changes in bugfix, you can start with one of these branches:

• https://github.com/thinkyhead/Marlin/tree/backup_1_split_first
• https://github.com/thinkyhead/Marlin/tree/backup_2_split_first

[thinkyhead]

I've applied patches from @hg42 to those branches, and they are now posted as PRs. They are linked just above this comment.

[AnHardt]

When buffer empty split the first move in half. -> Unknown consequences! (But maybe.)

One of the unknown, or better, not thought about, consequences is
splitting every move after a stepper.synchronize().
This might disturb homing and probing when the stop/probe is triggered in the first part and the other one is still in the buffer..
So if that breaks think about this first.

[Roxy-3D]

This might disturb homing and probing. So if that breaks think about this first.

Homing and probing is a 'special case'. In general, there should only be Z-Axis movement on these moves. So perhaps it makes sense to not split those moves??? Or in different words, the actual probe operation can not cross a mesh cell boundary. It is only moving the Z-Axis. So there is no purpose to splitting that movement nor trying to join it with a subsequent movement.

[AnHardt]

Maybe a 'split' parameter of '_buffer_line()' defaulting to 'true' and called with 'false' in the few cases where it matters is the way with the least changes.

[Roxy-3D]

Maybe a 'split' parameter of '_buffer_line()' defaulting to 'true' and called with 'false' in the few cases where it matters is the way with the least changes.

I would vote in favor of this implementation. And just for testing... It would be easy to turn all splitting off if issues show up in the future.

[tcm0116]

I'm just thinking out loud here, but what if instead if splitting the first move after a stop in half, we split it up a little more intelligently. Here's the trapezoid for a move:

| __ |
|/  \|

Within this trapezoid, there's the acceleration, constant velocity, and deceleration sections. The issue we're seeing is that if a second move is added after the first movement starts but before it finishes, the planner is unable to chain them together, resulting in the following:

| __ | __ |
|/  \|/  \|

Ideally, for a straight line, we would want these to be chained together to look like:

| ____ |
|/    \|

The issue with the proposed solution is that we're attempting to split up the first movement to allow the planner to chain them together. However, the planner still has the limitation of not being able to chain the first two movements together due to the way the recalculate() function is designed and implemented. In order to allow the planner to be able to chain the first two commanded movements together, we need to put three movements in the buffer. The trick here is that the "split" first movement has to already be optimized since recalculate() is not going to do it for us. In order to achieve this, I would like to propose the following.

When we look at the first movement after a stop, the acceleration and constant velocity (if applicable) sections of the movement can be safely executed without further processing. However, it's the deceleration section that is considered volatile since it could potentially be replaced with a constant velocity section in the event of two consecutive straight lines, or the deceleration curve reduced in the event of a change of direction less than 90 degrees. Therefore, I propose that we split the first movement into two sections, with the split being at the start of the deceleration section:

Original first move:
| __ |
|/  \|

Split first move:
| _ |  |
|/ \|/\|

Pre-optimized split first move:
| __| |
|/  |\|

Unoptimized (split) first and second movements:
| __| | __ |
|/  |\|/  \|

Optimized (split) first and second movements:
| __|_|___ |
|/  | |   \|

The trick here is that the first half of the first move wouldn't have any deceleration in its block, and the second half of the split move would start at the ending velocity of the first half. This is different than the current approaches since each segment ends up with an acceleration and deceleration section that need to be optimized by recalculate(), which can't be done without a complete overhaul of recalculate().

By pre-optimizing these first two segments, we eliminate the need to even run recalculate() until the third segment, which is how it already works. At that point, if the third segment (i.e. the second commanded movement) can be optimized with the end of the first commanded movement, then the optimization can take place as it currently does. Another benefit to this solution is that we don't have to play any games with the stepper ISR. So long as the second commanded movement is processed before the second segment starts (i.e. the deceleration portion of the first commanded movement), then the optimization can occur. Granted, if the second commanded movement arrives later than needed, there will be a stop between the two commanded movements, but I don't see how that can be solved since we can't really guess what the second commanded movement will be.

Unfortunately, I don't have to to attempt to implement this until next week, but I've been thinking about it all day, and wanted to get it out there for the smart folks in this group to chew on.

[Roxy-3D]

The trick here is that the first half of the first move wouldn't have any deceleration in its block, and the second half of the split move would start at the ending velocity of the first half. This is different than the current approaches since each segment ends up with an acceleration and deceleration section that need to be optimized by recalculate()

I agree. This path has a lot of merit. Let's all think about this. I don't think this will be very difficult to code up and debug.

[AnHardt]

Maybe a 'split' parameter of '_buffer_line()' defaulting to 'true' and called with 'false' in the few cases where it matters is the way with the least changes.

Too difficult. :-(
During probing do_blocking_move_to_z() is used. That uses about any kind of move where the parameter had to be propagated thru.
Now looking how a 'global' would work.

[AnHardt]

The global works surprisingly well because it can be set/reset in bracket_probe_move() (aka setup_for_endstop_or_probe_move() and clean_up_after_endstop_or_probe_move() )

planner.h

@@ -163,10 +163,11 @@ class Planner {
                  acceleration,         // Normal acceleration mm/s^2  DEFAULT ACCELERATION for all printing moves. M204 SXXXX
                  retract_acceleration, // Retract acceleration mm/s^2 filament pull-back and push-forward while standing still in the other axes M204 TXXXX
                  travel_acceleration,  // Travel acceleration mm/s^2  DEFAULT ACCELERATION for all NON printing moves. M204 MXXXX
                  max_jerk[XYZE],       // The largest speed change requiring no acceleration
                  min_travel_feedrate_mm_s;
+    static bool split_first_move;

     #if HAS_LEVELING
       static bool leveling_active;          // Flag that bed leveling is enabled
       #if ABL_PLANAR
         static matrix_3x3 bed_level_matrix; // Transform to compensate for bed level

planer.cpp

@@ -101,10 +101,12 @@ float Planner::max_feedrate_mm_s[XYZE_N], // Max speeds in mm per second

 #if ENABLED(DISTINCT_E_FACTORS)
   uint8_t Planner::last_extruder = 0;     // Respond to extruder change
 #endif

+bool Planner::split_first_move = true;
+
 int16_t Planner::flow_percentage[EXTRUDERS] = ARRAY_BY_EXTRUDERS1(100); // Extrusion factor for each extruder

 float Planner::e_factor[EXTRUDERS],               // The flow percentage and volumetric multiplier combine to scale E movement
       Planner::filament_size[EXTRUDERS],          // diameter of filament (in millimeters), typically around 1.75 or 2.85, 0 disables the volumetric calculations for the extruder
       Planner::volumetric_area_nominal = CIRCLE_AREA((DEFAULT_NOMINAL_FILAMENT_DIA) * 0.5), // Nominal cross-sectional area
@@ -1442,12 +1444,12 @@ void Planner::_buffer_line(const float &a, const float &b, const float &c, const

   // DRYRUN ignores all temperature constraints and assures that the extruder is instantly satisfied
   if (DEBUGGING(DRYRUN))
     position[E_AXIS] = target[E_AXIS];

-  // Always split the first move into one longer and one shorter move
-  if (!blocks_queued()) {
+  // Always split the first move into two (if not homing or probing)
+  if (!blocks_queued() && split_first_move) {
     #define _BETWEEN(A) (position[A##_AXIS] + target[A##_AXIS]) >> 1
     const int32_t between[XYZE] = { _BETWEEN(X), _BETWEEN(Y), _BETWEEN(Z), _BETWEEN(E) };
     DISABLE_STEPPER_DRIVER_INTERRUPT();
     _buffer_steps(between, fr_mm_s, extruder);
     _buffer_steps(target, fr_mm_s, extruder);

motion.cpp

@@ -424,15 +424,17 @@ void bracket_probe_move(const bool before) {
   if (before) {
     saved_feedrate_mm_s = feedrate_mm_s;
     saved_feedrate_percentage = feedrate_percentage;
     feedrate_percentage = 100;
     gcode.refresh_cmd_timeout();
+    planner.split_first_move = false;
   }
   else {
     feedrate_mm_s = saved_feedrate_mm_s;
     feedrate_percentage = saved_feedrate_percentage;
     gcode.refresh_cmd_timeout();
+    planner.split_first_move = true;
   }
 }

 void setup_for_endstop_or_probe_move() { bracket_probe_move(true); }
 void clean_up_after_endstop_or_probe_move() { bracket_probe_move(false); }

[thinkyhead]

Another idea is to simply have the stepper ISR throw away the rest of the blocks when it triggers an endstop or probe (which it should do anyway). There's a stepper variable (cleaning_buffer_counter) that, when set, causes the stepper ISR to throw away blocks until it counts down to zero. This would cover all future endstop/probing situations.

 void Stepper::endstop_triggered(AxisEnum axis) {
   . . .
   kill_current_block();
+  cleaning_buffer_counter = BLOCK_BUFFER_SIZE - 1;
 }

[AnHardt]

@thinkyhead
Ingenios. Compared to my attempt this is pointing directly to the target instead of "carpet bombing".

We'll see if the homing/probing issues come down to a normal level now. I hope they are just caused by the COPY() problem. But now we should be save here.

[AnHardt]

I'm just thinking out loud here, but what if instead if splitting the first move after a stop in half, we split it up a little more intelligently. Here's the trapezoid for a move:

| __ |
|/  \|

There is another case where the plateau is not reached because the move is too short or the wanted speed is too high or the acceleration too low. In these cases the speed just ramps up and down. Splitting in the mid. for this type of moves is close to ideal. (and the calculation is sooo cheap.)

However, the planner still has the limitation of not being able to chain the first two movements together due to the way the recalculate() function is designed and implemented. In order to allow the planner to be able to chain the first two commanded movements together, we need to put three movements in the buffer. The trick here is that the "split" first movement has to already be optimized since recalculate() is not going to do it for us. In order to achieve this, I would like to propose the following.

My tests tell another story, especially when the plateau is reached in the first step all seems to be well.

G-code Test

; Unchanged Configuration.h
; Test g-code:
G0 X10 F2000
G0 X20 
G0 X30
G0 X40
G0 X50
G0 X60
G0 X70
G0 X80
G0 X90
G0 X80
G0 X70
G0 X60
G0 X50
G0 X40
G0 X30
G0 X20
G0 X10
G0 X0

Results

"^" -> calculate_trapezoid_for_block(
"<" -> reverse_pass_kernel(
">" -> forward_pass_kernel(
"/" -> block with BLOCK_BIT_START_FROM_FULL_HALT
"X" ->block with BLOCK_BIT_BUSY
"-" -> BLOCK_BIT_NOMINAL_LENGTH (can reach wanted speed)
Numbers are initial_rate,nominal_rate,final_rate
testresult:
00:23:15.322 : ^^,^>^^
00:23:15.322 : echo:0:2; /- 1601,2667,2667
00:23:15.322 : echo:1:2;  - 2667,2667,120
00:23:15.338 : ^>>^^
00:23:15.338 : echo:0:3;X/- 1601,2667,2667
00:23:15.338 : echo:1:3;  - 2667,2667,2667
00:23:15.338 : echo:2:3;  - 2667,2667,120
00:23:15.338 : ^>>>^^
00:23:15.338 : echo:0:4;X/- 1601,2667,2667
00:23:15.338 : echo:1:4;  - 2667,2667,2667
00:23:15.338 : echo:2:4;  - 2667,2667,2667
00:23:15.338 : echo:3:4;  - 2667,2667,120
00:23:15.353 : ^>>>>^^
00:23:15.353 : echo:0:5;X/- 1601,2667,2667
00:23:15.353 : echo:1:5;  - 2667,2667,2667
00:23:15.353 : echo:2:5;  - 2667,2667,2667
00:23:15.353 : echo:3:5;  - 2667,2667,2667
00:23:15.353 : echo:4:5;  - 2667,2667,120
00:23:15.353 : ^<>>>>>^^
00:23:15.353 : echo:0:6;X/- 1601,2667,2667
00:23:15.353 : echo:1:6;  - 2667,2667,2667
00:23:15.353 : echo:2:6;  - 2667,2667,2667
00:23:15.369 : echo:3:6;  - 2667,2667,2667
00:23:15.369 : echo:4:6;  - 2667,2667,2667
00:23:15.369 : echo:5:6;  - 2667,2667,120
00:23:15.369 : ^<<>>>>>>^^
00:23:15.369 : echo:0:7;X/- 1601,2667,2667
00:23:15.369 : echo:1:7;  - 2667,2667,2667
00:23:15.369 : echo:2:7;  - 2667,2667,2667
00:23:15.369 : echo:3:7;  - 2667,2667,2667
00:23:15.369 : echo:4:7;  - 2667,2667,2667
00:23:15.369 : echo:5:7;  - 2667,2667,2667
00:23:15.385 : echo:6:7;  - 2667,2667,120
00:23:15.385 : ^<<<>>>>>>>^^
00:23:15.385 : echo:0:8;X/- 1601,2667,2667
00:23:15.385 : echo:1:8;  - 2667,2667,2667
00:23:15.385 : echo:2:8;  - 2667,2667,2667
00:23:15.385 : echo:3:8;  - 2667,2667,2667
00:23:15.385 : echo:4:8;  - 2667,2667,2667
00:23:15.385 : echo:5:8;  - 2667,2667,2667
00:23:15.385 : echo:6:8;  - 2667,2667,2667
00:23:15.400 : echo:7:8;  - 2667,2667,120
00:23:15.400 : ^<<<<>>>>>>>>^^
00:23:15.400 : echo:0:9;X/- 1601,2667,2667
00:23:15.400 : echo:1:9;  - 2667,2667,2667
00:23:15.400 : echo:2:9;  - 2667,2667,2667
00:23:15.400 : echo:3:9;  - 2667,2667,2667
00:23:15.400 : echo:4:9;  - 2667,2667,2667
00:23:15.400 : echo:5:9;  - 2667,2667,2667
00:23:15.400 : echo:6:9;  - 2667,2667,2667
00:23:15.400 : echo:7:9;  - 2667,2667,2667
00:23:15.417 : echo:8:9;  - 2667,2667,120
00:23:15.419 : ^<<<<<>>>>>>>>>^^
00:23:15.420 : echo:0:10;X/- 1601,2667,2667
00:23:15.423 : echo:1:10;  - 2667,2667,2667
00:23:15.424 : echo:2:10;  - 2667,2667,2667
00:23:15.426 : echo:3:10;  - 2667,2667,2667
00:23:15.428 : echo:4:10;  - 2667,2667,2667
00:23:15.428 : echo:5:10;  - 2667,2667,2667
00:23:15.429 : echo:6:10;  - 2667,2667,2667
00:23:15.431 : echo:7:10;  - 2667,2667,2667
00:23:15.432 : echo:8:10;  - 2667,2667,2667
00:23:15.435 : echo:9:10;  - 2667,2667,120
00:23:15.437 : ^<<<<<<>>>>>>>>>>^^
00:23:15.439 : echo:0:11;X/- 1601,2667,2667
00:23:15.441 : echo:1:11;  - 2667,2667,2667
00:23:15.442 : echo:2:11;  - 2667,2667,2667
00:23:15.444 : echo:3:11;  - 2667,2667,2667
00:23:15.446 : echo:4:11;  - 2667,2667,2667
00:23:15.447 : echo:5:11;  - 2667,2667,2667
00:23:15.447 : echo:6:11;  - 2667,2667,2667
00:23:15.449 : echo:7:11;  - 2667,2667,2667
00:23:15.450 : echo:8:11;  - 2667,2667,2667
00:23:15.452 : echo:9:11;  - 2667,2667,1601
00:23:15.454 : echo:10:11; /- 1601,2667,120
00:23:15.454 : ^<<<<<<<>>>>>>>>>>>^^
00:23:15.454 : echo:0:12;X/- 1601,2667,2667
00:23:15.454 : echo:1:12;  - 2667,2667,2667
00:23:15.454 : echo:2:12;  - 2667,2667,2667
00:23:15.454 : echo:3:12;  - 2667,2667,2667
00:23:15.454 : echo:4:12;  - 2667,2667,2667
00:23:15.454 : echo:5:12;  - 2667,2667,2667
00:23:15.454 : echo:6:12;  - 2667,2667,2667
00:23:15.454 : echo:7:12;  - 2667,2667,2667
00:23:15.470 : echo:8:12;  - 2667,2667,2667
00:23:15.470 : echo:9:12;  - 2667,2667,1601
00:23:15.470 : echo:10:12; /- 1601,2667,2667
00:23:15.470 : echo:11:12;  - 2667,2667,120
00:23:15.470 : ^<<<<<<<<>>>>>>>>>>>>^^
00:23:15.470 : echo:0:13;X/- 1601,2667,2667
00:23:15.470 : echo:1:13;  - 2667,2667,2667
00:23:15.470 : echo:2:13;  - 2667,2667,2667
00:23:15.470 : echo:3:13;  - 2667,2667,2667
00:23:15.486 : echo:4:12;  - 2667,2667,2667
00:23:15.486 : echo:5:12;  - 2667,2667,2667
00:23:15.486 : echo:6:12;  - 2667,2667,2667
00:23:15.486 : echo:7:12;  - 2667,2667,2667
00:23:15.486 : echo:8:12;  - 2667,2667,2667
00:23:15.486 : echo:9:12;  - 2667,2667,1601
00:23:15.486 : echo:10:12; /- 1601,2667,2667
00:23:15.486 : echo:11:12;  - 2667,2667,2667
00:23:15.486 : echo:12:12;  - 2667,2667,120
00:23:15.501 : ^>>>>>>>>>>>>^^
00:23:15.501 : echo:1:13;X - 2667,2667,2667
00:23:15.501 : echo:2:13;  - 2667,2667,2667
00:23:15.501 : echo:3:13;  - 2667,2667,2667
00:23:15.501 : echo:4:13;  - 2667,2667,2667
00:23:15.501 : echo:5:13;  - 2667,2667,2667
00:23:15.501 : echo:6:13;  - 2667,2667,2667
00:23:15.501 : echo:7:13;  - 2667,2667,2667
00:23:15.501 : echo:8:13;  - 2667,2667,2667
00:23:15.501 : echo:9:13;  - 2667,2667,1601
00:23:15.501 : echo:10:13; /- 1601,2667,2667
00:23:15.517 : echo:11:13;  - 2667,2667,2667
00:23:15.517 : echo:12:13;  - 2667,2667,2667
00:23:15.517 : echo:13:13;  - 2667,2667,120
00:23:15.517 : ^>>>>>>>>>>>>>^^
00:23:15.517 : echo:1:14;X - 2667,2667,2667
00:23:15.517 : echo:2:14;  - 2667,2667,2667
00:23:15.517 : echo:3:14;  - 2667,2667,2667
00:23:15.517 : echo:4:14;  - 2667,2667,2667
00:23:15.533 : echo:5:14;  - 2667,2667,2667
00:23:15.533 : echo:6:14;  - 2667,2667,2667
00:23:15.533 : echo:7:14;  - 2667,2667,2667
00:23:15.533 : echo:8:14;  - 2667,2667,2667
00:23:15.533 : echo:9:14;  - 2667,2667,1601
00:23:15.533 : echo:10:14; /- 1601,2667,2667
00:23:15.533 : echo:11:14;  - 2667,2667,2667
00:23:15.533 : echo:12:14;  - 2667,2667,2667
00:23:15.533 : echo:13:14;  - 2667,2667,2667
00:23:15.533 : echo:14:14;  - 2667,2667,120
00:23:15.548 : ^<>>>>>>>>>>>>>>^^
00:23:15.548 : echo:1:15;X - 2667,2667,2667
00:23:15.548 : echo:2:15;  - 2667,2667,2667
00:23:15.548 : echo:3:15;  - 2667,2667,2667
00:23:15.548 : echo:4:15;  - 2667,2667,2667
00:23:15.548 : echo:5:15;  - 2667,2667,2667
00:23:15.548 : echo:6:15;  - 2667,2667,2667
00:23:15.548 : echo:7:15;  - 2667,2667,2667
00:23:15.548 : echo:8:15;  - 2667,2667,2667
00:23:15.548 : echo:9:15;  - 2667,2667,1601
00:23:15.548 : echo:10:15; /- 1601,2667,2667
00:23:15.564 : echo:11:15;  - 2667,2667,2667
00:23:15.564 : echo:12:15;  - 2667,2667,2667
00:23:15.564 : echo:13:15;  - 2667,2667,2667
00:23:15.564 : echo:14:15;  - 2667,2667,2667
00:23:15.564 : echo:15:15;  - 2667,2667,120
00:23:15.626 : ^<<>>>>>>>>>>>>>>^^
00:23:15.626 : echo:2:15;X - 2667,2667,2667
00:23:15.642 : echo:3:15;  - 2667,2667,2667
00:23:15.642 : echo:4:15;  - 2667,2667,2667
00:23:15.642 : echo:5:15;  - 2667,2667,2667
00:23:15.642 : echo:6:15;  - 2667,2667,2667
00:23:15.642 : echo:7:15;  - 2667,2667,2667
00:23:15.642 : echo:8:15;  - 2667,2667,2667
00:23:15.642 : echo:9:15;  - 2667,2667,1601
00:23:15.642 : echo:10:15; /- 1601,2667,2667
00:23:15.642 : echo:11:15;  - 2667,2667,2667
00:23:15.642 : echo:12:15;  - 2667,2667,2667
00:23:15.642 : echo:13:15;  - 2667,2667,2667
00:23:15.658 : echo:14:15;  - 2667,2667,2667
00:23:15.658 : echo:15:15;  - 2667,2667,2667
00:23:15.658 : echo:0:15;  - 2667,2667,120
00:23:15.934 : ^<<<>>>>>>>>>>>>>>^^
00:23:15.934 : echo:3:15;X - 2667,2667,2667
00:23:15.934 : echo:4:15;  - 2667,2667,2667
00:23:15.934 : echo:5:15;  - 2667,2667,2667
00:23:15.934 : echo:6:15;  - 2667,2667,2667
00:23:15.934 : echo:7:15;  - 2667,2667,2667
00:23:15.950 : echo:8:15;  - 2667,2667,2667
00:23:15.950 : echo:9:15;  - 2667,2667,1601
00:23:15.950 : echo:10:15; /- 1601,2667,2667
00:23:15.950 : echo:11:15;  - 2667,2667,2667
00:23:15.950 : echo:12:15;  - 2667,2667,2667
00:23:15.950 : echo:13:15;  - 2667,2667,2667
00:23:15.950 : echo:14:15;  - 2667,2667,2667
00:23:15.950 : echo:15:15;  - 2667,2667,2667
00:23:15.950 : echo:0:15;  - 2667,2667,2667
00:23:15.950 : echo:1:15;  - 2667,2667,120
00:23:16.243 : ^<<<<>>>>>>>>>>>>>>^^
00:23:16.244 : echo:4:15;X - 2667,2667,2667
00:23:16.246 : echo:5:15;  - 2667,2667,2667
00:23:16.247 : echo:6:15;  - 2667,2667,2667
00:23:16.249 : echo:7:15;  - 2667,2667,2667
00:23:16.251 : echo:8:15;  - 2667,2667,2667
00:23:16.252 : echo:9:15;  - 2667,2667,1601
00:23:16.255 : echo:10:15; /- 1601,2667,2667
00:23:16.255 : echo:11:15;  - 2667,2667,2667
00:23:16.255 : echo:12:15;  - 2667,2667,2667
00:23:16.255 : echo:13:15;  - 2667,2667,2667
00:23:16.255 : echo:14:15;  - 2667,2667,2667
00:23:16.255 : echo:15:15;  - 2667,2667,2667
00:23:16.255 : echo:0:15;  - 2667,2667,2667
00:23:16.255 : echo:1:15;  - 2667,2667,2667
00:23:16.255 : echo:2:15;  - 2667,2667,120

Backward scan ("<") begins a bit late but is not needed at all here

If the "nominal_rate" is not reached things currently look like:

Results 2

Same config.
Same g-code but F20000

00:50:59.697 : ^^,^>^^
00:50:59.697 : echo:0:2; /  1601,24000,13857
00:50:59.697 : echo:1:2;    13857,24000,120
00:50:59.697 : ^>>^^
00:50:59.697 : echo:0:3;X/  1601,24000,13857
00:50:59.697 : echo:1:3;    13857,24000,19596
00:50:59.697 : echo:2:3;    19596,24000,120
00:50:59.713 : ^>>>^^
00:50:59.713 : echo:0:4;X/  1601,24000,13857
00:50:59.713 : echo:1:4;    13857,24000,19596
00:50:59.713 : echo:2:4;    19596,24000,19596
00:50:59.713 : echo:3:4;    19596,24000,120
00:50:59.713 : ^>>>>^^
00:50:59.729 : echo:0:5;X/  1601,24000,13857
00:50:59.729 : echo:1:5;    13857,24000,19596
00:50:59.729 : echo:2:5;    19596,24000,19596
00:50:59.729 : echo:3:5;    19596,24000,19596
00:50:59.729 : echo:4:5;    19596,24000,120
00:50:59.729 : ^<>>>>>^^^^
00:50:59.744 : echo:0:6;X/  1601,24000,13857
00:50:59.744 : echo:1:6;    13949,24000,19596
00:50:59.744 : echo:2:6;    19596,24000,19596
00:50:59.744 : echo:3:6;    19596,24000,19596
00:50:59.744 : echo:4:6;    19596,24000,19596
00:50:59.744 : echo:5:5;    19596,24000,120
00:50:59.760 : ^<>>>>>^^^^
00:50:59.760 : echo:1:6;X   13949,24000,19596
00:50:59.760 : echo:2:6;    19662,24000,19596
00:50:59.775 : echo:3:6;    19596,24000,19596
00:50:59.775 : echo:4:6;    19596,24000,19596
00:50:59.775 : echo:5:5;    19596,24000,19596
00:50:59.775 : echo:6:5;    19596,24000,120
00:50:59.791 : ^<>>>>>^^^^
00:50:59.791 : echo:2:6;X   19662,24000,19596
00:50:59.791 : echo:3:6;    24000,24000,19596
00:50:59.791 : echo:4:6;    19596,24000,19596
00:50:59.807 : echo:5:6;    19596,24000,19596
00:50:59.807 : echo:6:6;    19596,24000,19596
00:50:59.807 : echo:7:6;    19596,24000,120
00:50:59.807 : ^<>>>>>^^^^
00:50:59.824 : echo:3:6;X   24000,24000,19596
00:50:59.827 : echo:4:6;    24000,24000,19596
00:50:59.830 : echo:5:6;    19596,24000,19596
00:50:59.834 : echo:6:6;    19596,24000,19596
00:50:59.837 : echo:7:6;    19596,24000,19596
00:50:59.839 : echo:8:6;    19596,24000,120
00:50:59.848 : ^<<>>>>>>^^^^
00:50:59.851 : echo:3:7;X   24000,24000,19596
00:50:59.854 : echo:4:6;X   24000,24000,24000
00:50:59.858 : echo:5:6;    24000,24000,19596
00:50:59.861 : echo:6:6;    19596,24000,19596
00:50:59.862 : echo:7:6;    19596,24000,19596
00:50:59.862 : echo:8:6;    19596,24000,19596
00:50:59.862 : echo:9:6;    19596,24000,120
00:50:59.877 : ^<<>>>>>>^^^^
00:50:59.877 : echo:4:7;X   24000,24000,24000
00:50:59.877 : echo:5:7;    24000,24000,24000
00:50:59.877 : echo:6:6;    24000,24000,19596
00:50:59.877 : echo:7:6;    19596,24000,19596
00:50:59.877 : echo:8:6;    19596,24000,19596
00:50:59.893 : echo:9:6;    19596,24000,1601
00:50:59.893 : echo:10:6; /  1601,24000,120
00:50:59.909 : ^<<>>>>>>^^^^
00:50:59.909 : echo:5:7;X   24000,24000,24000
00:50:59.909 : echo:6:7;    24000,24000,24000
00:50:59.909 : echo:7:7;    24000,24000,19596
00:50:59.909 : echo:8:6;    19596,24000,19596
00:50:59.909 : echo:9:6;    19596,24000,1601
00:50:59.924 : echo:10:6; /  1601,24000,19596
00:50:59.924 : echo:11:6;    19596,24000,120
00:50:59.924 : ^<<>>>>>>^^^^
00:50:59.940 : echo:6:7;X   24000,24000,24000
00:50:59.940 : echo:7:7;    24000,24000,24000
00:50:59.940 : echo:8:7;    24000,24000,19596
00:50:59.940 : echo:9:7;    19596,24000,1601
00:50:59.940 : echo:10:7; /  1601,24000,19596
00:50:59.956 : echo:11:6;    19596,24000,19596
00:50:59.956 : echo:12:6;    19596,24000,120
00:50:59.956 : ^>>>>>>^^
00:50:59.956 : echo:7:7;X   24000,24000,24000
00:50:59.971 : echo:8:7;    24000,24000,19596
00:50:59.971 : echo:9:7;    19596,24000,1601
00:50:59.971 : echo:10:7; /  1601,24000,19596
00:50:59.971 : echo:11:7;    19596,24000,19596
00:50:59.971 : echo:12:7;    19596,24000,19596
00:50:59.971 : echo:13:6;    19596,24000,120
00:50:59.987 : ^>>>>>>^^
00:50:59.987 : echo:8:7;X   24000,24000,19596
00:50:59.987 : echo:9:7;    19596,24000,1601
00:51:00.002 : echo:10:7; /  1601,24000,19596
00:51:00.002 : echo:11:7;    19596,24000,19596
00:51:00.002 : echo:12:7;    19596,24000,19596
00:51:00.002 : echo:13:7;    19596,24000,19596
00:51:00.002 : echo:14:7;    19596,24000,120
00:51:00.018 : ^<>>>>>>^^^^
00:51:00.018 : echo:9:7;X   19596,24000,1601
00:51:00.034 : echo:10:7; /  1601,24000,19662
00:51:00.034 : echo:11:7;    19662,24000,19596
00:51:00.034 : echo:12:7;    19596,24000,19596
00:51:00.034 : echo:13:7;    19596,24000,19596
00:51:00.034 : echo:14:7;    19596,24000,19596
00:51:00.034 : echo:15:7;    19596,24000,120
00:51:00.049 : ^<<>>>>>>>^^^^^
00:51:00.049 : echo:9:8;X   19596,24000,1601
00:51:00.049 : echo:10:8; /  1601,24000,19662
00:51:00.049 : echo:11:8;    19662,24000,24000
00:51:00.049 : echo:12:8;    24000,24000,19596
00:51:00.049 : echo:13:8;    19596,24000,19596
00:51:00.065 : echo:14:8;    19596,24000,19596
00:51:00.065 : echo:15:8;    19596,24000,19596
00:51:00.065 : echo:0:8;    19596,24000,120
00:51:00.065 : ^<<<>>>>>>>>^^^^^^
00:51:00.065 : echo:9:9;X   19596,24000,1601
00:51:00.081 : echo:10:9; /  1601,24000,19662
00:51:00.081 : echo:11:9;    19662,24000,24000
00:51:00.081 : echo:12:9;    24000,24000,24000
00:51:00.081 : echo:13:9;    24000,24000,19596
00:51:00.081 : echo:14:9;    19596,24000,19596
00:51:00.081 : echo:15:9;    19596,24000,19596
00:51:00.081 : echo:0:9;    19596,24000,19596
00:51:00.081 : echo:1:9;    19596,24000,120

Even here the backward scan starts late, but fast enough to get a acceleration up to "nominal_rate".

But there are other interesting things

00:50:59.824 : echo:3:6;X   24000,24000,19596
00:50:59.827 : echo:4:6;    24000,24000,19596
final_rate != initial_rate

00:50:59.877 : echo:4:7;X   24000,24000,24000
00:50:59.877 : echo:5:7;    24000,24000,24000
buffer lines with continuous speeds at "nominal_rate" not marked with  BLOCK_BIT_NOMINAL_LENGTH

Splitting in 3 parts makes no sense to me.
Splitting at the start of the deceleration ramp makes no sense to me. Either nominal_rate is reached - and all is well with the current code, or the ideal split for a doubled move is about in the mid.

More interesting to me, is to match what the code does while recalculating with my expectations, or the other way around. I simply currently neither understand what's going on nor what should go on. :-(

Give me some days. A flu isn't helpful when wanting to think.

Testcode based on bugfix-2.0.x at https://github.com/AnHardt/Marlin/pull/80/commits/c4bdcd898709b9b3eb4a18055cab0f95683d6813
now
https://github.com/AnHardt/Marlin/pull/80/commits/2a8d5c0f4af983ae624db3cd18f819416b93ab6b

[AnHardt]

I still don't completely understand but added some more debug code to recalculate().
The i tried to shift the index borders in reverse_pass() a bit back and forward, shaked them and got

 void Planner::reverse_pass() {

-  if (movesplanned() > 3) {
+  if (movesplanned() > 2) {

-    block_t* block[3] = { NULL, NULL, NULL };
+    block_t* block[2] = { NULL, NULL };

     // Make a local copy of block_buffer_tail, because the interrupt can alter it
     // Is a critical section REALLY needed for a single byte change?
     //CRITICAL_SECTION_START;
     uint8_t tail = block_buffer_tail;
     //CRITICAL_SECTION_END
+    tail = BLOCK_MOD(tail+2);

-    uint8_t b = BLOCK_MOD(block_buffer_head - 3);
+    uint8_t b = BLOCK_MOD(block_buffer_head);
     while (b != tail) {
       if (block[0] && TEST(block[0]->flag, BLOCK_BIT_START_FROM_FULL_HALT)) break;
       b = prev_block_index(b);
-      block[2] = block[1];
       block[1] = block[0];
       block[0] = &block_buffer[b];
-      reverse_pass_kernel(block[1], block[2]);
+      reverse_pass_kernel(block[0], block[1]); // current, next
     }
   }
 }

what matches my expectations.
Perfect for series of moves where the single buffer lines reach nominal_rate

Slow

G0 X10 F1500
G0 X20 
G0 X30
G0 X40
G0 X50
G0 X60
G0 X70
G0 X80
G0 X90
G0 X80
G0 X70
G0 X60
G0 X50
G0 X40
G0 X30
G0 X20
G0 X10
G0 X0

23:54:42.920 : ^0
23:54:42.920 : R
23:54:42.921 : echo:0:1; /-*T1600,2000,1600;S400,90,310
23:54:42.921 : F
23:54:42.922 : echo:0:1; /-*T1600,2000,1600;S400,90,310
23:54:42.922 : T
23:54:42.925 : echo:0:1; /-*T1600,2000,1600;S400,90,310
23:54:42.925 : ^0,^1
23:54:42.925 : R
23:54:42.926 : echo:0:2; /- T1600,2000,120;S400,90,151
23:54:42.928 : echo:1:2;  -*T2000,2000,1600;S400,0,310
23:54:42.929 : F
23:54:42.930 : echo:0:2; /- T1600,2000,120;S400,90,151
23:54:42.931 : echo:1:2;  -*T2000,2000,1600;S400,0,310
23:54:42.932 : >0-1
23:54:42.932 : T
23:54:42.933 : echo:0:2; /- T1600,2000,120;S400,90,151
23:54:42.935 : echo:1:2;  -*T2000,2000,1600;S400,0,310
23:54:42.935 : ^0^1
23:54:42.937 : echo:0:2; /- T1600,2000,2000;S400,90,400
23:54:42.938 : echo:1:2;  - T2000,2000,120;S400,0,151
23:54:42.939 : ^2
23:54:42.939 : R
23:54:42.941 : echo:0:3;X/- T1600,2000,2000;S400,90,400
23:54:42.942 : echo:1:3;  - T2000,2000,120;S400,0,151
23:54:42.943 : echo:2:3;  -*T2000,2000,1600;S800,0,710
23:54:42.943 : F
23:54:42.946 : echo:0:3;X/- T1600,2000,2000;S400,90,400
23:54:42.947 : echo:1:3;  - T2000,2000,120;S400,0,151
23:54:42.948 : echo:2:3;  -*T2000,2000,1600;S800,0,710
23:54:42.949 : >0-1>1-2
23:54:42.949 : T
23:54:42.951 : echo:0:3;X/- T1600,2000,2000;S400,90,400
23:54:42.952 : echo:1:3;  - T2000,2000,120;S400,0,151
23:54:42.953 : echo:2:3;  -*T2000,2000,1600;S800,0,710
23:54:42.953 : ^1^2
23:54:42.956 : echo:0:3;X/- T1600,2000,2000;S400,90,400
23:54:42.957 : echo:1:3;  - T2000,2000,2000;S400,0,400
23:54:42.958 : echo:2:3;  - T2000,2000,120;S800,0,551
23:54:42.959 : ^3
23:54:42.959 : R
23:54:42.961 : echo:0:4;X/- T1600,2000,2000;S400,90,400
23:54:42.962 : echo:1:4;  - T2000,2000,2000;S400,0,400
23:54:42.963 : echo:2:4;  - T2000,2000,120;S800,0,551
23:54:42.964 : echo:3:4;  -*T2000,2000,1600;S800,0,710
23:54:42.966 : <2-3
23:54:42.966 : F
23:54:42.967 : echo:0:4;X/- T1600,2000,2000;S400,90,400
23:54:42.968 : echo:1:4;  - T2000,2000,2000;S400,0,400
23:54:42.969 : echo:2:4;  - T2000,2000,120;S800,0,551
23:54:42.973 : echo:3:4;  -*T2000,2000,1600;S800,0,710
23:54:42.973 : >0-1>1-2>2-3
23:54:42.973 : T
23:54:42.974 : echo:0:4;X/- T1600,2000,2000;S400,90,400
23:54:42.977 : echo:1:4;  - T2000,2000,2000;S400,0,400
23:54:42.978 : echo:2:4;  - T2000,2000,120;S800,0,551
23:54:42.979 : echo:3:4;  -*T2000,2000,1600;S800,0,710
23:54:42.979 : ^2^3
23:54:42.982 : echo:0:4;X/- T1600,2000,2000;S400,90,400
23:54:42.983 : echo:1:4;  - T2000,2000,2000;S400,0,400
23:54:42.984 : echo:2:4;  - T2000,2000,2000;S800,0,800
23:54:42.985 : echo:3:4;  - T2000,2000,120;S800,0,551
23:54:42.987 : ^4
23:54:42.987 : R
23:54:42.988 : echo:0:5;X/- T1600,2000,2000;S400,90,400
23:54:42.989 : echo:1:5;  - T2000,2000,2000;S400,0,400
23:54:42.990 : echo:2:5;  - T2000,2000,2000;S800,0,800
23:54:42.993 : echo:3:5;  - T2000,2000,120;S800,0,551
23:54:42.994 : echo:4:5;  -*T2000,2000,1600;S800,0,710
23:54:42.994 : <3-4<2-3
23:54:42.994 : F
23:54:42.996 : echo:0:5;X/- T1600,2000,2000;S400,90,400
23:54:42.998 : echo:1:5;  - T2000,2000,2000;S400,0,400
23:54:42.999 : echo:2:5;  - T2000,2000,2000;S800,0,800
23:54:43.001 : echo:3:5;  - T2000,2000,120;S800,0,551
23:54:43.002 : echo:4:5;  -*T2000,2000,1600;S800,0,710
23:54:43.003 : >0-1>1-2>2-3>3-4
23:54:43.003 : T
23:54:43.005 : echo:0:5;X/- T1600,2000,2000;S400,90,400
23:54:43.007 : echo:1:5;  - T2000,2000,2000;S400,0,400
23:54:43.008 : echo:2:5;  - T2000,2000,2000;S800,0,800
23:54:43.010 : echo:3:5;  - T2000,2000,120;S800,0,551
23:54:43.011 : echo:4:5;  -*T2000,2000,1600;S800,0,710
23:54:43.011 : ^3^4
23:54:43.013 : echo:0:5;X/- T1600,2000,2000;S400,90,400
23:54:43.015 : echo:1:5;  - T2000,2000,2000;S400,0,400
23:54:43.016 : echo:2:5;  - T2000,2000,2000;S800,0,800
23:54:43.017 : echo:3:5;  - T2000,2000,2000;S800,0,800
23:54:43.021 : echo:4:5;  - T2000,2000,120;S800,0,551
23:54:43.021 : ^5
23:54:43.021 : R
23:54:43.022 : echo:0:6;X/- T1600,2000,2000;S400,90,400
23:54:43.023 : echo:1:6;  - T2000,2000,2000;S400,0,400
23:54:43.026 : echo:2:6;  - T2000,2000,2000;S800,0,800
23:54:43.027 : echo:3:6;  - T2000,2000,2000;S800,0,800
23:54:43.028 : echo:4:6;  - T2000,2000,120;S800,0,551
23:54:43.029 : echo:5:6;  -*T2000,2000,1600;S800,0,710
23:54:43.031 : <4-5<3-4<2-3
23:54:43.031 : F
23:54:43.032 : echo:0:6;X/- T1600,2000,2000;S400,90,400
23:54:43.033 : echo:1:6;  - T2000,2000,2000;S400,0,400
23:54:43.036 : echo:2:6;  - T2000,2000,2000;S800,0,800
23:54:43.037 : echo:3:6;  - T2000,2000,2000;S800,0,800
23:54:43.038 : echo:4:6;  - T2000,2000,120;S800,0,551
23:54:43.040 : echo:5:6;  -*T2000,2000,1600;S800,0,710
23:54:43.041 : >0-1>1-2>2-3>3-4>4-5
23:54:43.041 : T
23:54:43.042 : echo:0:6;X/- T1600,2000,2000;S400,90,400
23:54:43.045 : echo:1:6;  - T2000,2000,2000;S400,0,400
23:54:43.046 : echo:2:6;  - T2000,2000,2000;S800,0,800
23:54:43.047 : echo:3:6;  - T2000,2000,2000;S800,0,800
23:54:43.049 : echo:4:6;  - T2000,2000,120;S800,0,551
23:54:43.051 : echo:5:6;  -*T2000,2000,1600;S800,0,710
23:54:43.051 : ^4^5
23:54:43.052 : echo:0:6;X/- T1600,2000,2000;S400,90,400
23:54:43.054 : echo:1:6;  - T2000,2000,2000;S400,0,400
23:54:43.056 : echo:2:6;  - T2000,2000,2000;S800,0,800
23:54:43.057 : echo:3:6;  - T2000,2000,2000;S800,0,800
23:54:43.059 : echo:4:6;  - T2000,2000,2000;S800,0,800
23:54:43.060 : echo:5:6;  - T2000,2000,120;S800,0,551
23:54:43.060 : ^6
23:54:43.061 : R
23:54:43.062 : echo:0:7;X/- T1600,2000,2000;S400,90,400
23:54:43.064 : echo:1:7;  - T2000,2000,2000;S400,0,400
23:54:43.065 : echo:2:7;  - T2000,2000,2000;S800,0,800
23:54:43.067 : echo:3:7;  - T2000,2000,2000;S800,0,800
23:54:43.069 : echo:4:7;  - T2000,2000,2000;S800,0,800
23:54:43.070 : echo:5:7;  - T2000,2000,120;S800,0,551
23:54:43.071 : echo:6:7;  -*T2000,2000,1600;S800,0,710
23:54:43.073 : <5-6<4-5<3-4<2-3
23:54:43.073 : F
23:54:43.074 : echo:0:7;X/- T1600,2000,2000;S400,90,400
23:54:43.075 : echo:1:7;  - T2000,2000,2000;S400,0,400
23:54:43.078 : echo:2:7;  - T2000,2000,2000;S800,0,800
23:54:43.079 : echo:3:7;  - T2000,2000,2000;S800,0,800
23:54:43.080 : echo:4:7;  - T2000,2000,2000;S800,0,800
23:54:43.082 : echo:5:7;  - T2000,2000,120;S800,0,551
23:54:43.085 : echo:6:7;  -*T2000,2000,1600;S800,0,710
23:54:43.085 : >0-1>1-2>2-3>3-4>4-5>5-6
23:54:43.085 : T
23:54:43.087 : echo:0:7;X/- T1600,2000,2000;S400,90,400
23:54:43.089 : echo:1:7;  - T2000,2000,2000;S400,0,400
23:54:43.090 : echo:2:7;  - T2000,2000,2000;S800,0,800
23:54:43.091 : echo:3:7;  - T2000,2000,2000;S800,0,800
23:54:43.094 : echo:4:7;  - T2000,2000,2000;S800,0,800
23:54:43.095 : echo:5:7;  - T2000,2000,120;S800,0,551
23:54:43.096 : echo:6:7;  -*T2000,2000,1600;S800,0,710
23:54:43.096 : ^5^6
23:54:43.099 : echo:0:7;X/- T1600,2000,2000;S400,90,400
23:54:43.100 : echo:1:7;  - T2000,2000,2000;S400,0,400
23:54:43.101 : echo:2:7;  - T2000,2000,2000;S800,0,800
23:54:43.102 : echo:3:7;  - T2000,2000,2000;S800,0,800
23:54:43.105 : echo:4:7;  - T2000,2000,2000;S800,0,800
23:54:43.106 : echo:5:7;  - T2000,2000,2000;S800,0,800
23:54:43.108 : echo:6:7;  - T2000,2000,120;S800,0,551
23:54:43.108 : ^7
23:54:43.108 : R
23:54:43.110 : echo:0:8;X/- T1600,2000,2000;S400,90,400
23:54:43.111 : echo:1:8;  - T2000,2000,2000;S400,0,400
23:54:43.113 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.114 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.116 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.118 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.119 : echo:6:8;  - T2000,2000,120;S800,0,551
23:54:43.120 : echo:7:8;  -*T2000,2000,1600;S800,0,710
23:54:43.122 : <6-7<5-6<4-5<3-4<2-3
23:54:43.122 : F
23:54:43.123 : echo:0:8;X/- T1600,2000,2000;S400,90,400
23:54:43.125 : echo:1:8;  - T2000,2000,2000;S400,0,400
23:54:43.127 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.128 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.129 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.132 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.134 : echo:6:8;  - T2000,2000,120;S800,0,551
23:54:43.135 : echo:7:8;  -*T2000,2000,1600;S800,0,710
23:54:43.136 : >0-1>1-2>2-3>3-4>4-5>5-6>6-7
23:54:43.136 : T
23:54:43.138 : echo:0:8;X/- T1600,2000,2000;S400,90,400
23:54:43.140 : echo:1:8;  - T2000,2000,2000;S400,0,400
23:54:43.141 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.143 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.144 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.146 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.148 : echo:6:8;  - T2000,2000,120;S800,0,551
23:54:43.149 : echo:7:8;  -*T2000,2000,1600;S800,0,710
23:54:43.149 : ^6^7
23:54:43.150 : echo:0:8;X/- T1600,2000,2000;S400,90,400
23:54:43.153 : echo:1:7;X - T2000,2000,2000;S400,0,400
23:54:43.154 : echo:2:7;  - T2000,2000,2000;S800,0,800
23:54:43.155 : echo:3:7;  - T2000,2000,2000;S800,0,800
23:54:43.157 : echo:4:7;  - T2000,2000,2000;S800,0,800
23:54:43.159 : echo:5:7;  - T2000,2000,2000;S800,0,800
23:54:43.161 : echo:6:7;  - T2000,2000,2000;S800,0,800
23:54:43.162 : echo:7:7;  - T2000,2000,120;S800,0,551
23:54:43.162 : ^8
23:54:43.163 : R
23:54:43.164 : echo:1:8;X - T2000,2000,2000;S400,0,400
23:54:43.166 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.167 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.169 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.171 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.172 : echo:6:8;  - T2000,2000,2000;S800,0,800
23:54:43.173 : echo:7:8;  - T2000,2000,120;S800,0,551
23:54:43.176 : echo:8:8;  -*T2000,2000,1600;S800,0,710
23:54:43.176 : <7-8<6-7<5-6<4-5<3-4
23:54:43.176 : F
23:54:43.177 : echo:1:8;X - T2000,2000,2000;S400,0,400
23:54:43.180 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.181 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.182 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.183 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.186 : echo:6:8;  - T2000,2000,2000;S800,0,800
23:54:43.187 : echo:7:8;  - T2000,2000,120;S800,0,551
23:54:43.189 : echo:8:8;  -*T2000,2000,1600;S800,0,710
23:54:43.190 : >1-2>2-3>3-4>4-5>5-6>6-7>7-8
23:54:43.190 : T
23:54:43.191 : echo:1:8;X - T2000,2000,2000;S400,0,400
23:54:43.193 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.195 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.196 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.197 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.200 : echo:6:8;  - T2000,2000,2000;S800,0,800
23:54:43.201 : echo:7:8;  - T2000,2000,120;S800,0,551
23:54:43.202 : echo:8:8;  -*T2000,2000,1600;S800,0,710
23:54:43.202 : ^7^8
23:54:43.205 : echo:1:8;X - T2000,2000,2000;S400,0,400
23:54:43.206 : echo:2:8;  - T2000,2000,2000;S800,0,800
23:54:43.208 : echo:3:8;  - T2000,2000,2000;S800,0,800
23:54:43.209 : echo:4:8;  - T2000,2000,2000;S800,0,800
23:54:43.213 : echo:5:8;  - T2000,2000,2000;S800,0,800
23:54:43.214 : echo:6:8;  - T2000,2000,2000;S800,0,800
23:54:43.215 : echo:7:8;  - T2000,2000,2000;S800,0,800
23:54:43.216 : echo:8:8;  - T2000,2000,120;S800,0,551
23:54:43.216 : ^9
23:54:43.217 : R
23:54:43.219 : echo:1:9;X - T2000,2000,2000;S400,0,400
23:54:43.220 : echo:2:9;  - T2000,2000,2000;S800,0,800
23:54:43.221 : echo:3:9;  - T2000,2000,2000;S800,0,800
23:54:43.224 : echo:4:9;  - T2000,2000,2000;S800,0,800
23:54:43.225 : echo:5:9;  - T2000,2000,2000;S800,0,800
23:54:43.226 : echo:6:9;  - T2000,2000,2000;S800,0,800
23:54:43.228 : echo:7:9;  - T2000,2000,2000;S800,0,800
23:54:43.229 : echo:8:9;  - T2000,2000,120;S800,0,551
23:54:43.231 : echo:9:9;  -*T2000,2000,1600;S800,0,710
23:54:43.233 : <8-9<7-8<6-7<5-6<4-5<3-4
23:54:43.233 : F
23:54:43.234 : echo:1:9;X - T2000,2000,2000;S400,0,400
23:54:43.235 : echo:2:9;  - T2000,2000,2000;S800,0,800
23:54:43.236 : echo:3:9;  - T2000,2000,2000;S800,0,800
23:54:43.239 : echo:4:9;  - T2000,2000,2000;S800,0,800
23:54:43.240 : echo:5:9;  - T2000,2000,2000;S800,0,800
23:54:43.241 : echo:6:9;  - T2000,2000,2000;S800,0,800
23:54:43.243 : echo:7:9;  - T2000,2000,2000;S800,0,800
23:54:43.245 : echo:8:9;  - T2000,2000,120;S800,0,551
23:54:43.247 : echo:9:9;  -*T2000,2000,1600;S800,0,710
23:54:43.248 : >1-2>2-3>3-4>4-5>5-6>6-7>7-8>8-9
23:54:43.248 : T
23:54:43.249 : echo:1:9;X - T2000,2000,2000;S400,0,400
23:54:43.250 : echo:2:9;  - T2000,2000,2000;S800,0,800
23:54:43.253 : echo:3:9;  - T2000,2000,2000;S800,0,800
23:54:43.254 : echo:4:9;  - T2000,2000,2000;S800,0,800
23:54:43.255 : echo:5:9;  - T2000,2000,2000;S800,0,800
23:54:43.257 : echo:6:9;  - T2000,2000,2000;S800,0,800
23:54:43.259 : echo:7:9;  - T2000,2000,2000;S800,0,800
23:54:43.261 : echo:8:9;  - T2000,2000,120;S800,0,551
23:54:43.262 : echo:9:9;  -*T2000,2000,1600;S800,0,710
23:54:43.262 : ^8^9
23:54:43.264 : echo:1:9;X - T2000,2000,2000;S400,0,400
23:54:43.266 : echo:2:9;  - T2000,2000,2000;S800,0,800
23:54:43.267 : echo:3:9;  - T2000,2000,2000;S800,0,800
23:54:43.268 : echo:4:9;  - T2000,2000,2000;S800,0,800
23:54:43.271 : echo:5:9;  - T2000,2000,2000;S800,0,800
23:54:43.272 : echo:6:9;  - T2000,2000,2000;S800,0,800
23:54:43.273 : echo:7:9;  - T2000,2000,2000;S800,0,800
23:54:43.274 : echo:8:9;  - T2000,2000,2000;S800,0,800
23:54:43.276 : echo:9:9;  - T2000,2000,120;S800,0,551
23:54:43.278 : ^10
23:54:43.278 : R
23:54:43.279 : echo:1:10;X - T2000,2000,2000;S400,0,400
23:54:43.280 : echo:2:10;  - T2000,2000,2000;S800,0,800
23:54:43.283 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.284 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.286 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.287 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.289 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.291 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.292 : echo:9:10;  - T2000,2000,120;S800,0,551
23:54:43.295 : echo:10:10; /-*T1600,2000,1600;S800,90,710
23:54:43.295 : F
23:54:43.296 : echo:1:10;X - T2000,2000,2000;S400,0,400
23:54:43.297 : echo:2:10;  - T2000,2000,2000;S800,0,800
23:54:43.300 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.301 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.302 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.303 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.306 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.307 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.309 : echo:9:10;  - T2000,2000,120;S800,0,551
23:54:43.311 : echo:10:10; /-*T1600,2000,1600;S800,90,710
23:54:43.312 : >1-2>2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10
23:54:43.312 : T
23:54:43.313 : echo:1:10;X - T2000,2000,2000;S400,0,400
23:54:43.315 : echo:2:10;  - T2000,2000,2000;S800,0,800
23:54:43.317 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.318 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.320 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.321 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.324 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.325 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.326 : echo:9:10;  - T2000,2000,120;S800,0,551
23:54:43.329 : echo:10:10; /-*T1600,2000,1600;S800,90,710
23:54:43.329 : ^9^10
23:54:43.330 : echo:1:10;X - T2000,2000,2000;S400,0,400
23:54:43.332 : echo:2:10;  - T2000,2000,2000;S800,0,800
23:54:43.335 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.336 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.337 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.340 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.341 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.342 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.344 : echo:9:10;  - T2000,2000,1600;S800,0,710
23:54:43.346 : echo:10:10; /- T1600,2000,120;S800,90,551
23:54:43.346 : ^11
23:54:43.346 : R
23:54:43.347 : echo:1:11;X - T2000,2000,2000;S400,0,400
23:54:43.349 : echo:2:11;  - T2000,2000,2000;S800,0,800
23:54:43.351 : echo:3:11;  - T2000,2000,2000;S800,0,800
23:54:43.352 : echo:4:11;  - T2000,2000,2000;S800,0,800
23:54:43.353 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.356 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.357 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.358 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.359 : echo:9:10;  - T2000,2000,1600;S800,0,710
23:54:43.362 : echo:10:10; /- T1600,2000,120;S800,90,551
23:54:43.363 : echo:11:10;  -*T2000,2000,1600;S800,0,710
23:54:43.363 : <10-11
23:54:43.363 : F
23:54:43.366 : echo:2:10;X - T2000,2000,2000;S800,0,800
23:54:43.367 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.368 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.371 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.372 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.375 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.375 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.378 : echo:9:10;  - T2000,2000,1600;S800,0,710
23:54:43.380 : echo:10:10; /- T1600,2000,120;S800,90,551
23:54:43.381 : echo:11:10;  -*T2000,2000,1600;S800,0,710
23:54:43.383 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11
23:54:43.383 : T
23:54:43.385 : echo:2:10;X - T2000,2000,2000;S800,0,800
23:54:43.386 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.387 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.390 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.391 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.392 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.395 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.396 : echo:9:10;  - T2000,2000,1600;S800,0,710
23:54:43.397 : echo:10:10; /- T1600,2000,120;S800,90,551
23:54:43.399 : echo:11:10;  -*T2000,2000,1600;S800,0,710
23:54:43.400 : ^10^11
23:54:43.401 : echo:2:10;X - T2000,2000,2000;S800,0,800
23:54:43.402 : echo:3:10;  - T2000,2000,2000;S800,0,800
23:54:43.405 : echo:4:10;  - T2000,2000,2000;S800,0,800
23:54:43.406 : echo:5:10;  - T2000,2000,2000;S800,0,800
23:54:43.407 : echo:6:10;  - T2000,2000,2000;S800,0,800
23:54:43.409 : echo:7:10;  - T2000,2000,2000;S800,0,800
23:54:43.411 : echo:8:10;  - T2000,2000,2000;S800,0,800
23:54:43.413 : echo:9:10;  - T2000,2000,1600;S800,0,710
23:54:43.414 : echo:10:10; /- T1600,2000,2000;S800,90,800
23:54:43.416 : echo:11:10;  - T2000,2000,120;S800,0,551
23:54:43.416 : ^12
23:54:43.416 : R
23:54:43.418 : echo:2:11;X - T2000,2000,2000;S800,0,800
23:54:43.419 : echo:3:11;  - T2000,2000,2000;S800,0,800
23:54:43.421 : echo:4:11;  - T2000,2000,2000;S800,0,800
23:54:43.423 : echo:5:11;  - T2000,2000,2000;S800,0,800
23:54:43.424 : echo:6:11;  - T2000,2000,2000;S800,0,800
23:54:43.426 : echo:7:11;  - T2000,2000,2000;S800,0,800
23:54:43.428 : echo:8:11;  - T2000,2000,2000;S800,0,800
23:54:43.429 : echo:9:11;  - T2000,2000,1600;S800,0,710
23:54:43.430 : echo:10:11; /- T1600,2000,2000;S800,90,800
23:54:43.433 : echo:11:11;  - T2000,2000,120;S800,0,551
23:54:43.434 : echo:12:11;  -*T2000,2000,1600;S800,0,710
23:54:43.434 : <11-12<10-11
23:54:43.434 : F
23:54:43.437 : echo:2:11;X - T2000,2000,2000;S800,0,800
23:54:43.438 : echo:3:11;  - T2000,2000,2000;S800,0,800
23:54:43.440 : echo:4:11;  - T2000,2000,2000;S800,0,800
23:54:43.443 : echo:5:11;  - T2000,2000,2000;S800,0,800
23:54:43.444 : echo:6:11;  - T2000,2000,2000;S800,0,800
23:54:43.445 : echo:7:11;  - T2000,2000,2000;S800,0,800
23:54:43.447 : echo:8:11;  - T2000,2000,2000;S800,0,800
23:54:43.449 : echo:9:11;  - T2000,2000,1600;S800,0,710
23:54:43.450 : echo:10:11; /- T1600,2000,2000;S800,90,800
23:54:43.452 : echo:11:11;  - T2000,2000,120;S800,0,551
23:54:43.454 : echo:12:11;  -*T2000,2000,1600;S800,0,710
23:54:43.456 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12
23:54:43.456 : T
23:54:43.457 : echo:2:11;X - T2000,2000,2000;S800,0,800
23:54:43.459 : echo:3:11;  - T2000,2000,2000;S800,0,800
23:54:43.461 : echo:4:11;  - T2000,2000,2000;S800,0,800
23:54:43.462 : echo:5:11;  - T2000,2000,2000;S800,0,800
23:54:43.464 : echo:6:11;  - T2000,2000,2000;S800,0,800
23:54:43.466 : echo:7:11;  - T2000,2000,2000;S800,0,800
23:54:43.467 : echo:8:11;  - T2000,2000,2000;S800,0,800
23:54:43.468 : echo:9:11;  - T2000,2000,1600;S800,0,710
23:54:43.471 : echo:10:11; /- T1600,2000,2000;S800,90,800
23:54:43.472 : echo:11:11;  - T2000,2000,120;S800,0,551
23:54:43.473 : echo:12:11;  -*T2000,2000,1600;S800,0,710
23:54:43.474 : ^11^12
23:54:43.476 : echo:2:11;X - T2000,2000,2000;S800,0,800
23:54:43.477 : echo:3:11;  - T2000,2000,2000;S800,0,800
23:54:43.478 : echo:4:11;  - T2000,2000,2000;S800,0,800
23:54:43.481 : echo:5:11;  - T2000,2000,2000;S800,0,800
23:54:43.482 : echo:6:11;  - T2000,2000,2000;S800,0,800
23:54:43.484 : echo:7:11;  - T2000,2000,2000;S800,0,800
23:54:43.486 : echo:8:11;  - T2000,2000,2000;S800,0,800
23:54:43.487 : echo:9:11;  - T2000,2000,1600;S800,0,710
23:54:43.489 : echo:10:11; /- T1600,2000,2000;S800,90,800
23:54:43.490 : echo:11:11;  - T2000,2000,2000;S800,0,800
23:54:43.492 : echo:12:11;  - T2000,2000,120;S800,0,551
23:54:43.493 : ^13
23:54:43.493 : R
23:54:43.494 : echo:2:12;X - T2000,2000,2000;S800,0,800
23:54:43.496 : echo:3:12;  - T2000,2000,2000;S800,0,800
23:54:43.497 : echo:4:12;  - T2000,2000,2000;S800,0,800
23:54:43.499 : echo:5:12;  - T2000,2000,2000;S800,0,800
23:54:43.500 : echo:6:12;  - T2000,2000,2000;S800,0,800
23:54:43.502 : echo:7:12;  - T2000,2000,2000;S800,0,800
23:54:43.504 : echo:8:12;  - T2000,2000,2000;S800,0,800
23:54:43.505 : echo:9:12;  - T2000,2000,1600;S800,0,710
23:54:43.507 : echo:10:12; /- T1600,2000,2000;S800,90,800
23:54:43.509 : echo:11:12;  - T2000,2000,2000;S800,0,800
23:54:43.510 : echo:12:12;  - T2000,2000,120;S800,0,551
23:54:43.513 : echo:13:12;  -*T2000,2000,1600;S800,0,710
23:54:43.513 : <12-13<11-12<10-11
23:54:43.513 : F
23:54:43.515 : echo:2:12;X - T2000,2000,2000;S800,0,800
23:54:43.517 : echo:3:12;  - T2000,2000,2000;S800,0,800
23:54:43.519 : echo:4:12;  - T2000,2000,2000;S800,0,800
23:54:43.520 : echo:5:12;  - T2000,2000,2000;S800,0,800
23:54:43.522 : echo:6:12;  - T2000,2000,2000;S800,0,800
23:54:43.524 : echo:7:12;  - T2000,2000,2000;S800,0,800
23:54:43.525 : echo:8:12;  - T2000,2000,2000;S800,0,800
23:54:43.526 : echo:9:12;  - T2000,2000,1600;S800,0,710
23:54:43.529 : echo:10:12; /- T1600,2000,2000;S800,90,800
23:54:43.530 : echo:11:12;  - T2000,2000,2000;S800,0,800
23:54:43.531 : echo:12:12;  - T2000,2000,120;S800,0,551
23:54:43.534 : echo:13:12;  -*T2000,2000,1600;S800,0,710
23:54:43.535 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13
23:54:43.535 : T
23:54:43.538 : echo:2:12;X - T2000,2000,2000;S800,0,800
23:54:43.539 : echo:3:12;  - T2000,2000,2000;S800,0,800
23:54:43.540 : echo:4:12;  - T2000,2000,2000;S800,0,800
23:54:43.543 : echo:5:12;  - T2000,2000,2000;S800,0,800
23:54:43.544 : echo:6:12;  - T2000,2000,2000;S800,0,800
23:54:43.545 : echo:7:12;  - T2000,2000,2000;S800,0,800
23:54:43.547 : echo:8:12;  - T2000,2000,2000;S800,0,800
23:54:43.549 : echo:9:12;  - T2000,2000,1600;S800,0,710
23:54:43.550 : echo:10:12; /- T1600,2000,2000;S800,90,800
23:54:43.552 : echo:11:12;  - T2000,2000,2000;S800,0,800
23:54:43.554 : echo:12:12;  - T2000,2000,120;S800,0,551
23:54:43.555 : echo:13:12;  -*T2000,2000,1600;S800,0,710
23:54:43.555 : ^12^13
23:54:43.557 : echo:2:12;X - T2000,2000,2000;S800,0,800
23:54:43.559 : echo:3:12;  - T2000,2000,2000;S800,0,800
23:54:43.560 : echo:4:12;  - T2000,2000,2000;S800,0,800
23:54:43.562 : echo:5:12;  - T2000,2000,2000;S800,0,800
23:54:43.565 : echo:6:12;  - T2000,2000,2000;S800,0,800
23:54:43.566 : echo:7:12;  - T2000,2000,2000;S800,0,800
23:54:43.567 : echo:8:12;  - T2000,2000,2000;S800,0,800
23:54:43.568 : echo:9:12;  - T2000,2000,1600;S800,0,710
23:54:43.571 : echo:10:12; /- T1600,2000,2000;S800,90,800
23:54:43.572 : echo:11:12;  - T2000,2000,2000;S800,0,800
23:54:43.573 : echo:12:12;  - T2000,2000,2000;S800,0,800
23:54:43.576 : echo:13:12;  - T2000,2000,120;S800,0,551
23:54:43.576 : ^14
23:54:43.577 : R
23:54:43.578 : echo:2:13;X - T2000,2000,2000;S800,0,800
23:54:43.580 : echo:3:13;  - T2000,2000,2000;S800,0,800
23:54:43.581 : echo:4:13;  - T2000,2000,2000;S800,0,800
23:54:43.584 : echo:5:13;  - T2000,2000,2000;S800,0,800
23:54:43.585 : echo:6:13;  - T2000,2000,2000;S800,0,800
23:54:43.586 : echo:7:13;  - T2000,2000,2000;S800,0,800
23:54:43.587 : echo:8:13;  - T2000,2000,2000;S800,0,800
23:54:43.590 : echo:9:13;  - T2000,2000,1600;S800,0,710
23:54:43.591 : echo:10:13; /- T1600,2000,2000;S800,90,800
23:54:43.592 : echo:11:13;  - T2000,2000,2000;S800,0,800
23:54:43.595 : echo:12:13;  - T2000,2000,2000;S800,0,800
23:54:43.596 : echo:13:13;  - T2000,2000,120;S800,0,551
23:54:43.598 : echo:14:13;  -*T2000,2000,1600;S800,0,710
23:54:43.599 : <13-14<12-13<11-12<10-11
23:54:43.599 : F
23:54:43.601 : echo:2:13;X - T2000,2000,2000;S800,0,800
23:54:43.604 : echo:3:13;  - T2000,2000,2000;S800,0,800
23:54:43.605 : echo:4:13;  - T2000,2000,2000;S800,0,800
23:54:43.606 : echo:5:13;  - T2000,2000,2000;S800,0,800
23:54:43.609 : echo:6:13;  - T2000,2000,2000;S800,0,800
23:54:43.610 : echo:7:13;  - T2000,2000,2000;S800,0,800
23:54:43.611 : echo:8:13;  - T2000,2000,2000;S800,0,800
23:54:43.613 : echo:9:13;  - T2000,2000,1600;S800,0,710
23:54:43.615 : echo:10:13; /- T1600,2000,2000;S800,90,800
23:54:43.616 : echo:11:13;  - T2000,2000,2000;S800,0,800
23:54:43.618 : echo:12:13;  - T2000,2000,2000;S800,0,800
23:54:43.620 : echo:13:13;  - T2000,2000,120;S800,0,551
23:54:43.622 : echo:14:13;  -*T2000,2000,1600;S800,0,710
23:54:43.624 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14
23:54:43.624 : T
23:54:43.625 : echo:2:13;X - T2000,2000,2000;S800,0,800
23:54:43.627 : echo:3:13;  - T2000,2000,2000;S800,0,800
23:54:43.629 : echo:4:13;  - T2000,2000,2000;S800,0,800
23:54:43.630 : echo:5:13;  - T2000,2000,2000;S800,0,800
23:54:43.632 : echo:6:13;  - T2000,2000,2000;S800,0,800
23:54:43.634 : echo:7:13;  - T2000,2000,2000;S800,0,800
23:54:43.635 : echo:8:13;  - T2000,2000,2000;S800,0,800
23:54:43.637 : echo:9:13;  - T2000,2000,1600;S800,0,710
23:54:43.638 : echo:10:13; /- T1600,2000,2000;S800,90,800
23:54:43.640 : echo:11:13;  - T2000,2000,2000;S800,0,800
23:54:43.642 : echo:12:13;  - T2000,2000,2000;S800,0,800
23:54:43.643 : echo:13:13;  - T2000,2000,120;S800,0,551
23:54:43.645 : echo:14:13;  -*T2000,2000,1600;S800,0,710
23:54:43.645 : ^13^14
23:54:43.647 : echo:2:13;X - T2000,2000,2000;S800,0,800
23:54:43.648 : echo:3:13;  - T2000,2000,2000;S800,0,800
23:54:43.651 : echo:4:13;  - T2000,2000,2000;S800,0,800
23:54:43.652 : echo:5:13;  - T2000,2000,2000;S800,0,800
23:54:43.653 : echo:6:13;  - T2000,2000,2000;S800,0,800
23:54:43.656 : echo:7:13;  - T2000,2000,2000;S800,0,800
23:54:43.657 : echo:8:13;  - T2000,2000,2000;S800,0,800
23:54:43.658 : echo:9:13;  - T2000,2000,1600;S800,0,710
23:54:43.659 : echo:10:13; /- T1600,2000,2000;S800,90,800
23:54:43.662 : echo:11:13;  - T2000,2000,2000;S800,0,800
23:54:43.663 : echo:12:13;  - T2000,2000,2000;S800,0,800
23:54:43.666 : echo:13:13;  - T2000,2000,2000;S800,0,800
23:54:43.668 : echo:14:13;  - T2000,2000,120;S800,0,551
23:54:43.668 : ^15
23:54:43.668 : R
23:54:43.669 : echo:2:14;X - T2000,2000,2000;S800,0,800
23:54:43.672 : echo:3:14;  - T2000,2000,2000;S800,0,800
23:54:43.673 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.674 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.676 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.678 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.679 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.681 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.683 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.685 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.686 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.688 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.690 : echo:14:14;  - T2000,2000,120;S800,0,551
23:54:43.691 : echo:15:14;  -*T2000,2000,1600;S800,0,710
23:54:43.692 : <14-15<13-14<12-13<11-12<10-11
23:54:43.692 : F
23:54:43.693 : echo:2:14;X - T2000,2000,2000;S800,0,800
23:54:43.700 : echo:3:14;  - T2000,2000,2000;S800,0,800
23:54:43.700 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.700 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.701 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.703 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.704 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.705 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.708 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.709 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.710 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.713 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.714 : echo:14:14;  - T2000,2000,120;S800,0,551
23:54:43.715 : echo:15:14;  -*T2000,2000,1600;S800,0,710
23:54:43.718 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15
23:54:43.718 : T
23:54:43.720 : echo:2:14;X - T2000,2000,2000;S800,0,800
23:54:43.722 : echo:3:14;  - T2000,2000,2000;S800,0,800
23:54:43.723 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.724 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.727 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.728 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.729 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.732 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.733 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.734 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.737 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.738 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.739 : echo:14:14;  - T2000,2000,120;S800,0,551
23:54:43.741 : echo:15:14;  -*T2000,2000,1600;S800,0,710
23:54:43.742 : ^14^15
23:54:43.743 : echo:2:14;X - T2000,2000,2000;S800,0,800
23:54:43.744 : echo:3:14;  - T2000,2000,2000;S800,0,800
23:54:43.747 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.748 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.750 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.752 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.754 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.756 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.757 : echo:10:13; /- T1600,2000,2000;S800,90,800
23:54:43.759 : echo:11:13;  - T2000,2000,2000;S800,0,800
23:54:43.761 : echo:12:13;  - T2000,2000,2000;S800,0,800
23:54:43.762 : echo:13:13;  - T2000,2000,2000;S800,0,800
23:54:43.764 : echo:14:13;  - T2000,2000,2000;S800,0,800
23:54:43.766 : echo:15:13;  - T2000,2000,120;S800,0,551
23:54:43.766 : ^0
23:54:43.766 : R
23:54:43.767 : echo:3:14;X - T2000,2000,2000;S800,0,800
23:54:43.769 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.771 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.772 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.773 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.776 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.777 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.778 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.781 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.782 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.783 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.786 : echo:14:14;  - T2000,2000,2000;S800,0,800
23:54:43.787 : echo:15:14;  - T2000,2000,120;S800,0,551
23:54:43.789 : echo:0:14;  -*T2000,2000,1600;S800,0,710
23:54:43.790 : <15-0<14-15<13-14<12-13<11-12<10-11
23:54:43.790 : F
23:54:43.792 : echo:3:14;X - T2000,2000,2000;S800,0,800
23:54:43.794 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.795 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.796 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.799 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.800 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.801 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.804 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.805 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.807 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.809 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.810 : echo:14:14;  - T2000,2000,2000;S800,0,800
23:54:43.812 : echo:15:14;  - T2000,2000,120;S800,0,551
23:54:43.813 : echo:0:14;  -*T2000,2000,1600;S800,0,710
23:54:43.817 : >3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0
23:54:43.817 : T
23:54:43.818 : echo:3:14;X - T2000,2000,2000;S800,0,800
23:54:43.819 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.821 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.823 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.824 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.825 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.829 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.830 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.832 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.834 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.835 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.837 : echo:14:14;  - T2000,2000,2000;S800,0,800
23:54:43.838 : echo:15:14;  - T2000,2000,120;S800,0,551
23:54:43.840 : echo:0:14;  -*T2000,2000,1600;S800,0,710
23:54:43.841 : ^15^0
23:54:43.842 : echo:3:14;X - T2000,2000,2000;S800,0,800
23:54:43.843 : echo:4:14;  - T2000,2000,2000;S800,0,800
23:54:43.846 : echo:5:14;  - T2000,2000,2000;S800,0,800
23:54:43.847 : echo:6:14;  - T2000,2000,2000;S800,0,800
23:54:43.848 : echo:7:14;  - T2000,2000,2000;S800,0,800
23:54:43.851 : echo:8:14;  - T2000,2000,2000;S800,0,800
23:54:43.852 : echo:9:14;  - T2000,2000,1600;S800,0,710
23:54:43.853 : echo:10:14; /- T1600,2000,2000;S800,90,800
23:54:43.856 : echo:11:14;  - T2000,2000,2000;S800,0,800
23:54:43.857 : echo:12:14;  - T2000,2000,2000;S800,0,800
23:54:43.858 : echo:13:14;  - T2000,2000,2000;S800,0,800
23:54:43.860 : echo:14:14;  - T2000,2000,2000;S800,0,800
23:54:43.862 : echo:15:14;  - T2000,2000,2000;S800,0,800
23:54:43.863 : echo:0:14;  - T2000,2000,120;S800,0,551
23:54:43.863 : ^1
23:54:43.863 : R
23:54:43.866 : echo:3:15;X - T2000,2000,2000;S800,0,800
23:54:43.867 : echo:4:15;  - T2000,2000,2000;S800,0,800
23:54:43.868 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:43.870 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:43.872 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:43.874 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:43.875 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:43.877 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:43.879 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:43.880 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:43.882 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:43.884 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:43.885 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:43.886 : echo:0:15;  - T2000,2000,120;S800,0,551
23:54:43.889 : echo:1:15;  -*T2000,2000,1600;S800,0,710
23:54:43.890 : <0-1<15-0<14-15<13-14<12-13<11-12<10-11
23:54:43.890 : F
23:54:43.891 : echo:3:15;X - T2000,2000,2000;S800,0,800
23:54:43.894 : echo:4:15;  - T2000,2000,2000;S800,0,800
23:54:43.895 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:43.896 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:43.898 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:43.900 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:43.902 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:43.903 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:43.906 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:43.908 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:43.909 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:43.911 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:43.913 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:43.914 : echo:0:15;  - T2000,2000,120;S800,0,551
23:54:43.915 : echo:1:15;  -*T2000,2000,1600;S800,0,710
23:54:43.919 : >3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0>0-1
23:54:43.919 : T
23:54:43.920 : echo:3:15;X - T2000,2000,2000;S800,0,800
23:54:43.922 : echo:4:15;  - T2000,2000,2000;S800,0,800
23:54:43.923 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:43.925 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:43.927 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:43.928 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:43.931 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:43.932 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:43.933 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:43.936 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:43.937 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:43.938 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:43.939 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:43.942 : echo:0:15;  - T2000,2000,120;S800,0,551
23:54:43.943 : echo:1:15;  -*T2000,2000,1600;S800,0,710
23:54:43.943 : ^0^1
23:54:43.944 : echo:3:15;X - T2000,2000,2000;S800,0,800
23:54:43.947 : echo:4:15;  - T2000,2000,2000;S800,0,800
23:54:43.948 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:43.949 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:43.952 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:43.953 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:43.955 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:43.956 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:43.959 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:43.960 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:43.961 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:43.964 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:43.965 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:43.966 : echo:0:15;  - T2000,2000,2000;S800,0,800
23:54:43.969 : echo:1:15;  - T2000,2000,120;S800,0,551
23:54:44.149 : ^2
23:54:44.149 : R
23:54:44.150 : echo:4:15;X - T2000,2000,2000;S800,0,800
23:54:44.151 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:44.153 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:44.155 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:44.156 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:44.158 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:44.160 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:44.161 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:44.163 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:44.165 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:44.166 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:44.168 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:44.170 : echo:0:15;  - T2000,2000,2000;S800,0,800
23:54:44.172 : echo:1:15;  - T2000,2000,120;S800,0,551
23:54:44.173 : echo:2:15;  -*T2000,2000,1600;S800,0,710
23:54:44.174 : <1-2<0-1<15-0<14-15<13-14<12-13<11-12<10-11
23:54:44.174 : F
23:54:44.178 : echo:4:15;X - T2000,2000,2000;S800,0,800
23:54:44.179 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:44.180 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:44.183 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:44.184 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:44.185 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:44.188 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:44.189 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:44.190 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:44.191 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:44.194 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:44.195 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:44.197 : echo:0:15;  - T2000,2000,2000;S800,0,800
23:54:44.199 : echo:1:15;  - T2000,2000,120;S800,0,551
23:54:44.200 : echo:2:15;  -*T2000,2000,1600;S800,0,710
23:54:44.203 : >4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0>0-1>1-2
23:54:44.203 : T
23:54:44.204 : echo:4:15;X - T2000,2000,2000;S800,0,800
23:54:44.207 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:44.208 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:44.209 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:44.212 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:44.213 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:44.214 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:44.216 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:44.218 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:44.219 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:44.221 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:44.223 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:44.224 : echo:0:15;  - T2000,2000,2000;S800,0,800
23:54:44.226 : echo:1:15;  - T2000,2000,120;S800,0,551
23:54:44.228 : echo:2:15;  -*T2000,2000,1600;S800,0,710
23:54:44.228 : ^1^2
23:54:44.229 : echo:4:15;X - T2000,2000,2000;S800,0,800
23:54:44.231 : echo:5:15;  - T2000,2000,2000;S800,0,800
23:54:44.234 : echo:6:15;  - T2000,2000,2000;S800,0,800
23:54:44.235 : echo:7:15;  - T2000,2000,2000;S800,0,800
23:54:44.237 : echo:8:15;  - T2000,2000,2000;S800,0,800
23:54:44.238 : echo:9:15;  - T2000,2000,1600;S800,0,710
23:54:44.240 : echo:10:15; /- T1600,2000,2000;S800,90,800
23:54:44.242 : echo:11:15;  - T2000,2000,2000;S800,0,800
23:54:44.243 : echo:12:15;  - T2000,2000,2000;S800,0,800
23:54:44.246 : echo:13:15;  - T2000,2000,2000;S800,0,800
23:54:44.247 : echo:14:15;  - T2000,2000,2000;S800,0,800
23:54:44.248 : echo:15:15;  - T2000,2000,2000;S800,0,800
23:54:44.251 : echo:0:15;  - T2000,2000,2000;S800,0,800
23:54:44.252 : echo:1:15;  - T2000,2000,2000;S800,0,800
23:54:44.254 : echo:2:15;  - T2000,2000,120;S800,0,551

and even so when the reverse_pass() is really needed (nominal_rate faster than can be reached in one block )

Fast

G0 X10 F5000
G0 X20 
G0 X30
G0 X40
G0 X50
G0 X60
G0 X70
G0 X80
G0 X90
G0 X80
G0 X70
G0 X60
G0 X50
G0 X40
G0 X30
G0 X20
G0 X10
G0 X0

23:51:51.666 : ^0
23:51:51.667 : R
23:51:51.668 : echo:0:1; / *T1601,6667,1601;S400,200,200
23:51:51.668 : F
23:51:51.669 : echo:0:1; / *T1601,6667,1601;S400,200,200
23:51:51.669 : T
23:51:51.672 : echo:0:1; / *T1601,6667,1601;S400,200,200
23:51:51.672 : ^0,^1
23:51:51.672 : R
23:51:51.673 : echo:0:2; /  T1601,6667,120;S400,121,121
23:51:51.676 : echo:1:2;   *T2530,6667,1601;S400,81,81
23:51:51.676 : F
23:51:51.677 : echo:0:2; /  T1601,6667,120;S400,121,121
23:51:51.678 : echo:1:2;   *T2530,6667,1601;S400,81,81
23:51:51.678 : >0-1
23:51:51.678 : T
23:51:51.682 : echo:0:2; /  T1601,6667,120;S400,121,121
23:51:51.683 : echo:1:2;   *T2530,6667,1601;S400,81,81
23:51:51.683 : ^0^1
23:51:51.684 : echo:0:2; /  T1601,6667,2530;S400,320,320
23:51:51.687 : echo:1:2;    T2530,6667,120;S400,1,1
23:51:51.687 : ^2
23:51:51.687 : R
23:51:51.688 : echo:0:3;X/  T1601,6667,2530;S400,320,320
23:51:51.689 : echo:1:3;    T2530,6667,120;S400,1,1
23:51:51.692 : echo:2:3;   *T3578,6667,1601;S800,81,81
23:51:51.692 : F
23:51:51.693 : echo:0:3;X/  T1601,6667,2530;S400,320,320
23:51:51.694 : echo:1:3;    T2530,6667,120;S400,1,1
23:51:51.696 : echo:2:3;   *T3578,6667,1601;S800,81,81
23:51:51.697 : >0-1>1-2
23:51:51.697 : T
23:51:51.698 : echo:0:3;X/  T1601,6667,2530;S400,320,320
23:51:51.700 : echo:1:3;    T2530,6667,120;S400,1,1
23:51:51.701 : echo:2:3;   *T3578,6667,1601;S800,81,81
23:51:51.702 : ^1^2
23:51:51.703 : echo:0:3;X/  T1601,6667,2530;S400,320,320
23:51:51.705 : echo:1:3;    T2530,6667,3578;S400,400,400
23:51:51.706 : echo:2:3;    T3578,6667,120;S800,1,1
23:51:51.707 : ^3
23:51:51.707 : R
23:51:51.708 : echo:0:4;X/  T1601,6667,2530;S400,320,320
23:51:51.710 : echo:1:4;    T2530,6667,3578;S400,400,400
23:51:51.711 : echo:2:4;    T3578,6667,120;S800,1,1
23:51:51.713 : echo:3:4;   *T3578,6667,1601;S800,81,81
23:51:51.713 : <2-3
23:51:51.713 : F
23:51:51.715 : echo:0:4;X/  T1601,6667,2530;S400,320,320
23:51:51.716 : echo:1:4;    T2530,6667,3578;S400,400,400
23:51:51.718 : echo:2:4;   *T3578,6667,120;S800,1,1
23:51:51.720 : echo:3:4;   *T3578,6667,1601;S800,81,81
23:51:51.720 : >0-1>1-2>2-3
23:51:51.720 : T
23:51:51.722 : echo:0:4;X/  T1601,6667,2530;S400,320,320
23:51:51.723 : echo:1:4;    T2530,6667,3578;S400,400,400
23:51:51.725 : echo:2:4;   *T3578,6667,120;S800,1,1
23:51:51.726 : echo:3:4;   *T3578,6667,1601;S800,81,81
23:51:51.727 : ^1^2^3
23:51:51.729 : echo:0:4;X/  T1601,6667,2530;S400,320,320
23:51:51.730 : echo:1:4;    T2530,6667,3578;S400,400,400
23:51:51.732 : echo:2:4;    T3578,6667,3578;S800,400,400
23:51:51.735 : echo:3:4;    T3578,6667,120;S800,1,1
23:51:51.735 : ^4
23:51:51.735 : R
23:51:51.736 : echo:0:5;X/  T1601,6667,2530;S400,320,320
23:51:51.738 : echo:1:5;    T2530,6667,3578;S400,400,400
23:51:51.740 : echo:2:5;    T3578,6667,3578;S800,400,400
23:51:51.741 : echo:3:5;    T3578,6667,120;S800,1,1
23:51:51.742 : echo:4:5;   *T3578,6667,1601;S800,81,81
23:51:51.744 : <3-4<2-3
23:51:51.744 : F
23:51:51.745 : echo:0:5;X/  T1601,6667,2530;S400,320,320
23:51:51.746 : echo:1:5;    T2530,6667,3578;S400,400,400
23:51:51.749 : echo:2:5;   *T3578,6667,3578;S800,400,400
23:51:51.750 : echo:3:5;   *T3578,6667,120;S800,1,1
23:51:51.751 : echo:4:5;   *T3578,6667,1601;S800,81,81
23:51:51.751 : >0-1>1-2>2-3>3-4
23:51:51.753 : T
23:51:51.754 : echo:0:5;X/  T1601,6667,2530;S400,320,320
23:51:51.755 : echo:1:5;    T2530,6667,3578;S400,400,400
23:51:51.756 : echo:2:5;   *T3578,6667,3578;S800,400,400
23:51:51.759 : echo:3:5;   *T3578,6667,120;S800,1,1
23:51:51.760 : echo:4:5;   *T3578,6667,1601;S800,81,81
23:51:51.760 : ^1^2^3^4
23:51:51.762 : echo:0:5;X/  T1601,6667,2530;S400,320,320
23:51:51.764 : echo:1:5;    T2530,6667,3578;S400,400,400
23:51:51.765 : echo:2:5;    T3578,6667,5060;S800,800,800
23:51:51.767 : echo:3:5;    T5060,6667,3578;S800,0,0
23:51:51.768 : echo:4:5;    T3578,6667,120;S800,1,1
23:51:51.769 : ^5
23:51:51.769 : R
23:51:51.770 : echo:0:6;X/  T1601,6667,2530;S400,320,320
23:51:51.772 : echo:1:6;    T2530,6667,3578;S400,400,400
23:51:51.774 : echo:2:6;    T3578,6667,5060;S800,800,800
23:51:51.775 : echo:3:6;    T5060,6667,3578;S800,0,0
23:51:51.777 : echo:4:6;    T3578,6667,120;S800,1,1
23:51:51.778 : echo:5:6;   *T3578,6667,1601;S800,81,81
23:51:51.779 : <4-5<3-4<2-3
23:51:51.779 : F
23:51:51.781 : echo:0:6;X/  T1601,6667,2530;S400,320,320
23:51:51.782 : echo:1:6;    T2530,6667,3578;S400,400,400
23:51:51.784 : echo:2:6;   *T3578,6667,5060;S800,800,800
23:51:51.786 : echo:3:6;   *T5060,6667,3578;S800,0,0
23:51:51.787 : echo:4:6;   *T3578,6667,120;S800,1,1
23:51:51.788 : echo:5:6;   *T3578,6667,1601;S800,81,81
23:51:51.789 : >0-1>1-2>2-3>3-4>4-5
23:51:51.789 : T
23:51:51.791 : echo:0:6;X/  T1601,6667,2530;S400,320,320
23:51:51.793 : echo:1:6;    T2530,6667,3578;S400,400,400
23:51:51.795 : echo:2:6;   *T3578,6667,5060;S800,800,800
23:51:51.796 : echo:3:6;   *T5060,6667,3578;S800,0,0
23:51:51.797 : echo:4:6;   *T3578,6667,120;S800,1,1
23:51:51.798 : echo:5:6;   *T3578,6667,1601;S800,81,81
23:51:51.800 : ^1^2^3^4^5
23:51:51.801 : echo:0:6;X/  T1601,6667,2530;S400,320,320
23:51:51.802 : echo:1:6;    T2530,6667,3578;S400,400,400
23:51:51.805 : echo:2:6;    T3578,6667,5060;S800,800,800
23:51:51.806 : echo:3:6;    T5060,6667,5060;S800,400,400
23:51:51.807 : echo:4:6;    T5060,6667,3578;S800,0,0
23:51:51.808 : echo:5:6;    T3578,6667,120;S800,1,1
23:51:51.810 : ^6
23:51:51.810 : R
23:51:51.811 : echo:0:7;X/  T1601,6667,2530;S400,320,320
23:51:51.812 : echo:1:7;    T2530,6667,3578;S400,400,400
23:51:51.816 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.817 : echo:3:7;    T5060,6667,5060;S800,400,400
23:51:51.818 : echo:4:7;    T5060,6667,3578;S800,0,0
23:51:51.819 : echo:5:7;    T3578,6667,120;S800,1,1
23:51:51.822 : echo:6:7;   *T3578,6667,1601;S800,81,81
23:51:51.822 : <5-6<4-5<3-4<2-3
23:51:51.822 : F
23:51:51.823 : echo:0:7;X/  T1601,6667,2530;S400,320,320
23:51:51.826 : echo:1:7;    T2530,6667,3578;S400,400,400
23:51:51.827 : echo:2:7;   *T3578,6667,5060;S800,800,800
23:51:51.828 : echo:3:7;   *T5060,6667,5060;S800,400,400
23:51:51.831 : echo:4:7;   *T5060,6667,3578;S800,0,0
23:51:51.832 : echo:5:7;   *T3578,6667,120;S800,1,1
23:51:51.833 : echo:6:7;   *T3578,6667,1601;S800,81,81
23:51:51.835 : >0-1>1-2>2-3>3-4>4-5>5-6
23:51:51.835 : T
23:51:51.836 : echo:0:7;X/  T1601,6667,2530;S400,320,320
23:51:51.837 : echo:1:7;    T2530,6667,3578;S400,400,400
23:51:51.840 : echo:2:7;   *T3578,6667,5060;S800,800,800
23:51:51.841 : echo:3:7;   *T5060,6667,5060;S800,400,400
23:51:51.842 : echo:4:7;   *T5060,6667,3578;S800,0,0
23:51:51.844 : echo:5:7;   *T3578,6667,120;S800,1,1
23:51:51.846 : echo:6:7;   *T3578,6667,1601;S800,81,81
23:51:51.846 : ^1^2^3^4^5^6
23:51:51.847 : echo:0:7;X/  T1601,6667,2530;S400,320,320
23:51:51.850 : echo:1:7;    T2530,6667,3578;S400,400,400
23:51:51.851 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.852 : echo:3:7;    T5060,6667,6198;S800,800,800
23:51:51.854 : echo:4:7;    T6198,6667,5060;S800,0,0
23:51:51.856 : echo:5:7;    T5060,6667,3578;S800,0,0
23:51:51.857 : echo:6:7;    T3578,6667,120;S800,1,1
23:51:51.859 : ^7
23:51:51.859 : R
23:51:51.860 : echo:0:8;X/  T1601,6667,2530;S400,320,320
23:51:51.861 : echo:1:8;    T2530,6667,3578;S400,400,400
23:51:51.864 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.865 : echo:3:7;    T5060,6667,6198;S800,800,800
23:51:51.866 : echo:4:7;    T6198,6667,5060;S800,0,0
23:51:51.868 : echo:5:7;    T5060,6667,3578;S800,0,0
23:51:51.869 : echo:6:7;    T3578,6667,120;S800,1,1
23:51:51.872 : echo:7:7;   *T3578,6667,1601;S800,81,81
23:51:51.872 : <6-7<5-6<4-5<3-4
23:51:51.872 : F
23:51:51.874 : echo:1:7;X   T2530,6667,3578;S400,400,400
23:51:51.876 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.877 : echo:3:7;   *T5060,6667,6198;S800,800,800
23:51:51.878 : echo:4:7;   *T6198,6667,5060;S800,0,0
23:51:51.881 : echo:5:7;   *T5060,6667,3578;S800,0,0
23:51:51.882 : echo:6:7;   *T3578,6667,120;S800,1,1
23:51:51.883 : echo:7:7;   *T3578,6667,1601;S800,81,81
23:51:51.884 : >1-2>2-3>3-4>4-5>5-6>6-7
23:51:51.884 : T
23:51:51.886 : echo:1:7;X   T2530,6667,3578;S400,400,400
23:51:51.889 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.890 : echo:3:7;   *T5060,6667,6198;S800,800,800
23:51:51.892 : echo:4:7;   *T6198,6667,5060;S800,0,0
23:51:51.893 : echo:5:7;   *T5060,6667,3578;S800,0,0
23:51:51.894 : echo:6:7;   *T3578,6667,120;S800,1,1
23:51:51.897 : echo:7:7;   *T3578,6667,1601;S800,81,81
23:51:51.897 : ^2^3^4^5^6^7
23:51:51.898 : echo:1:7;X   T2530,6667,3578;S400,400,400
23:51:51.900 : echo:2:7;    T3578,6667,5060;S800,800,800
23:51:51.902 : echo:3:7;    T5060,6667,6198;S800,800,800
23:51:51.903 : echo:4:7;    T6198,6667,6198;S800,378,423
23:51:51.904 : echo:5:7;    T6198,6667,5060;S800,0,0
23:51:51.907 : echo:6:7;    T5060,6667,3578;S800,0,0
23:51:51.908 : echo:7:7;    T3578,6667,120;S800,1,1
23:51:51.908 : ^8
23:51:51.908 : R
23:51:51.909 : echo:1:8;X   T2530,6667,3578;S400,400,400
23:51:51.912 : echo:2:8;    T3578,6667,5060;S800,800,800
23:51:51.913 : echo:3:8;    T5060,6667,6198;S800,800,800
23:51:51.915 : echo:4:8;    T6198,6667,6198;S800,378,423
23:51:51.916 : echo:5:8;    T6198,6667,5060;S800,0,0
23:51:51.918 : echo:6:8;    T5060,6667,3578;S800,0,0
23:51:51.920 : echo:7:8;    T3578,6667,120;S800,1,1
23:51:51.921 : echo:8:8;   *T3578,6667,1601;S800,81,81
23:51:51.922 : <7-8<6-7<5-6<4-5<3-4
23:51:51.922 : F
23:51:51.923 : echo:1:8;X   T2530,6667,3578;S400,400,400
23:51:51.925 : echo:2:8;    T3578,6667,5060;S800,800,800
23:51:51.927 : echo:3:8;   *T5060,6667,6198;S800,800,800
23:51:51.929 : echo:4:8;   *T6198,6667,6198;S800,378,423
23:51:51.930 : echo:5:8;   *T6198,6667,5060;S800,0,0
23:51:51.931 : echo:6:8;   *T5060,6667,3578;S800,0,0
23:51:51.933 : echo:7:8;   *T3578,6667,120;S800,1,1
23:51:51.935 : echo:8:8;   *T3578,6667,1601;S800,81,81
23:51:51.936 : >1-2>2-3>3-4>4-5>5-6>6-7>7-8
23:51:51.936 : T
23:51:51.937 : echo:1:8;X   T2530,6667,3578;S400,400,400
23:51:51.939 : echo:2:8;    T3578,6667,5060;S800,800,800
23:51:51.941 : echo:3:8;   *T5060,6667,6198;S800,800,800
23:51:51.942 : echo:4:8;   *T6198,6667,6198;S800,378,423
23:51:51.944 : echo:5:8;   *T6198,6667,5060;S800,0,0
23:51:51.945 : echo:6:8;   *T5060,6667,3578;S800,0,0
23:51:51.948 : echo:7:8;   *T3578,6667,120;S800,1,1
23:51:51.950 : echo:8:8;   *T3578,6667,1601;S800,81,81
23:51:51.950 : ^2^3^4^5^6^7^8
23:51:51.952 : echo:1:8;X   T2530,6667,3578;S400,400,400
23:51:51.953 : echo:2:8;    T3578,6667,5060;S800,800,800
23:51:51.955 : echo:3:8;    T5060,6667,6198;S800,800,800
23:51:51.957 : echo:4:8;    T6198,6667,6667;S800,378,800
23:51:51.959 : echo:5:8;    T6667,6667,6198;S800,0,423
23:51:51.960 : echo:6:8;    T6198,6667,5060;S800,0,0
23:51:51.961 : echo:7:8;    T5060,6667,3578;S800,0,0
23:51:51.962 : echo:8:8;    T3578,6667,120;S800,1,1
23:51:51.964 : ^9
23:51:51.964 : R
23:51:51.965 : echo:1:9;X   T2530,6667,3578;S400,400,400
23:51:51.966 : echo:2:9;    T3578,6667,5060;S800,800,800
23:51:51.969 : echo:3:9;    T5060,6667,6198;S800,800,800
23:51:51.970 : echo:4:9;    T6198,6667,6667;S800,378,800
23:51:51.971 : echo:5:9;    T6667,6667,6198;S800,0,423
23:51:51.972 : echo:6:9;    T6198,6667,5060;S800,0,0
23:51:51.974 : echo:7:9;    T5060,6667,3578;S800,0,0
23:51:51.976 : echo:8:9;    T3578,6667,120;S800,1,1
23:51:51.978 : echo:9:9;   *T3578,6667,1601;S800,81,81
23:51:51.979 : <8-9<7-8<6-7<5-6<4-5<3-4
23:51:51.979 : F
23:51:51.980 : echo:1:9;X   T2530,6667,3578;S400,400,400
23:51:51.981 : echo:2:9;    T3578,6667,5060;S800,800,800
23:51:51.984 : echo:3:9;   *T5060,6667,6198;S800,800,800
23:51:51.985 : echo:4:9;   *T6198,6667,6667;S800,378,800
23:51:51.986 : echo:5:9;    T6667,6667,6198;S800,0,423
23:51:51.988 : echo:6:9;   *T6198,6667,5060;S800,0,0
23:51:51.990 : echo:7:9;   *T5060,6667,3578;S800,0,0
23:51:51.992 : echo:8:9;   *T3578,6667,120;S800,1,1
23:51:51.993 : echo:9:9;   *T3578,6667,1601;S800,81,81
23:51:51.994 : >1-2>2-3>3-4>4-5>5-6>6-7>7-8>8-9
23:51:51.994 : T
23:51:51.995 : echo:2:8;X   T3578,6667,5060;S800,800,800
23:51:51.998 : echo:3:8;   *T5060,6667,6198;S800,800,800
23:51:51.999 : echo:4:8;   *T6198,6667,6667;S800,378,800
23:51:52.000 : echo:5:8;    T6667,6667,6198;S800,0,423
23:51:52.002 : echo:6:8;   *T6198,6667,5060;S800,0,0
23:51:52.004 : echo:7:8;   *T5060,6667,3578;S800,0,0
23:51:52.006 : echo:8:8;   *T3578,6667,120;S800,1,1
23:51:52.007 : echo:9:8;   *T3578,6667,1601;S800,81,81
23:51:52.009 : ^2^3^4^5^6^7^8^9
23:51:52.011 : echo:2:8;X   T3578,6667,5060;S800,800,800
23:51:52.012 : echo:3:8;    T5060,6667,6198;S800,800,800
23:51:52.014 : echo:4:8;    T6198,6667,6667;S800,378,800
23:51:52.016 : echo:5:8;    T6667,6667,6667;S800,0,800
23:51:52.018 : echo:6:8;    T6667,6667,6198;S800,0,423
23:51:52.019 : echo:7:8;    T6198,6667,5060;S800,0,0
23:51:52.020 : echo:8:8;    T5060,6667,3578;S800,0,0
23:51:52.023 : echo:9:8;    T3578,6667,120;S800,1,1
23:51:52.024 : ^10
23:51:52.025 : R
23:51:52.026 : echo:2:9;X   T3578,6667,5060;S800,800,800
23:51:52.027 : echo:3:9;    T5060,6667,6198;S800,800,800
23:51:52.030 : echo:4:9;    T6198,6667,6667;S800,378,800
23:51:52.031 : echo:5:9;    T6667,6667,6667;S800,0,800
23:51:52.032 : echo:6:9;    T6667,6667,6198;S800,0,423
23:51:52.034 : echo:7:9;    T6198,6667,5060;S800,0,0
23:51:52.035 : echo:8:9;    T5060,6667,3578;S800,0,0
23:51:52.037 : echo:9:9;    T3578,6667,120;S800,1,1
23:51:52.039 : echo:10:9; / *T1601,6667,1601;S800,400,400
23:51:52.039 : F
23:51:52.040 : echo:2:9;X   T3578,6667,5060;S800,800,800
23:51:52.042 : echo:3:9;    T5060,6667,6198;S800,800,800
23:51:52.044 : echo:4:9;    T6198,6667,6667;S800,378,800
23:51:52.045 : echo:5:9;    T6667,6667,6667;S800,0,800
23:51:52.047 : echo:6:9;    T6667,6667,6198;S800,0,423
23:51:52.049 : echo:7:9;    T6198,6667,5060;S800,0,0
23:51:52.050 : echo:8:9;    T5060,6667,3578;S800,0,0
23:51:52.051 : echo:9:9;    T3578,6667,120;S800,1,1
23:51:52.053 : echo:10:9; / *T1601,6667,1601;S800,400,400
23:51:52.054 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10
23:51:52.055 : T
23:51:52.056 : echo:2:9;X   T3578,6667,5060;S800,800,800
23:51:52.058 : echo:3:9;    T5060,6667,6198;S800,800,800
23:51:52.059 : echo:4:9;    T6198,6667,6667;S800,378,800
23:51:52.061 : echo:5:9;    T6667,6667,6667;S800,0,800
23:51:52.063 : echo:6:9;    T6667,6667,6198;S800,0,423
23:51:52.064 : echo:7:9;    T6198,6667,5060;S800,0,0
23:51:52.065 : echo:8:9;    T5060,6667,3578;S800,0,0
23:51:52.066 : echo:9:9;    T3578,6667,120;S800,1,1
23:51:52.069 : echo:10:9; / *T1601,6667,1601;S800,400,400
23:51:52.069 : ^9^10
23:51:52.070 : echo:2:9;X   T3578,6667,5060;S800,800,800
23:51:52.073 : echo:3:9;    T5060,6667,6198;S800,800,800
23:51:52.074 : echo:4:9;    T6198,6667,6667;S800,378,800
23:51:52.075 : echo:5:9;    T6667,6667,6667;S800,0,800
23:51:52.077 : echo:6:9;    T6667,6667,6198;S800,0,423
23:51:52.079 : echo:7:9;    T6198,6667,5060;S800,0,0
23:51:52.080 : echo:8:9;    T5060,6667,3578;S800,0,0
23:51:52.082 : echo:9:9;    T3578,6667,1601;S800,81,81
23:51:52.083 : echo:10:9; /  T1601,6667,120;S800,321,321
23:51:52.086 : ^11
23:51:52.086 : R
23:51:52.087 : echo:2:10;X   T3578,6667,5060;S800,800,800
23:51:52.088 : echo:3:10;    T5060,6667,6198;S800,800,800
23:51:52.092 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.093 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.094 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.096 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.098 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.099 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.101 : echo:10:10; /  T1601,6667,120;S800,321,321
23:51:52.103 : echo:11:10;   *T3578,6667,1601;S800,81,81
23:51:52.103 : <10-11
23:51:52.103 : F
23:51:52.105 : echo:2:10;X   T3578,6667,5060;S800,800,800
23:51:52.107 : echo:3:10;    T5060,6667,6198;S800,800,800
23:51:52.108 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.110 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.112 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.113 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.115 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.116 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.119 : echo:10:10; /  T1601,6667,120;S800,321,321
23:51:52.120 : echo:11:10;   *T3578,6667,1601;S800,81,81
23:51:52.121 : >2-3>3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11
23:51:52.122 : T
23:51:52.124 : echo:2:10;X   T3578,6667,5060;S800,800,800
23:51:52.125 : echo:3:10;    T5060,6667,6198;S800,800,800
23:51:52.127 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.129 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.131 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.132 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.133 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.136 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.137 : echo:10:10; /  T1601,6667,120;S800,321,321
23:51:52.139 : echo:11:10;   *T3578,6667,1601;S800,81,81
23:51:52.139 : ^10^11
23:51:52.142 : echo:2:10;X   T3578,6667,5060;S800,800,800
23:51:52.143 : echo:3:10;    T5060,6667,6198;S800,800,800
23:51:52.145 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.147 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.148 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.150 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.151 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.153 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.155 : echo:10:10; /  T1601,6667,3578;S800,720,720
23:51:52.156 : echo:11:10;    T3578,6667,120;S800,1,1
23:51:52.160 : ^12
23:51:52.160 : R
23:51:52.161 : echo:2:11;X   T3578,6667,5060;S800,800,800
23:51:52.163 : echo:3:11;    T5060,6667,6198;S800,800,800
23:51:52.165 : echo:4:11;    T6198,6667,6667;S800,378,800
23:51:52.167 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.168 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.170 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.172 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.173 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.175 : echo:10:11; /  T1601,6667,3578;S800,720,720
23:51:52.177 : echo:11:11;    T3578,6667,120;S800,1,1
23:51:52.179 : echo:12:11;   *T3578,6667,1601;S800,81,81
23:51:52.179 : <11-12<10-11
23:51:52.179 : F
23:51:52.182 : echo:3:10;X   T5060,6667,6198;S800,800,800
23:51:52.183 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.184 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.187 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.188 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.189 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.191 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.193 : echo:10:10; /  T1601,6667,3578;S800,720,720
23:51:52.195 : echo:11:10;   *T3578,6667,120;S800,1,1
23:51:52.196 : echo:12:10;   *T3578,6667,1601;S800,81,81
23:51:52.199 : >3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12
23:51:52.199 : T
23:51:52.201 : echo:3:10;X   T5060,6667,6198;S800,800,800
23:51:52.202 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.205 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.206 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.207 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.209 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.211 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.213 : echo:10:10; /  T1601,6667,3578;S800,720,720
23:51:52.215 : echo:11:10;   *T3578,6667,120;S800,1,1
23:51:52.216 : echo:12:10;   *T3578,6667,1601;S800,81,81
23:51:52.219 : ^10^11^12
23:51:52.220 : echo:3:10;X   T5060,6667,6198;S800,800,800
23:51:52.222 : echo:4:10;    T6198,6667,6667;S800,378,800
23:51:52.225 : echo:5:10;    T6667,6667,6667;S800,0,800
23:51:52.226 : echo:6:10;    T6667,6667,6198;S800,0,423
23:51:52.227 : echo:7:10;    T6198,6667,5060;S800,0,0
23:51:52.229 : echo:8:10;    T5060,6667,3578;S800,0,0
23:51:52.231 : echo:9:10;    T3578,6667,1601;S800,81,81
23:51:52.233 : echo:10:10; /  T1601,6667,3920;S800,800,800
23:51:52.235 : echo:11:10;    T3920,6667,3578;S800,320,320
23:51:52.237 : echo:12:10;    T3578,6667,120;S800,1,1
23:51:52.240 : ^13
23:51:52.240 : R
23:51:52.241 : echo:3:11;X   T5060,6667,6198;S800,800,800
23:51:52.242 : echo:4:11;    T6198,6667,6667;S800,378,800
23:51:52.245 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.246 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.248 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.249 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.252 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.253 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.254 : echo:11:11;    T3920,6667,3578;S800,320,320
23:51:52.257 : echo:12:11;    T3578,6667,120;S800,1,1
23:51:52.259 : echo:13:11;   *T3578,6667,1601;S800,81,81
23:51:52.260 : <12-13<11-12<10-11
23:51:52.260 : F
23:51:52.261 : echo:3:11;X   T5060,6667,6198;S800,800,800
23:51:52.263 : echo:4:11;    T6198,6667,6667;S800,378,800
23:51:52.266 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.267 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.268 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.269 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.272 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.274 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.275 : echo:11:11;   *T3920,6667,3578;S800,320,320
23:51:52.278 : echo:12:11;   *T3578,6667,120;S800,1,1
23:51:52.279 : echo:13:11;   *T3578,6667,1601;S800,81,81
23:51:52.282 : >3-4>4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13
23:51:52.282 : T
23:51:52.285 : echo:3:11;X   T5060,6667,6198;S800,800,800
23:51:52.286 : echo:4:11;    T6198,6667,6667;S800,378,800
23:51:52.288 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.290 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.292 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.293 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.294 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.297 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.299 : echo:11:11;   *T3920,6667,3578;S800,320,320
23:51:52.300 : echo:12:11;   *T3578,6667,120;S800,1,1
23:51:52.305 : echo:13:11;   *T3578,6667,1601;S800,81,81
23:51:52.305 : ^10^11^12^13
23:51:52.307 : echo:3:11;X   T5060,6667,6198;S800,800,800
23:51:52.310 : echo:4:11;    T6198,6667,6667;S800,378,800
23:51:52.311 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.313 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.315 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.317 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.318 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.319 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.322 : echo:11:11;    T3920,6667,5060;S800,720,720
23:51:52.324 : echo:12:11;    T5060,6667,3578;S800,0,0
23:51:52.326 : echo:13:10;    T3578,6667,120;S800,1,1
23:51:52.329 : ^14
23:51:52.329 : R
23:51:52.330 : echo:4:11;X   T6198,6667,6667;S800,378,800
23:51:52.332 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.334 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.336 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.337 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.338 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.341 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.343 : echo:11:11;    T3920,6667,5060;S800,720,720
23:51:52.344 : echo:12:11;    T5060,6667,3578;S800,0,0
23:51:52.347 : echo:13:11;    T3578,6667,120;S800,1,1
23:51:52.349 : echo:14:11;   *T3578,6667,1601;S800,81,81
23:51:52.350 : <13-14<12-13<11-12<10-11
23:51:52.350 : F
23:51:52.353 : echo:4:11;X   T6198,6667,6667;S800,378,800
23:51:52.354 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.357 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.358 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.360 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.361 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.364 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.365 : echo:11:11;   *T3920,6667,5060;S800,720,720
23:51:52.367 : echo:12:11;   *T5060,6667,3578;S800,0,0
23:51:52.370 : echo:13:11;   *T3578,6667,120;S800,1,1
23:51:52.371 : echo:14:11;   *T3578,6667,1601;S800,81,81
23:51:52.373 : >4-5>5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14
23:51:52.373 : T
23:51:52.376 : echo:4:11;X   T6198,6667,6667;S800,378,800
23:51:52.378 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.379 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.382 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.383 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.384 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.386 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.388 : echo:11:11;   *T3920,6667,5060;S800,720,720
23:51:52.390 : echo:12:11;   *T5060,6667,3578;S800,0,0
23:51:52.391 : echo:13:11;   *T3578,6667,120;S800,1,1
23:51:52.397 : echo:14:11;   *T3578,6667,1601;S800,81,81
23:51:52.397 : ^10^11^12^13^14
23:51:52.398 : echo:4:11;X   T6198,6667,6667;S800,378,800
23:51:52.401 : echo:5:11;    T6667,6667,6667;S800,0,800
23:51:52.402 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.404 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.405 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.407 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.409 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.410 : echo:11:11;    T3920,6667,5307;S800,800,800
23:51:52.413 : echo:12:11;    T5307,6667,5060;S800,320,320
23:51:52.414 : echo:13:11;    T5060,6667,3578;S800,0,0
23:51:52.417 : echo:14:11;    T3578,6667,120;S800,1,1
23:51:52.419 : ^15
23:51:52.419 : R
23:51:52.421 : echo:4:12;X   T6198,6667,6667;S800,378,800
23:51:52.422 : echo:5:12;    T6667,6667,6667;S800,0,800
23:51:52.425 : echo:6:12;    T6667,6667,6198;S800,0,423
23:51:52.426 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.427 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.429 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.432 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.434 : echo:11:12;    T3920,6667,5307;S800,800,800
23:51:52.435 : echo:12:12;    T5307,6667,5060;S800,320,320
23:51:52.438 : echo:13:12;    T5060,6667,3578;S800,0,0
23:51:52.439 : echo:14:12;    T3578,6667,120;S800,1,1
23:51:52.440 : echo:15:12;   *T3578,6667,1601;S800,81,81
23:51:52.442 : <14-15<13-14<12-13<11-12<10-11
23:51:52.442 : F
23:51:52.445 : echo:4:12;X   T6198,6667,6667;S800,378,800
23:51:52.446 : echo:5:12;    T6667,6667,6667;S800,0,800
23:51:52.447 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.449 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.451 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.453 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.454 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.457 : echo:11:11;   *T3920,6667,5307;S800,800,800
23:51:52.458 : echo:12:11;   *T5307,6667,5060;S800,320,320
23:51:52.460 : echo:13:11;   *T5060,6667,3578;S800,0,0
23:51:52.461 : echo:14:11;   *T3578,6667,120;S800,1,1
23:51:52.464 : echo:15:11;   *T3578,6667,1601;S800,81,81
23:51:52.466 : >5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15
23:51:52.466 : T
23:51:52.468 : echo:5:11;X   T6667,6667,6667;S800,0,800
23:51:52.470 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.471 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.472 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.475 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.476 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.477 : echo:11:11;   *T3920,6667,5307;S800,800,800
23:51:52.480 : echo:12:11;   *T5307,6667,5060;S800,320,320
23:51:52.481 : echo:13:11;   *T5060,6667,3578;S800,0,0
23:51:52.483 : echo:14:11;   *T3578,6667,120;S800,1,1
23:51:52.489 : echo:15:11;   *T3578,6667,1601;S800,81,81
23:51:52.489 : ^10^11^12^13^14^15
23:51:52.493 : echo:5:11;X   T6667,6667,6667;S800,0,800
23:51:52.494 : echo:6:11;    T6667,6667,6198;S800,0,423
23:51:52.495 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.496 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.499 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.500 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.502 : echo:11:11;    T3920,6667,5307;S800,800,800
23:51:52.505 : echo:12:11;    T5307,6667,6198;S800,721,721
23:51:52.506 : echo:13:11;    T6198,6667,5060;S800,0,0
23:51:52.507 : echo:14:11;    T5060,6667,3578;S800,0,0
23:51:52.510 : echo:15:11;    T3578,6667,120;S800,1,1
23:51:52.512 : ^0
23:51:52.512 : R
23:51:52.514 : echo:5:12;X   T6667,6667,6667;S800,0,800
23:51:52.515 : echo:6:12;    T6667,6667,6198;S800,0,423
23:51:52.516 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.519 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.520 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.521 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.524 : echo:11:12;    T3920,6667,5307;S800,800,800
23:51:52.526 : echo:12:12;    T5307,6667,6198;S800,721,721
23:51:52.527 : echo:13:12;    T6198,6667,5060;S800,0,0
23:51:52.530 : echo:14:12;    T5060,6667,3578;S800,0,0
23:51:52.531 : echo:15:12;    T3578,6667,120;S800,1,1
23:51:52.532 : echo:0:12;   *T3578,6667,1601;S800,81,81
23:51:52.534 : <15-0<14-15<13-14<12-13<11-12<10-11
23:51:52.534 : F
23:51:52.537 : echo:5:12;X   T6667,6667,6667;S800,0,800
23:51:52.538 : echo:6:12;    T6667,6667,6198;S800,0,423
23:51:52.539 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.541 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.543 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.544 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.546 : echo:11:12;   *T3920,6667,5307;S800,800,800
23:51:52.549 : echo:12:12;   *T5307,6667,6198;S800,721,721
23:51:52.550 : echo:13:12;   *T6198,6667,5060;S800,0,0
23:51:52.551 : echo:14:12;   *T5060,6667,3578;S800,0,0
23:51:52.552 : echo:15:12;   *T3578,6667,120;S800,1,1
23:51:52.555 : echo:0:12;   *T3578,6667,1601;S800,81,81
23:51:52.557 : >5-6>6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0
23:51:52.557 : T
23:51:52.560 : echo:5:12;X   T6667,6667,6667;S800,0,800
23:51:52.561 : echo:6:12;    T6667,6667,6198;S800,0,423
23:51:52.562 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.564 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.567 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.569 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.571 : echo:11:11;   *T3920,6667,5307;S800,800,800
23:51:52.573 : echo:12:11;   *T5307,6667,6198;S800,721,721
23:51:52.574 : echo:13:11;   *T6198,6667,5060;S800,0,0
23:51:52.575 : echo:14:11;   *T5060,6667,3578;S800,0,0
23:51:52.578 : echo:15:11;   *T3578,6667,120;S800,1,1
23:51:52.583 : echo:0:11;   *T3578,6667,1601;S800,81,81
23:51:52.585 : ^10^11^12^13^14^15^0
23:51:52.586 : echo:6:11;X   T6667,6667,6198;S800,0,423
23:51:52.587 : echo:7:11;    T6198,6667,5060;S800,0,0
23:51:52.588 : echo:8:11;    T5060,6667,3578;S800,0,0
23:51:52.591 : echo:9:11;    T3578,6667,1601;S800,81,81
23:51:52.592 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.594 : echo:11:11;    T3920,6667,5307;S800,800,800
23:51:52.597 : echo:12:11;    T5307,6667,6401;S800,800,800
23:51:52.598 : echo:13:11;    T6401,6667,6198;S800,218,423
23:51:52.599 : echo:14:11;    T6198,6667,5060;S800,0,0
23:51:52.602 : echo:15:11;    T5060,6667,3578;S800,0,0
23:51:52.603 : echo:0:11;    T3578,6667,120;S800,1,1
23:51:52.606 : ^1
23:51:52.606 : R
23:51:52.607 : echo:6:12;X   T6667,6667,6198;S800,0,423
23:51:52.608 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.610 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.612 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.614 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.615 : echo:11:12;    T3920,6667,5307;S800,800,800
23:51:52.618 : echo:12:12;    T5307,6667,6401;S800,800,800
23:51:52.619 : echo:13:12;    T6401,6667,6198;S800,218,423
23:51:52.621 : echo:14:12;    T6198,6667,5060;S800,0,0
23:51:52.623 : echo:15:12;    T5060,6667,3578;S800,0,0
23:51:52.624 : echo:0:12;    T3578,6667,120;S800,1,1
23:51:52.626 : echo:1:12;   *T3578,6667,1601;S800,81,81
23:51:52.628 : <0-1<15-0<14-15<13-14<12-13<11-12<10-11
23:51:52.628 : F
23:51:52.630 : echo:6:12;X   T6667,6667,6198;S800,0,423
23:51:52.632 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.633 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.635 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.638 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.640 : echo:11:12;   *T3920,6667,5307;S800,800,800
23:51:52.643 : echo:12:12;   *T5307,6667,6401;S800,800,800
23:51:52.645 : echo:13:12;   *T6401,6667,6198;S800,218,423
23:51:52.646 : echo:14:12;   *T6198,6667,5060;S800,0,0
23:51:52.648 : echo:15:12;   *T5060,6667,3578;S800,0,0
23:51:52.650 : echo:0:12;   *T3578,6667,120;S800,1,1
23:51:52.652 : echo:1:12;   *T3578,6667,1601;S800,81,81
23:51:52.655 : >6-7>7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0>0-1
23:51:52.656 : T
23:51:52.657 : echo:6:12;X   T6667,6667,6198;S800,0,423
23:51:52.658 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.660 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.663 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.664 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.666 : echo:11:12;   *T3920,6667,5307;S800,800,800
23:51:52.669 : echo:12:12;   *T5307,6667,6401;S800,800,800
23:51:52.670 : echo:13:12;   *T6401,6667,6198;S800,218,423
23:51:52.672 : echo:14:12;   *T6198,6667,5060;S800,0,0
23:51:52.674 : echo:15:12;   *T5060,6667,3578;S800,0,0
23:51:52.675 : echo:0:12;   *T3578,6667,120;S800,1,1
23:51:52.679 : echo:1:12;   *T3578,6667,1601;S800,81,81
23:51:52.683 : ^10^11^12^13^14^15^0^1
23:51:52.685 : echo:6:12;X   T6667,6667,6198;S800,0,423
23:51:52.686 : echo:7:12;    T6198,6667,5060;S800,0,0
23:51:52.689 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.690 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.692 : echo:10:11; /  T1601,6667,3920;S800,800,800
23:51:52.695 : echo:11:11;    T3920,6667,5307;S800,800,800
23:51:52.696 : echo:12:11;    T5307,6667,6401;S800,800,800
23:51:52.698 : echo:13:11;    T6401,6667,6667;S800,218,800
23:51:52.700 : echo:14:11;    T6667,6667,6198;S800,0,423
23:51:52.702 : echo:15:11;    T6198,6667,5060;S800,0,0
23:51:52.703 : echo:0:11;    T5060,6667,3578;S800,0,0
23:51:52.704 : echo:1:11;    T3578,6667,120;S800,1,1
23:51:52.708 : ^2
23:51:52.708 : R
23:51:52.710 : echo:7:12;X   T6198,6667,5060;S800,0,0
23:51:52.711 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.712 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.716 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.718 : echo:11:12;    T3920,6667,5307;S800,800,800
23:51:52.719 : echo:12:12;    T5307,6667,6401;S800,800,800
23:51:52.722 : echo:13:12;    T6401,6667,6667;S800,218,800
23:51:52.723 : echo:14:12;    T6667,6667,6198;S800,0,423
23:51:52.725 : echo:15:12;    T6198,6667,5060;S800,0,0
23:51:52.727 : echo:0:12;    T5060,6667,3578;S800,0,0
23:51:52.729 : echo:1:12;    T3578,6667,120;S800,1,1
23:51:52.730 : echo:2:12;   *T3578,6667,1601;S800,81,81
23:51:52.732 : <1-2<0-1<15-0<14-15<13-14<12-13<11-12<10-11
23:51:52.734 : F
23:51:52.735 : echo:7:12;X   T6198,6667,5060;S800,0,0
23:51:52.736 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.737 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.740 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.742 : echo:11:12;   *T3920,6667,5307;S800,800,800
23:51:52.743 : echo:12:12;   *T5307,6667,6401;S800,800,800
23:51:52.746 : echo:13:12;   *T6401,6667,6667;S800,218,800
23:51:52.747 : echo:14:12;    T6667,6667,6198;S800,0,423
23:51:52.749 : echo:15:12;   *T6198,6667,5060;S800,0,0
23:51:52.751 : echo:0:12;   *T5060,6667,3578;S800,0,0
23:51:52.753 : echo:1:12;   *T3578,6667,120;S800,1,1
23:51:52.754 : echo:2:12;   *T3578,6667,1601;S800,81,81
23:51:52.758 : >7-8>8-9>9-10>10-11>11-12>12-13>13-14>14-15>15-0>0-1>1-2
23:51:52.758 : T
23:51:52.759 : echo:7:12;X   T6198,6667,5060;S800,0,0
23:51:52.760 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.763 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.764 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.766 : echo:11:12;   *T3920,6667,5307;S800,800,800
23:51:52.769 : echo:12:12;   *T5307,6667,6401;S800,800,800
23:51:52.770 : echo:13:12;   *T6401,6667,6667;S800,218,800
23:51:52.771 : echo:14:12;    T6667,6667,6198;S800,0,423
23:51:52.774 : echo:15:12;   *T6198,6667,5060;S800,0,0
23:51:52.775 : echo:0:12;   *T5060,6667,3578;S800,0,0
23:51:52.776 : echo:1:12;   *T3578,6667,120;S800,1,1
23:51:52.779 : echo:2:12;   *T3578,6667,1601;S800,81,81
23:51:52.785 : ^10^11^12^13^14^15^0^1^2
23:51:52.786 : echo:7:12;X   T6198,6667,5060;S800,0,0
23:51:52.789 : echo:8:12;    T5060,6667,3578;S800,0,0
23:51:52.790 : echo:9:12;    T3578,6667,1601;S800,81,81
23:51:52.791 : echo:10:12; /  T1601,6667,3920;S800,800,800
23:51:52.794 : echo:11:12;    T3920,6667,5307;S800,800,800
23:51:52.796 : echo:12:12;    T5307,6667,6401;S800,800,800
23:51:52.797 : echo:13:12;    T6401,6667,6667;S800,218,800
23:51:52.800 : echo:14:12;    T6667,6667,6667;S800,0,800
23:51:52.801 : echo:15:12;    T6667,6667,6198;S800,0,423
23:51:52.802 : echo:0:12;    T6198,6667,5060;S800,0,0
23:51:52.804 : echo:1:12;    T5060,6667,3578;S800,0,0
23:51:52.807 : echo:2:12;    T3578,6667,120;S800,1,1

You can find the complete test code in https://github.com/AnHardt/Marlin/pull/80

[Roxy-3D]

Slow
and even so when the reverse_pass() is really needed (nominal_rate faster than can be reached in one block )
Fast
You can find the complete test code in AnHardt#80

I don't understand what Slow and Fast refer to? Its not the speed of the algorithm, right?

[AnHardt]

It's the value of F, in the g-code, what here makes the difference if 'nominal_rate' can be reached in one block or not.
Accelerations are low in this example to fill the buffer even with lots of output on the serial.

[AnHardt]

After finally understanding what should go on and what was going on, her my hopefully a bit more readable and working version:

/**
 * recalculate() needs to go over the current plan twice.
 * Once in reverse and once forward. This implements the reverse pass.
 */
void Planner::reverse_pass() {
  if (movesplanned() > 3) {
    uint8_t endnr = BLOCK_MOD(block_buffer_tail + 2); // tail is running. tail+1 should not be altered because it's connected to the running block.
                                                      // tail+2 because the index is not already advanced when checked
    uint8_t blocknr = prev_block_index(block_buffer_head);
    block_t* current = &block_buffer[blocknr];

    do {
      block_t* next = current;
      blocknr = prev_block_index(blocknr);
      current = &block_buffer[blocknr];
      if(TEST(current->flag, BLOCK_BIT_START_FROM_FULL_HALT)) //before of that every block is already optimized.
        break;
      reverse_pass_kernel(current, next);
    } while (blocknr != endnr);
  }
}

[tcm0116]

@thinkyhead I think there's an issue in 1.1.7 with the changes that were made to resolve this issue. I'm attempting to perform a print with several different parts, and I've noticed that at the end of some travel movements, it appears that the movement suddenly stops, resulting in a noticeable thud. I've got my acceleration values set to 800 all around and X/Y jerk set to 12. The changes in direction for normal printing movements are very smooth.

The issue seems to be worse as a function of the amount of change in direction at the end of the travel movement, with a full 180 degree stop and continue being the worst. This seems very similar to what I was experiencing during my experimentation in https://github.com/MarlinFirmware/Marlin/issues/8595#issuecomment-348074555.

[tcm0116]

Here's a video showing the issue. You can hear the thud just before three seconds in.

https://photos.app.goo.gl/sminpjsg7JPvhxvx2

[tcm0116]

After a bunch of experimenting, I ended up reverting back to 1.1.6, and the issue is not there.

The major concern with this issue is that the immediate stop over-torques the stepper motor and was causing it to lose steps.

[thinkyhead]

I've noticed that at the end of some travel movements, it appears that the movement suddenly stops, resulting in a noticeable thud.

Thanks for the video! I've been trying to discover the cause in issue #8808. The problem will go away if you disable SEGMENT_LEVELED_MOVES.

[tcm0116]

I had SEGMENT_LEVELED_MOVES disabled, but was using UBL.

[hg42]

is there a relation to ubl issue #8684 on bugfix-2.0.x?
could be introduced by incorporating some changes from 2.0.x to 1.1.7
if so the changes between the two versions in that issue might give a hint...

[tcm0116]

I don't think UBL in itself can cause this type of motion issue. What I
think is happening is that the segmented moves are exposing the issue,
which is why the issue was seen when SEGMENT_LEVELED_MOVES or UBL are
enabled. I suspect it would happen with bilinear leveling also.

In my case, I couldn't figure out why it wasn't happening during every
travel movement, but my hypothesis above would explain it since movements
with UBL (with SEGMENT_LEVELED_MOVES disabled) are only segmented if the
movement crosses a grid boundary.

[thinkyhead]

@tcm0116 I'm trying to narrow down the cause of the issue now. I'm about to test some points in time and see where this starts.

• December 8
• December 4
• November 31

It's due to some specific change after the end of November, or maybe some poison combination of changes. I hope to be able to find the one or two responsible and get this patched tonight!

[tcm0116]

@thinkyhead sounds like a plan! I started does that path, but it was 3:30am
and I needed to get to bed.

[thinkyhead]

Revert this commit and it also fixes the issue: ec028bf747ff7fe99c4fac29f0df62491db2528c

@Bob-the-Kuhn I guess we need to have another look at #8735 "Initial Step Correction."

@tcm0116 Please test the bf1_reverting_8735 branch and see if it solves the issue.

[tcm0116]

@thinkyead it appears that reverting https://github.com/MarlinFirmware/Marlin/commit/ec028bf747ff7fe99c4fac29f0df62491db2528c resolves the issue for me.

[thinkyhead]

@tcm0116 Good news! The issue that #8735 addresses is subtle and maybe even esoteric, so I think we can take our time with it.

[tcm0116]

It's just a shame that it made it into 1.1.7. Since it's pretty
problematic, are we going to quickly release 1.1.8 or re-release 1.1.7 with
that change reverted?

[thinkyhead]

…quickly release 1.1.8 or re-release 1.1.7…?

Got it covered!