Delay for the snapshot

[effernity]

If this is a feature request describe it here

FEATURE_REQUEST_DESCRIPTION_GOES_HERE

Version of Octolapse

Octolapse Version: Octolapse 0.3.4

Version of OctoPrint

OctoPrint Version: OctoPrint 1.3.11

When you ran into the problem, did you have diagnostic logging enabled?

Diagnostic Logging was Enabled: YES

What were you doing when the problem occurred

1. Printing on Klipper with Octolapse enabled
2. Octolapse triggers on z-hop

What should have happened?

Minimal delay

What happened instead?

There's a serious delay before Octolapse actually takes snapshot, although delay set to 35 ms

Operating System running OctoPrint and Octolapse

OS Name: Armbian Buster Os Version: hmm... latest?

Printer model & used firmware incl. version

Printer Model: Ender 3 Printer Firmware Version: Latest Klipper

Browser and version of browser, operating system running browser

Browser: Chrome Browser OS: Windows

Link to the gcode file you were printing when the problem occurred

Link to Gcode File: https://gist.github.com/effernity/29b4ead5ef9c3b1e6ceadcc6df01dd26

Link to settings.json

Link to settings.json with all passwords removed: SETTINGS_JSON_LINK_GOES_HERE

Link to plugin_octolapse.log

Link to plugin_octolapse.log: https://gist.github.com/effernity/432b6760dc1a51babd157a53b819969c

Actually, there is 2 second delay between M400 and OK

2019-10-04 04:14:01,798 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z0.600 F702, tags: set(['source:file', 'filepos:213797', 'fileline:7358'])
2019-10-04 04:14:01,800 Received G1
2019-10-04 04:14:01,802 Position Change - G1 Z0.600 F702 - Absolute Move From(X:122.293,Y:125.632,Z:0.36,E:261.6702) - To(X:122.293,Y:125.632,Z:0.6,E:261.6702) 
2019-10-04 04:14:01,805 Extruder Changed: E:0.0, Retraction:1.4 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-False, IsRetractingStart:True-False, IsRetracting:True-False, IsPartiallyRetracted:False-False, IsRetracted:True-True, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2019-10-04 04:14:01,817 Position - Zhop:0.24
2019-10-04 04:14:01,818 TimerTrigger - 15 second interval, 18 seconds elapsed, -3 seconds to trigger
2019-10-04 04:14:01,820 Sent to printer: Command Type:None, gcode:G92, cmd: G92 E0.0000, tags: set(['fileline:7356', 'source:file', 'filepos:213762'])
2019-10-04 04:14:01,821 Triggered E:0.0, Retraction:1.4 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:False-None, IsRetracting:False-None, IsRetracted:True-True, IsDetracting:False-None, IsTriggered:True
2019-10-04 04:14:01,822 TimerTrigger - Triggering.
2019-10-04 04:14:01,822 Received from printer: line:ok

2019-10-04 04:14:01,823 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X139.232 Y121.641 F5100, tags: set(['source:file', 'filepos:213825', 'fileline:7359'])
2019-10-04 04:14:01,824 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F1800.0, tags: set(['source:file', 'source:rewrite', 'filepos:213781', 'fileline:7357', 'plugin:octolapse', 'phase:queuing'])
2019-10-04 04:14:01,824 Received G1
2019-10-04 04:14:01,825 Position Change - G1 X139.232 Y121.641 F5100 - Absolute Move From(X:122.293,Y:125.632,Z:0.6,E:261.6702) - To(X:139.232,Y:121.641,Z:0.6,E:261.6702) 
2019-10-04 04:14:01,825 Position - Zhop:0.24
2019-10-04 04:14:01,826 TimerTrigger - 15 second interval, 0 seconds elapsed, 15 seconds to trigger
2019-10-04 04:14:01,827 A snapshot is triggering
2019-10-04 04:14:01,827 About to take a snapshot.  Triggering Command: G1
2019-10-04 04:14:01,828 The triggering command is travel only, skipping return command generation
2019-10-04 04:14:01,828 Skipping return position, traveling to the triggering command position: X=139.232, y=139.232
2019-10-04 04:14:01,829 Snapshot Gcode - SnapshotCommandIndex:2, EndIndex:7, Triggering Command:G1 X139.232 Y121.641 F5100
2019-10-04 04:14:01,830     M83
2019-10-04 04:14:01,830     G1 E-0.00000 F1800.000
2019-10-04 04:14:01,831     G1 X117.500 Y105.000 F5100.000
2019-10-04 04:14:01,832     G1 X139.232 Y121.641
2019-10-04 04:14:01,832 Received from printer: line:ok

