Ah yes, count must be under 32767 now in the stepcompress branch (int16_t rather than uint16_t; avoids a need of uint16_t → uint32_t cast in some codepaths on MCU).
So, you can try count=30000 and see how it goes.
Unfortunately, I cannot get any meaningful out of it:
allocate_oids count=3
config_stepper oid=0 step_pin=P1.20 dir_pin=P1.18 invert_step=-1 step_pulse_ticks=0
config_stepper oid=1 step_pin=P1.21 dir_pin=P1.18 invert_step=-1 step_pulse_ticks=0
config_stepper oid=2 step_pin=P1.23 dir_pin=P1.18 invert_step=-1 step_pulse_ticks=0
finalize_config crc=0
012.237: stats count=82 sum=85028 sumsq=5505205
017.237: stats count=67 sum=32355 sumsq=152646
SET start_clock {clock+freq}
SET ticks 30
reset_step_clock oid=0 clock={start_clock}
set_next_step_dir oid=0 dir=0
queue_step oid=0 interval={ticks} count=30000 add=0 add2=0 shift=0
set_next_step_dir oid=0 dir=1
queue_step oid=0 interval=3000 count=1 add=0
reset_step_clock oid=1 clock={start_clock}
set_next_step_dir oid=1 dir=0
queue_step oid=1 interval={ticks} count=30000 add=0 add2=0 shift=0
set_next_step_dir oid=1 dir=1
queue_step oid=1 interval=3000 count=1 add=0
reset_step_clock oid=2 clock={start_clock}
set_next_step_dir oid=2 dir=0
queue_step oid=2 interval={ticks} count=30000 add=0 add2=0 shift=0
set_next_step_dir oid=2 dir=1
queue_step oid=2 interval=3000 count=1 add=0
Eval: SET start_clock 2574666653
Eval: reset_step_clock oid=0 clock=2574666653
Eval: queue_step oid=0 interval=30 count=30000 add=0 add2=0 shift=0
Error: Unable to encode: queue_step
Eval: reset_step_clock oid=1 clock=2574666653
Eval: queue_step oid=1 interval=30 count=30000 add=0 add2=0 shift=0
Error: Unable to encode: queue_step
Eval: reset_step_clock oid=2 clock=2574666653
Eval: queue_step oid=2 interval=30 count=30000 add=0 add2=0 shift=0
Error: Unable to encode: queue_step
018.694: shutdown clock=2574847116 static_string_id=Rescheduled timer in the past
I get an rescheduled error even with 30 ticks. Does this even make sense, or am I following a red herring?
First, you still have a few errors in the log Error: Unable to encode: queue_step, so not all of the commands in your input are updated to have add2=0 shift=0. Then, 30 ticks seems kind of low?
Ignore the above. Brain-dead moment on my side.
Benchmark results I got with a SKR 1.4T:
- Klipper Main: Ticks 231 → Test result is: 1558K
- Stepcompress: Ticks 288 → Test result is: 1250K
@dmbutyugin
I have tried to do some prints using your improved stepcompress, but are getting some errors
ie Internal error in stepcompress , Timer too close
A caveat I have a PT100 and have hacked in Thermocouple Fault Tolerance doubt that should have a influence . I have been using it with the Mainline without issue. I have included some logs.
klippy (3).zip (1.2 MB)
Hit an error now as well. Completed 3 (smaller) prints successfully but now on a bit bigger one it errored out.
klipper.zip (530.7 KB)
Thanks for reporting, I’ll take a look.
@Blackstump, @Sineos, OK, I’ve pushed a commit that should fix the problem. FWIW, I was able to reproduce (occasionally) the stepcompress error, and I fixed that (I hope 
). The same problem could have also manifested as ‘Timer too close’ error occasionally, so I hope the fix will also fix that problem. However, it could have been some different problem that I didn’t stumble upon myself. So, if you get a chance to test the fix, please let me know how it goes.
@dmbutyugin completed the print with no issues now, I have enclosed log just incase there is anything of interest to you.
klippy.log (2.4 MB)
Printed some more parts and no crash so far.
I experienced a strange effect, I never saw up to now on my Klipper printers: Printhead was pausing for a second on some parts of the model:
- Model: Printables (the hex grid)
- Starting from layer 2 where the speed increased
- 2 - 3 occurrences per layer
- Looking at the sliced gcode it is uniformly sliced, e.g. no points where suddenly the number of segments increased considerably compared to other regions (so would have expected no pausing, or pausing all over the place)
- Load graph indeed shows a saturation of the host buffer but no other system overloads
- Sliced gcode attached as well as klippy.log. Tried to catch such a pausing event with M112
No idea if related, just thought I’d mention it.
klippy_stepcompress.log (2.1 MB)
Grid.zip (4.1 MB)
So, just for my understanding, this is happening only on the stepcompress branch, not with the mainline Klipper?
TBH, I did not check. Using the stepcompress branch currently. Can do if you want
I would recommend printing that file from the virtual_sdcard to see if it exhibits the same behavior. Probably only need to do a few layers to confirm.
Using virtual_sdcard anyway as I’m still an Octoprint user.
Confrirmed that it happens likewise with Klipper mainline. So it is related to the model or rather slicer in this case: Cura 5.1
What is a bit strange is that the entire layer has uniform slicing pattern (with too much tiny segments due to the new Arachne slicing engine) but the stuttering is only shown on a few spots.
Thanks for confirming! Your logs indicated Klipper large buffered queue (buffer_time of 5-8 seconds), which can happen if there are too many small moves, and there were some amount of print_stall(s), though the latter typically happen when printing via serial (e.g. from Octoprint). Then, the GCode you have attached has more than 20K commands for layer Z=0.6, which is a bit too much (I’d expect about 10 times fewer commands for that kind of geometry). And if you load the GCode in some GCode viewer, you can confirm that some internal infill between the outer perimeters consists of dozens of tiny moves. So, it can indeed be a bug in Arachne engine (or in Cura in general) that would generate excessive amount of moves in certain places. But if you are printing from virtual_sdcard and still experience problems with the mainline Klipper, I suppose there could be some improvements in the queuing code implemented to better handle that. But I’m not sure if it would be possible or easy.
Don’t think it is worth spending time on. This was the first time I experienced this with Klipper and I have not seen any other reports lately.
For the issue in Cura, I opened a ticket there: 5.1.0: Strange segmentation · Issue #12828 · Ultimaker/Cura · GitHub
I was just wondering because the pattern shown in the screenshots (2nd layer) are uniform over the entire layer and yet the pausing occurred only 3 or 4 times on the layer.
FWIW, the log you posted of the issue shows that the gcode is coming over the pty (Octoprint), not the virtual sdcard. I suspect that the stall is the result of Octoprint’s gcode processing, which is why I recommended giving vsd a try. That said, you may be correct that its not worth spending time on.
Where do you see this?
I have defined:
[virtual_sdcard]
path: ~/gcode_files
And this is where my gcode files end up and I start printing.
Regardless, it is the first time I saw this effect. So far a happy camper.
You have the virtual_sdcard enabled, however OctoPrint isn’t using it. You can tell by looking at the debug output from M112, it dumps all the gcode commands received over the pty. If the virtual sdcard was operational it would also show up in the M112 output. Klipper also logs virtual sdcard events (such as when a print starts and stops).
Presumably OctoPrint is configured to use the same gcode path as the virtual sdcard. That said, it is possible to have OctoPrint start a print from sd, this bypasses its own gcode processing.
Thanks for the explanation. Appreciated. Again learned something. Apparently I printed all my Klipper life without virtual_sdcard while being fully confident I’d use it. Well, never gave me issues, so 
Quickly digging into it, I couldn’t get Octoprint to use the virtual sdcard when starting a print from the GUI. Only a dedicated M23 would so and is indeed reflected in klippy.log. Wonder how many users just think they use this feature.