long time (5s) between the jobs

[TylonHH]

Describe the bug
It tooks too long between the printjob, bed cleaning gcode and the next job

To Reproduce
ad two jobs and start

Expected behavior
the next file should selected and "printed" immediately

System info:
octoprint-systeminfo-20220508154646.zip

Additional context
Here is the octoprint log:

2022-05-08 15:22:39,789 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:22:45,704 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:22:47,992 - octoprint.util.comm - INFO - Finished in 2198.283 s.
2022-05-08 15:22:47,993 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2022-05-08 15:22:48,019 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, owner: None
2022-05-08 15:22:49,141 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2022-05-08 15:22:51,624 - octoprint.plugins.continuousprint - DEBUG - TICK, IDLE, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:22:51,624 - octoprint.plugins.continuousprint - INFO - _state_printing -> _state_success
2022-05-08 15:22:56,647 - octoprint.plugins.continuousprint - DEBUG - TICK, IDLE, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:22:57,646 - octoprint.plugins.continuousprint - DEBUG - Completing q[18] - success
2022-05-08 15:23:02,325 - octoprint.plugins.continuousprint - INFO - _state_success -> _state_start_clearing
2022-05-08 15:23:07,351 - octoprint.plugins.continuousprint - DEBUG - TICK, IDLE, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:23:07,502 - octoprint.plugins.continuousprint - INFO - Wrote file cp_bed_clearing_script.gcode
2022-05-08 15:23:07,505 - octoprint.filemanager.analysis - INFO - Starting analysis of local:cp_bed_clearing_script.gcode
2022-05-08 15:23:07,535 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python3 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --bed-z=0.0 /home/pi/.octoprint/uploads/cp_bed_clearing_script.gcode
2022-05-08 15:23:07,602 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: cp_bed_clearing_script.gcode, owner: None, user: None
2022-05-08 15:23:07,795 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2022-05-08 15:23:07,835 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: cp_bed_clearing_script.gcode, owner: None, user: None
2022-05-08 15:23:08,567 - octoprint.plugins.continuousprint - INFO - _state_start_clearing -> _state_clearing
2022-05-08 15:23:08,568 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2022-05-08 15:23:08,710 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2022-05-08 15:23:12,012 - octoprint.util.comm - INFO - Finished in 4.232 s.
2022-05-08 15:23:12,013 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2022-05-08 15:23:12,036 - octoprint.filemanager.analysis - INFO - Starting analysis of local:cp_bed_clearing_script.gcode
2022-05-08 15:23:12,042 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: cp_bed_clearing_script.gcode, owner: None
2022-05-08 15:23:12,132 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python3 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --bed-z=0.0 /home/pi/.octoprint/uploads/cp_bed_clearing_script.gcode
2022-05-08 15:23:13,601 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:13,869 - octoprint.filemanager.analysis - INFO - Result is empty, no extrusions found
2022-05-08 15:23:13,870 - octoprint.filemanager.analysis - INFO - Analysis of entry local:cp_bed_clearing_script.gcode finished, needed 1.83s
2022-05-08 15:23:18,619 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:23,625 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:28,632 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:30,370 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2022-05-08 15:23:33,639 - octoprint.plugins.continuousprint - DEBUG - TICK, IDLE, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:33,640 - octoprint.plugins.continuousprint - INFO - Clearing bed
2022-05-08 15:23:33,641 - octoprint.plugins.continuousprint - INFO - _state_clearing -> _state_start_print
2022-05-08 15:23:38,660 - octoprint.plugins.continuousprint - DEBUG - TICK, IDLE, path=cp_bed_clearing_script.gcode, materials=[]
2022-05-08 15:23:44,219 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, owner: None, user: None
2022-05-08 15:23:44,256 - octoprint.plugins.continuousprint - INFO - E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode
2022-05-08 15:23:44,260 - octoprint.util.comm - INFO - Starting job on behalf of plugin continuousprint
2022-05-08 15:23:44,329 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2022-05-08 15:23:44,368 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, owner: None, user: None
2022-05-08 15:23:45,003 - octoprint.plugins.continuousprint - INFO - _state_start_print -> _state_printing
2022-05-08 15:23:45,012 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2022-05-08 15:23:45,088 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2022-05-08 15:23:50,019 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:23:51,018 - octoprint.plugins.continuousprint - INFO - Printing E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode
2022-05-08 15:23:56,023 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]
2022-05-08 15:24:02,008 - octoprint.plugins.continuousprint - DEBUG - TICK, BUSY, path=E_V3_LID_vase_mode_deeper_notch_Frage_fixed100-5.aw.gcode, materials=[]

There you can see the long loadings.

kind regards

How to investigate further?

[smartin015]

This is actually a side effect of a change I made to prevent the queue from stalling. Previously it was event-based - e.g. octoprint fires a "PRINT_COMPLETED" event and the plugin starts the bed clearing process. Now it's event-based but with an extra 5-second timer that pokes the driver if it somehow missed an event.

It shouldn't have to take 5 seconds every time to start printing, though. I'll take a look at the startup sequence once I've reached a steady state with #60.

[smartin015]

I added a shortcut in between states in the new v2.0.0rc1 release, so this should no longer take so long to start printing.