2019-10-04 04:14:01,833     G1 E0.00000 F1800.000
2019-10-04 04:14:01,833     M82
2019-10-04 04:14:01,834     G1 F702.000
2019-10-04 04:14:01,834     G1 X139.232 Y121.641 F5100
2019-10-04 04:14:01,835 Sending snapshot start gcode and snapshot commands.
2019-10-04 04:14:01,836 Octolapse is requesting a position.
2019-10-04 04:14:01,836 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z0.600 F702, tags: set(['source:file', 'filepos:213797', 'fileline:7358'])
2019-10-04 04:14:01,837 Queuing Command: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,837 Received from printer: line:ok

2019-10-04 04:14:01,838 Received M83 - Switching Extruder to Relative Coordinates
2019-10-04 04:14:01,838 Position - Zhop:0.24
2019-10-04 04:14:01,839 Queuing Command: Command Type:None, gcode:G1, cmd: G1 E-0.00000 F1800.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,839 Received G1
2019-10-04 04:14:01,840 Position Change - G1 E-0.00000 F1800.000 - Absolute Move From(X:122.293,Y:125.632,Z:0.6,E:261.6702) - To(X:122.293,Y:125.632,Z:0.6,E:261.6702) 
2019-10-04 04:14:01,840 Sent to printer: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,841 Position - Zhop:0.24
2019-10-04 04:14:01,841 Received from printer: line:ok

2019-10-04 04:14:01,842 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,843 Received G1
2019-10-04 04:14:01,843 Position Change - G1 X117.500 Y105.000 F5100.000 - Absolute Move From(X:122.293,Y:125.632,Z:0.6,E:261.6702) - To(X:117.5,Y:105.0,Z:0.6,E:261.6702) 
2019-10-04 04:14:01,844 Position - Zhop:0.24
2019-10-04 04:14:01,844 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F1800.0, tags: set(['plugin:octolapse', 'source:plugin', 'source:rewrite', 'trigger:printer.commands', 'snapshot_gcode', 'phase:queuing'])
2019-10-04 04:14:01,845 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,845 Received from printer: line:ok

2019-10-04 04:14:01,846 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'snapshot_gcode', 'source:plugin'])
2019-10-04 04:14:01,847 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:01,848 Printer event received:ZChange.
2019-10-04 04:14:01,997 Received from printer: line:ok

**2019-10-04 04:14:02,003** Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
**2019-10-04 04:14:04,433** Received from printer: line:ok

2019-10-04 04:14:04,464 The position request is being sent
2019-10-04 04:14:04,466 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:04,471 Received from printer: line:X:117.500 Y:105.000 Z:0.600 E:0.000

2019-10-04 04:14:04,494 Octolapse has received a position request response.
2019-10-04 04:14:04,497 Received from printer: line:ok

2019-10-04 04:14:04,500 Taking a snapshot.
2019-10-04 04:14:04,509 Snapshot Delay - Waiting 0.035 second(s) after executing the snapshot script.
2019-10-04 04:14:04,543 Printer event received:PositionUpdate.
2019-10-04 04:14:04,555 Snapshot - downloading from http://127.0.0.1:8080/?action=snapshot to /home/opi/.octoprint/data/octolapse/snapshots/e48aa750-5265-44f2-b62e-64b9318b8a76/354def78-9eea-409a-ad23-ee966dfff4ba.
2019-10-04 04:14:04,672 Snapshot - Snapshot saved to disk at /home/opi/.octoprint/data/octolapse/snapshots/e48aa750-5265-44f2-b62e-64b9318b8a76/354def78-9eea-409a-ad23-ee966dfff4ba/BeltSplicer000020.jpg
2019-10-04 04:14:04,862 Snapshot Download Job completed, signaling task queue.
2019-10-04 04:14:04,867 Sending snapshot return and end gcode.
2019-10-04 04:14:04,876 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X139.232 Y121.641, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:04,879 Received G1
2019-10-04 04:14:04,881 Position Change - G1 X139.232 Y121.641 - Absolute Move From(X:117.5,Y:105.0,Z:0.6,E:261.6702) - To(X:139.232,Y:121.641,Z:0.6,E:261.6702) 
2019-10-04 04:14:04,884 Position - Zhop:0.24
2019-10-04 04:14:04,885 Queuing Command: Command Type:None, gcode:G1, cmd: G1 E0.00000 F1800.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:04,886 Received G1
2019-10-04 04:14:04,893 Position Change - G1 E0.00000 F1800.000 - Absolute Move From(X:139.232,Y:121.641,Z:0.6,E:261.6702) - To(X:139.232,Y:121.641,Z:0.6,E:261.6702) 
2019-10-04 04:14:04,895 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X139.232 Y121.641, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'snapshot_gcode', 'source:plugin'])
2019-10-04 04:14:04,897 Queuing Command: Command Type:None, gcode:M82, cmd: M82, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:04,905 Received M82 - Switching Extruder to Absolute Coordinates
2019-10-04 04:14:04,907 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F702.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 04:14:04,910 Received G1
2019-10-04 04:14:04,913 Position Change - G1 F702.000 - Absolute Move From(X:139.232,Y:121.641,Z:0.6,E:261.6702) - To(X:139.232,Y:121.641,Z:0.6,E:261.6702) 
2019-10-04 04:14:04,914 Received from printer: line:ok

[FormerLurker]

The delay has already been greatly reduced in the alpha version if you want to try that. That version still needs a bit of work, but the delay is about as low as I can get it now I believe.

However, keep in mind that the delay setting in the camera profile is additional delay before a snapshot is taken and not the total amount of time for the whole process. Not much time elapsed at that point (9MS). The delay added 35MS, as advertised. Next, according to your log, the snapshot download itself took about 120MS (up your framerate to reduce that). That is a lot of time, but not unheard of. Post processing seems to have taken a lot longer than I'd expect (about 180MS). What kind of pi are you using? What is your camera image resolution? What kind of camera? Is your camera image rotated via the octolapse camera profile settings? Also, are you running octoprint anywhere or some other plugin that uses custom streaming?

Fyi, the next version of octolapse performs post processing on a background thread. This includes image rotation, adding metadata, thumbnail generation, and maybe something that I've forgotten. That alone would have saved over 100MS. You can probably reduce the download time by upping the framerate to 30FPS, prob to around 50-60MS. Mjpgstreamer will wait untill the next frame is available before returning an image, so that makes a difference.

[effernity]

I'm using Orange Pi lite and c270. Resolution is 1280x720 and fps is 30 with no rotarion or mirroring and no other stream plugins or octoprint anywhere. Actual problem is that printhead moves to snapshot location and then 1-2 second delay is applied. I'll try to capture video today.

[FormerLurker]

Sounds good. If I had to guess I'd say there is a delay in responding to the M400 + M114 combo. Every so often my MK2 will do this (wait for 1 or 2 seconds at either before or after the snapshot movement maybe 1 time out of 1000 snapshots), but it happens so infrequently that I've had a hard time debugging it. At this point I've not ruled out Octolapse, Octoprint or Marlin at this point.

There is a way to test this manually if it happens during every snapshot. You could perform the following sequence to see if it triggers a similar delay without Octolapse.

1. Home your XY axis.
2. Set your feedrate to something very low so that you will have a chance to run other commands before your printer stops moving. This will be key.
3. Move your extruder from the home position (0,0) to the opposite corner (220,220 I think)
4. Issue an M400 and then an M114 BEFORE your extruder gets to 220,220
5. Direct your extruder to move back to 0,0 BEFORE your extruder gets to 220,220
6. Watch your printer and see if there is a delay when it starts moving from 220,220 to 0,0

Here is the gcode sequence (approximate, I do not have an ender 3 to test this on!):

G90 ; ensure your xyz axis is in absolute mode
G28 XY ; home x and y only
G0 X0 Y0 F100;  Ensure you are at 0,0 and set the feedrate to a super slow speed
G0 X220 Y220; Lurch slowly to 220,220
M400 ; wait for movements to complete before responding
M114 ; request a position.  Octolapse does this so it knows when all movements have stopped
G0 X0 Y0; return to the origin

I'm curious how it responds to this. Also, can you tell me if this happens every single time, or if it only happens some of the time?

Thanks!

[effernity]

Yep, every time.

Examples from fresh logs:

2019-10-04 18:55:47,480 Position Change - G1 E-0.00000 F1800.000 - Absolute Move From(X:94.64,Y:126.76,Z:0.44,E:60.0422) - To(X:94.64,Y:126.76,Z:0.44,E:60.0422) 
2019-10-04 18:55:47,482 Sent to printer: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:47,483 Position - Zhop:0.24
2019-10-04 18:55:47,485 Received from printer: line:ok

2019-10-04 18:55:47,485 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:47,486 Received G1
2019-10-04 18:55:47,487 Position Change - G1 X117.500 Y105.000 F5100.000 - Absolute Move From(X:94.64,Y:126.76,Z:0.44,E:60.0422) - To(X:117.5,Y:105.0,Z:0.44,E:60.0422) 
2019-10-04 18:55:47,487 Position - Zhop:0.24
2019-10-04 18:55:47,488 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F1800.0, tags: set(['plugin:octolapse', 'source:plugin', 'source:rewrite', 'trigger:printer.commands', 'snapshot_gcode', 'phase:queuing'])
2019-10-04 18:55:47,488 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:47,489 Received from printer: line:ok

2019-10-04 18:55:47,489 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:47,490 Printer event received:ZChange.
2019-10-04 18:55:47,491 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'snapshot_gcode', 'source:plugin'])
2019-10-04 18:55:49,061 Received from printer: line:ok

2019-10-04 18:55:49,066 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:51,600 Received from printer: line:ok

2019-10-04 18:55:51,614 The position request is being sent
2019-10-04 18:55:51,624 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:55:51,630 Received from printer: line:X:117.500 Y:105.000 Z:0.440 E:0.000

2019-10-04 18:55:51,633 Octolapse has received a position request response.
2019-10-04 18:55:51,694 Received from printer: line:ok

2019-10-04 18:55:51,720 Taking a snapshot.

2019-10-04 18:56:51,493     G1 X98.583 Y112.362
2019-10-04 18:56:51,494     G1 F702.000
2019-10-04 18:56:51,496     G1 X98.583 Y112.362 F5100
2019-10-04 18:56:51,496 Sending snapshot start gcode and snapshot commands.
2019-10-04 18:56:51,497 Octolapse is requesting a position.
2019-10-04 18:56:51,498 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:51,498 Received G1
2019-10-04 18:56:51,499 Position Change - G1 X117.500 Y105.000 F5100.000 - Absolute Move From(X:96.042,Y:110.694,Z:0.44,E:96.1879) - To(X:117.5,Y:105.0,Z:0.44,E:96.1879) 
2019-10-04 18:56:51,499 Position - Zhop:0.24
2019-10-04 18:56:51,500 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:51,500 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'snapshot_gcode', 'source:plugin'])
2019-10-04 18:56:51,501 Received from printer: line:ok

2019-10-04 18:56:51,501 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:51,502 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:51,503 Printer event received:ZChange.
2019-10-04 18:56:53,813 Received from printer: line:ok

2019-10-04 18:56:53,819 The position request is being sent
2019-10-04 18:56:53,824 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:53,830 Received from printer: line:X:117.500 Y:105.000 Z:0.440 E:0.000

2019-10-04 18:56:53,849 Octolapse has received a position request response.
2019-10-04 18:56:53,851 Received from printer: line:ok

2019-10-04 18:56:53,857 Taking a snapshot.

2019-10-04 18:58:40,039 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:58:40,039 Received G1
2019-10-04 18:58:40,040 Position Change - G1 X117.500 Y105.000 F5100.000 - Absolute Move From(X:122.242,Y:111.099,Z:0.44,E:159.616) - To(X:117.5,Y:105.0,Z:0.44,E:159.616) 
2019-10-04 18:58:40,041 Position - Zhop:0.24
2019-10-04 18:58:40,041 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z0.440 F702, tags: set(['fileline:2171', 'source:file', 'filepos:67547'])
2019-10-04 18:58:40,042 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:58:40,042 Received from printer: line:ok

2019-10-04 18:58:40,043 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:58:40,043 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X117.500 Y105.000 F5100.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'snapshot_gcode', 'source:plugin'])
2019-10-04 18:58:40,044 Received from printer: line:ok

2019-10-04 18:58:40,045 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:58:40,045 Printer event received:ZChange.
2019-10-04 18:58:42,232 Received from printer: line:ok

2019-10-04 18:58:42,249 The position request is being sent
2019-10-04 18:58:42,251 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:58:42,265 Received from printer: line:X:117.500 Y:105.000 Z:0.440 E:0.000

2019-10-04 18:58:42,268 Octolapse has received a position request response.
2019-10-04 18:58:42,277 Taking a snapshot.

Tried that you asked:

Send: G28 Recv: ok Send: G0 X0 Y0 Recv: ok Send: G0 X200 Y200 F1000 Recv: ok Send: M400 Recv: ok Send: M114 Recv: X:200.000 Y:200.000 Z:19.898 E:0.000 Recv: ok Send: G0 X00 Y00 F1000 Recv: ok

When printhead got to x200 y200 there was about 0.5 sec delay, maybe a bit less

Upd.: loading a video

[effernity]

Here's a video

https://www.youtube.com/watch?v=T6Rft0Lpggk

[FormerLurker]

A 0.5 sec delay with only 1 gcode in the planner is not very good (assuming it is 500MS). That means 500 + 35 + 120 + 180 = 835MS delay is accounted for. Not sure where the extra 1065MS (assuming the full 2 second delay you are reporting) are coming from just yet.

Looking at this log entry for now:

2019-10-04 18:56:51,502 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:51,503 Printer event received:ZChange.
2019-10-04 18:56:53,813 Received from printer: line:ok
2019-10-04 18:56:53,819 The position request is being sent
2019-10-04 18:56:53,824 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 18:56:53,830 Received from printer: line:X:117.500 Y:105.000 Z:0.440 E:0.000

There was a 2300MS wait between sending the M400 and receiving a response from the M114 command. I can't tell by looking if the printer was just slow to respond, or if it really took that long to process any commands that were in the planner already. In any case, it doesn't look like Octolapse is causing any extra delay here over and above what I listed in my first response, at least that I've been able to see just by looking at the logs. This issue might require access to hardware to diagnose unfortunately, but I'm not 100% sure right now. I'll take some more time to review the logs to see if I notice anything that I didn't see before.

You might be able to create an extremely small print (maybe 5 layers with a thin wall, which will have super bad quality, but who cares right?). Slice and run the print with full diagnostic debug enabled AND with octoprint serial logging. WE should then be able to compare timestamps and see if there is a delay between Octoprint's seeing the response and Octolapse handling the response (the position response from M114, since that's the only one you can track with any certainty). Any substantial delay between the too would either indicate a problem with Octolapse or Octoprint and remove Klipper from the equation.

[FormerLurker]

Oh, one other thing you might want to try: switch to relative extrusion inside of simplify. Some printers have the odd habit of returning a position response when sending a G92 command, which can mess with Octolapse. I'm not really expecting this to make a difference, but I did see a few confusing position responses in your log.

[effernity]

Slice and run the print with full diagnostic debug enabled AND with octoprint serial logging.

Test run or full, with extrusion and temp?

[effernity]

Also, i will try printing via usb, not serial. I've had issues with marlin and octoprint connected via serial, then switched to klipper. Maybe my board have issues with serial connection

[FormerLurker]

You are free to use test mode as long as the issue still exists when using it. Also, def try usb too. Anything we can do to isolate the problem will be very useful.

[effernity]

Ok, new set of logs:

serial (3).log plugin_octolapse (2).log octoprint (7).log

And yes, switched to relative extrusion, no changes

[FormerLurker]

Excellent 👍. I am heading out for the day, but will try to take a look tomorrow. Thanks for providing me with useful information! It helps a ton.

[FormerLurker]

So, I looked through several of the M400 requests. Here is one entry within the serial.log file:

2019-10-04 20:23:10,028 - Send: N70 M400*16
2019-10-04 20:23:12,569 - Recv: ok
2019-10-04 20:23:12,596 - Send: N71 M114*17
2019-10-04 20:23:12,608 - Recv: X:117.500 Y:105.000 Z:0.440 E:0.000

And here is the same sequence from plugin_octolapse.log

2019-10-04 20:23:10,047 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 20:23:12,582 Received from printer: line:ok

2019-10-04 20:23:12,597 The position request is being sent
2019-10-04 20:23:12,604 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin', 'snapshot_gcode'])
2019-10-04 20:23:12,625 Received from printer: line:X:117.500 Y:105.000 Z:0.440 E:0.000

As you can see, there is only a 17MS delay between Octoprint receiving the M114 response and Octolapse seeing the same response. The snapshot was then downloaded in about 444MS, including the delay. That is still higher than I'd like it to be (remember, this is greatly reduced already in Octolapse V0.4 alpha), but not really close to the 2 second delay you describe.

It looks to me like this issue must be related to how Klipper responds to M400. I think the next step is to engineer a gcode file that shows the same behavior without running Octolapse, and to post this to the Klipper github issues here. Some delay is expected after M400, but not THAT much. If you link to this issue I will follow along and chime in as necessary.

Here is some gcode I put together from your serial log that showed the behavior:

G90
G28
G0 X0 Y0
G1 Z5 F702
G1 X93.075 Y130.200 F5100 ; Maybe loop the code a few times here for debug purposes?
G1 F1800.0
G1 Y128.325 X91.2 F1080.0
G1 Y81.675 X91.2
G1 Y79.8 X93.075
G1 Y79.8 X115.725
G1 Y81.575 X117.5
G1 Y79.8 X119.275
G1 Y79.8 X141.925
G1 Y81.675 X143.8
G1 Y128.325 X143.8
G1 Y130.2 X141.925
G1 Y130.2 X119.275
G1 Y128.425 X117.5
G1 Y130.2 X115.725
G1 Y130.2 X93.075
G1 X93.273 Y129.720 F5100
G1 Y128.127 X91.68 F1080.0
G1 Y81.873 X91.68
G1 Y80.28 X93.273
G1 Y80.28 X115.527
G1 Y81.873 X117.12
G1 Y128.127 X117.12
G1 Y129.72 X115.527
G1 Y129.72 X93.273
G1 X93.472 Y129.240 F5100
G1 Y127.928 X92.16 F1080.0
G1 Y82.072 X92.16
G1 Y80.76 X93.472
G1 Y80.76 X115.328
G1 Y82.072 X116.64
G1 Y127.928 X116.64
G1 Y129.24 X115.328
G1 Y129.24 X93.472
G1 F1800.0
G1 X117.500 Y105.000 F5100.000
M400
M114
G1 X119.473 Y129.720
G1 F702.000
G1 X119.473 Y129.720 F5100
G1 F1800.0
G1 Y128.127 X117.88 F1080.0
G1 Y81.873 X117.88
G1 Y80.28 X119.473
G1 Y80.28 X141.727
G1 Y81.873 X143.32

I removed all z-hops from this code, and set it to start at z=5mm to prevent any bed scratching (we don't want that). You could loop this code a few times starting from this line:

G1 X93.075 Y130.200 F5100 ; Maybe loop the code a few times here for debug purposes?

That would make it easier to see what's going on. Let me know if you have any problems with this, or if you don't see the delay when running this gcode. That would be strange, but a possibility.

Thanks!

[effernity]

Hello!

Tried test gcode:

https://gist.github.com/effernity/1b6729b2627f57d652466249765153fc

Some of the lines:

2019-10-07 19:22:48,589 - Send: N101 M400*39
2019-10-07 19:22:52,332 - Recv: ok

2019-10-07 19:23:22,514 - Send: N154 M400*39
2019-10-07 19:23:26,251 - Recv: ok

2019-10-07 19:23:59,504 - Send: N208 M400*45
2019-10-07 19:24:00,223 - Recv: ok

2019-10-07 19:24:01,704 - Send: N219 M400*45
2019-10-07 19:24:05,138 - Recv: ok

I guess i'll open the issue on klipper's github page. Thanks for your support!

Also, how can i test v0.4 alpha?

[FormerLurker]

Hey, thanks for opening that issue! I'm sure you aren't the only one having this problem.

Also, how can i test v0.4 alpha?

So, use the plugin manager and install from this link (this is the devel link, and it changes rapidly): https://github.com/FormerLurker/Octolapse/archive/devel.zip

Then, follow this guide which explains how to get started. Let me know if you have any questions!

[FormerLurker]

@effernity, I just wanted to verify that you see a similar delay when you ran the test gcode I posted without running Octolapse (or with Octolapse disabled). I don't want to send anyone down a rabbit hole. Sorry, I should have confirmed this before I asked you to create that issue.

Would you be willing to re-run the gcode test (making sure Octolapse is disabled) while recording a video of your printer? Also, it might be a good idea to run another test bypassing OctoPrint completely.

[effernity]

Would you be willing to re-run the gcode test (making sure Octolapse is disabled) while recording a video of your printer?

Yes, of course. What code i'll have to run?

Also, it might be a good idea to run another test bypassing OctoPrint completely

I'm currently running Klipper, it doesnt' work without octoprint.

[Arksine]

Klipper can print without octoprint using the virtual_sdcard module. After setting it up you can still use octoprint to start the print. Alternatively you can connect with a terminal program like screen, or echo commands to /tmp/printer, ie:

echo M21 > /tmp/printer

[effernity]

Klipper can print without octoprint using the virtual_sdcard module. After setting it up you can still use octoprint to start the print. Alternatively you can connect with a terminal program like screen, or echo commands to /tmp/printer, ie:

echo M21 > /tmp/printer

Oh, i thought "without octoprint" is "without pi" :)

[FormerLurker]

@effernity, print the code I posted above that contains the embedded M400 and M114 commands using both methods (without Octolapse and without Octoprint as @Arksine suggests) and record a video of both prints. I think that will give us a good confirmation or refutation of our suspicions.

Sorry I didn't confirm all of this with you earlier :( I blame too little sleep and too much work :)

[effernity]

@effernity, print the code I posted above that contains the embedded M400 and M114 commands using both methods (without Octolapse and without Octoprint as @Arksine suggests) and record a video of both prints. I think that will give us a good confirmation or refutation of our suspicions.

Sorry I didn't confirm all of this with you earlier :( I blame too little sleep and too much work :)

It's ok, nevermind. I'll try gcode tomorrow

[effernity]

Ok, new set of tests.

1. Test gcode from your post, Octolapse disabled. https://gist.github.com/effernity/a08a2cc179cc974be73ba24ea131f453 Video: https://youtu.be/nO65esRhtxQ

2. Test with Octolapse, full debug https://gist.github.com/effernity/2f2e50ea3ac1331c0a7b505150460f59 Video: https://youtu.be/5cmDDnA_v38

Actually, i have another video, but full debug was off, only test mode. And that is very strange behaviour (same gcode as in test 2): https://youtu.be/gsdaXmnBL-c https://gist.github.com/effernity/6fc4b058af09458911c44923cf397a85 edit: found a bit of info in log:

2019-10-10 17:55:54,913 - octolapse.__init__ - INFO - Started logging to file.
2019-10-10 17:55:54,917 - octolapse.settings - INFO - Loading existing settings file from: /home/opi/.octoprint/data/octolapse/settings.json.
2019-10-10 17:55:55,029 - octolapse.settings - INFO - Creating settings from iterable.
2019-10-10 17:55:55,141 - octolapse.settings - INFO - Settings created from iterable.
2019-10-10 17:55:55,142 - octolapse.settings - INFO - Settings file loaded.
2019-10-10 18:10:22,292 Octolapse - loaded and active.
2019-10-10 18:10:34,860 Octolapse - is loading template configurations.
2019-10-10 18:15:32,146 extruder.py - A 'length_to_retract' was requested, but the extruder is beyond the configured retraction length.
2019-10-10 18:16:04,117 Sending on_snapshot_complete payload.
2019-10-10 18:16:23,895 Sending on_snapshot_complete payload.
2019-10-10 18:16:43,425 Sending on_snapshot_complete payload.
2019-10-10 18:17:02,780 Sending on_snapshot_complete payload.
2019-10-10 18:17:22,521 Sending on_snapshot_complete payload.

[effernity]

Adding settings.json https://gist.github.com/effernity/b989f623f63e0fcb9c7273f7ca3cc5b7

[FormerLurker]

@effernity, your second test should have bypassed Octoprint (print directly with klipper), and should not have had Octolapse disabled. The sample code was intended to simulate injecting an M400 without Octolapse. Using that code with Octolapse means you could have multiple M400s injected in a row, which would definitely cause strange behaviors. Anyway, we can just ignore that for now.

From your videos it looks like the delay happens AFTER the snapshot and AFTER the toolhead returns to the original position. Is that correct? If you would, please try upgrading Octolapse to the most recent version via the link I sent earlier. Follow the guide to get started, and re-run your ORIGINAL gcode for a few layers and see if the problem persists.

If you have any problem configuring the new version, please let me know. Things have changed quite a bit. There is now a good profile for your printer which you can select in the printer profile edit screen (just choose your make and model). Be absolutely sure to follow the instructions for cura, since you will need to add some code to your start gcode, and reslice your stl.

I'm going to update the Klipper issue since I'm now not sure if it is involved at all, except maybe for adding some small amount of additional delay due to the M400 command (which is probably not avoidable).

[effernity]

@FormerLurker for my first test i ran your gcode, without octolapse at all, only thing is that was via octoprint. For second test i ran other gcode, just normal gcode, without added M400's

The delay happens actually before move to center position and after move to previous location. Maybe i messed with some settings? It looks like z-hop performs really slow, there's a delay before zhop-to-move-to-center and after return to previous location, just before return to normal Z

[FormerLurker]

LOL, I'm so confused :)

Try setting your zhop speed to 3600.0 and see how that goes.

If the problem has to do with slicer settings, upgrading Octolapse to the dev version I posted above would eliminate this from the list of possible problems, since the settings will be extracted automatically from your gcode. My last post mentioned Cura, but I now see and remember that you are using simplify 3d, which requires no special configuration (it should work out of the box).

[effernity]

LOL, I'm so confused :)

Try setting your zhop speed to 3600.0 and see how that goes.

If the problem has to do with slicer settings, upgrading Octolapse to the dev version I posted above would eliminate this from the list of possible problems, since the settings will be extracted automatically from your gcode. My last post mentioned Cura, but I now see and remember that you are using simplify 3d, which requires no special configuration (it should work out of the box).

Here, right?

[FormerLurker]

Thats right!!

[effernity]

Tried, nothing changed. https://www.youtube.com/watch?v=g-rfi5Y7fsE&feature=youtu.be Here, 60 fps footage The sequence is like this Printing - stop - delay - zhop and move to center - snapshot - move to original position - delay - zhop back - continue printing

[FormerLurker]

OK, so now I think it's definitely time to try the development build. Those delays are totally unexpected and baffling. The slicer settings and configuration has changed DRAMATICALLY in the next version, so it's unlikely that any issues that were in 0.3.4 that could have caused this still exist in V0.4.

So, use the plugin manager and install from this link (this is the devel link, and it changes rapidly): https://github.com/FormerLurker/Octolapse/archive/devel.zip

Then, follow this guide which explains how to get started. Let me know if you have any questions!

[effernity]

Actually, installed dev version just before your comment :) Will return with feedback

[FormerLurker]

Excellent, I'm excited for more feedback on this version! It still needs some polishing, but I"m pretty happy with how things are coming together!

[effernity]

https://www.youtube.com/watch?v=6XEWl-2iRHQ Just.. wow..

[FormerLurker]

Woah, that looks good! How do you feel about the new version so far?

[effernity]

The setup process is literally several clicks, actually I had to change one thing - bed size, my ender is capable of printing 200 on Y, not 220, but it's only mine issue.

Also, custom image preferences are way better to tune now, with live preview. Outstanding job!

[FormerLurker]

Ahh, you made my day! I will update the klipper issue with my apologies. Be sure to create a new issue if you have problems or suggestions for v0.4, and thanks for posting!!!

[FormerLurker]

Closed! Thanks for posting! I look forward to hearing from you again!