Slow upload to rPi SD after upgrade to 1.4.2

m.hutchinson · September 28, 2020, 9:08pm

What is the problem?

Uploads from browser (FF) to OctoPi onboard MicroSD hang with a 30-35 second delay.

All four OctoPi's were previously 1.4.0/Python 2, upgraded recently to 1.4.2 and Python 3. Three exhibit this issue, the fourth unit (my spare/testbed) does not have an uploads delay. Log for that unit replicating sequence will be posted on a following post, if desired.

Logging appears to point to filemanager.analysis which reviews file in or out of safe mode. Will review my #4 unit that does not have this issue.

Steps to replicate:

Create new folder (or use existing folder) on OctoPi
Navigate to folder
Click "Upload" and select file
Click "Open" to start upload
Watch "Saving" bar quickly reach 100% in a typical 2 seconds, then hang for 30 to 35 seconds.
File upload completes after delay and shows up on file list, and is visible in folder listing via SSH and WinSCP.

What did you already try to solve it?

Restarted OctoPrint
Restarted OctoPi
Disabled File Check (2020.8.7)
Restarted OctoPrint in Safe Mode
sudo apt-get upgrade (tested on my #1 rPi only)

Have you tried running in safe mode and if so did it solve the issue?

Yes, No change

Complete Logs

octoprint.log, serial.log or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support! Not log excerpts, complete logs.)

Log from my #3 rPi contains OctoPrint in normal mode, file upload. Next post will contain log after a restart in Safe mode, then a file upload again. Problem exhibits itself in both modes. I did not do sudo apt-get upgrade on this unit.

2020-09-28 21:43:07,106 - octoprint.startup - INFO - ******************************************************************************
2020-09-28 21:43:07,108 - octoprint.startup - INFO - Starting OctoPrint 1.4.2
2020-09-28 21:43:07,108 - octoprint.startup - INFO - ******************************************************************************
2020-09-28 21:43:07,576 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity changed from offline to online
2020-09-28 21:43:07,632 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity state is currently: online
2020-09-28 21:43:07,632 - octoprint.util.connectivity.connectivity_checker - INFO - Connecting to 8.8.8.8:53 is working
2020-09-28 21:43:07,632 - octoprint.util.connectivity.connectivity_checker - INFO - Resolving octoprint.org is working
2020-09-28 21:43:08,343 - octoprint.startup - INFO - Blacklist processing done, adding 10 blacklisted plugin versions: roomtemp (any), GcodeEditor (0.1.1), GcodeEditor (0.2.0), GcodeEditor (0.2.1), GcodeEditor (0.2.2), GcodeEditor (0.2.3), GcodeEditor (0.2.4), GcodeEditor (0.2.5), GcodeEditor (0.2.6), GcodeEditor (0.2.8)
2020-09-28 21:43:08,398 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-28 21:43:09,585 - octoprint.plugins.octoprint.plugins.discovery - INFO - pybonjour is not installed, Zeroconf Discovery won't be available
2020-09-28 21:43:09,605 - octoprint.plugin.core - INFO - Found 21 plugin(s) providing 21 mixin implementations, 36 hook handlers
2020-09-28 21:43:09,784 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2020-09-28 21:43:09,793 - octoprint.server - INFO - Intermediary server started
2020-09-28 21:43:09,793 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-28 21:43:09,859 - octoprint.plugin.core - INFO - Found 21 plugin(s) providing 21 mixin implementations, 36 hook handlers
2020-09-28 21:43:09,892 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2020-09-28 21:43:11,413 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2020-09-28 21:43:11,416 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_SHOW (needs: "Need(method='role', value='plugin_action_command_notification_show')")
2020-09-28 21:43:11,417 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_CLEAR (needs: "Need(method='role', value='plugin_action_command_notification_clear')")
2020-09-28 21:43:11,417 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: "Need(method='role', value='plugin_action_command_prompt_interact')")
2020-09-28 21:43:11,418 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: "Need(method='role', value='plugin_announcements_read')")
2020-09-28 21:43:11,418 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: "Need(method='role', value='plugin_announcements_read'), Need(method='role', value='plugin_announcements_manage')")
2020-09-28 21:43:11,419 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: "Need(method='role', value='plugin_appkeys_admin')")
2020-09-28 21:43:11,419 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: "Need(method='role', value='plugin_backup_access')")
2020-09-28 21:43:11,419 - octoprint.server - INFO - Added new permission from plugin firmware_check: PLUGIN_FIRMWARE_CHECK_DISPLAY (needs: "Need(method='role', value='plugin_firmware_check_display')")
2020-09-28 21:43:11,420 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: "Need(method='role', value='plugin_logging_manage')")
2020-09-28 21:43:11,420 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: "Need(method='role', value='plugin_pi_support_check')")
2020-09-28 21:43:11,421 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: "Need(method='role', value='plugin_pluginmanager_manage')")
2020-09-28 21:43:11,421 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: "Need(method='role', value='plugin_pluginmanager_manage'), Need(method='role', value='plugin_pluginmanager_install')")
2020-09-28 21:43:11,423 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: "Need(method='role', value='plugin_softwareupdate_check')")
2020-09-28 21:43:11,424 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: "Need(method='role', value='plugin_softwareupdate_update')")
2020-09-28 21:43:12,419 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-28 21:43:13,371 - octoprint.util.pip - INFO - Version of pip is 20.2.3
2020-09-28 21:43:13,373 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-28 21:43:13,373 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-28 21:43:13,475 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2020-09-28 21:43:13,491 - octoprint.plugin.core - INFO - Initialized 21 plugin implementation(s)
2020-09-28 21:43:13,503 - octoprint.plugin.core - INFO - 21 plugin(s) registered with the system:
|  Action Command Notification Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/discovery
|  Error Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  File Check (2020.8.7) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_file_check
|  FileManager (0.1.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_filemanager
|  Firmware Check (2020.9.23) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmware_check
|  Firmware Updater (1.7.0) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmwareupdater
|  GCode Viewer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/gcodeviewer
|  ipOnConnect (0.2.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_ipOnConnect
|  Logging (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/logging
|  Login UI (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/loginui
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Software Update (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2020-09-28 21:43:13,517 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1200.0
|      ram: 917016576
|  os:
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 3 Model B Rev 1.2
|          octopi_version: 0.17.0
|  python:
|      pip: 20.2.3
|      version: 3.7.3
|      virtualenv: /home/pi/oprint
2020-09-28 21:43:13,528 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2020-09-28 21:43:13,548 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2020-09-28 21:43:14,401 - octoprint.server - INFO - Shutting down intermediary server...
2020-09-28 21:43:14,443 - octoprint.server - INFO - Intermediary server shut down
2020-09-28 21:43:14,446 - octoprint.events - INFO - Processing startup event, this is our first event
2020-09-28 21:43:14,446 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2020-09-28 21:43:14,449 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2020-09-28 21:43:14,452 - octoprint.server - INFO - Autoconnect on startup is configured, trying to connect to the printer...
2020-09-28 21:43:14,492 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-28 21:43:14,516 - octoprint.plugins.ipOnConnect - INFO - ipOnConnectPlugin: M117 192.168.3.53
2020-09-28 21:43:15,197 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.61s
2020-09-28 21:43:15,249 - octoprint.server - INFO - Trying to connect to configured serial port None
2020-09-28 21:43:15,560 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2020-09-28 21:43:15,590 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2020-09-28 21:43:15,643 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2020-09-28 21:43:15,741 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "Ender 3 Pro #2 - New" for SSDP
2020-09-28 21:43:16,032 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2020-09-28 21:43:16,200 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-28 21:43:16,435 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.72s
2020-09-28 21:43:16,583 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-28 21:43:16,826 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.63s
2020-09-28 21:43:16,998 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:43:17,006 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:43:17,282 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-28 21:43:17,291 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-28 21:43:17,292 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-28 21:43:17,334 - octoprint.plugins.softwareupdate - INFO - Minimum free storage across all update relevant locations is 48.1GB. That is considered sufficient for updating.
2020-09-28 21:43:17,482 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.67s
2020-09-28 21:43:17,609 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 1 port/baudrate candidates: /dev/ttyUSB0@115200
2020-09-28 21:43:17,609 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyUSB0, baudrate 115200
2020-09-28 21:43:17,610 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2020-09-28 21:43:17,711 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.72s
2020-09-28 21:43:17,737 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2020-09-28 21:43:17,757 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-09-28 21:43:17,827 - octoprint.plugins.ipOnConnect - INFO - ipOnConnectPlugin: M117 192.168.3.53
2020-09-28 21:43:18,184 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2020-09-28 21:43:18,238 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'base_url': 'http://192.168.3.53/', 'path': '/', 'query_string': 'l10n=en'}
2020-09-28 21:43:18,461 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.66s
2020-09-28 21:43:18,493 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 8}
2020-09-28 21:43:18,687 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.7s
2020-09-28 21:43:19,082 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0', 'plugins': 'iponconnect:0.2.4,firmwareupdater:1.7.0,filemanager:0.1.4'}
2020-09-28 21:43:19,286 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.67s
2020-09-28 21:43:19,488 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.58s
2020-09-28 21:43:19,494 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2020-09-28 21:43:19,604 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Operational"
2020-09-28 21:43:19,610 - octoprint.plugins.firmwareupdater - INFO - Got CONNECTED event
2020-09-28 21:43:19,611 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-09-28 21:43:19,612 - octoprint.plugins.firmwareupdater - INFO - Run postflash flag is not set
2020-09-28 21:43:19,637 - octoprint.plugins.ipOnConnect - INFO - ipOnConnectPlugin: M117 192.168.3.53
2020-09-28 21:43:19,639 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0'}
2020-09-28 21:43:20,338 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2020-09-28 21:43:24,324 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-28 21:43:26,218 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.3.107
2020-09-28 21:43:26,352 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-28 21:43:28,295 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin Creality 3D"
2020-09-28 21:43:28,313 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2020-09-28 21:43:28,810 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {'firmware_name': 'Marlin Creality 3D', 'printer_port': None, 'printer_baudrate': 115200}
2020-09-28 21:43:28,873 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:43:28,873 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:43:33,473 - octoprint.server.preemptive_cache - INFO - ... done in 15.23s
2020-09-28 21:43:33,530 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:43:33,531 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:43:33,555 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.3.107
2020-09-28 21:43:34,080 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-28 21:43:34,115 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:43:34,116 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:43:36,290 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-28 21:43:47,961 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:43:47,962 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:44:08,773 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Ut-test/Rivit_10mm_support.gcode finished, needed 20.81s
2020-09-28 21:44:15,864 - octoprint.server.api.system - INFO - Performing command for core:restart_safe: sudo service octoprint restart
2020-09-28 21:44:16,179 - octoprint.server - INFO - Shutting down...
2020-09-28 21:44:17,139 - octoprint.server - INFO - Calling on_shutdown on plugins
2020-09-28 21:44:17,142 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-09-28 21:44:17,146 - octoprint.events - INFO - Event loop shut down
2020-09-28 21:44:17,681 - octoprint.plugins.tracking - INFO - Sent tracking event shutdown, payload: {}
2020-09-28 21:44:17,683 - octoprint.server - INFO - Goodbye!

Additional information about your setup

Four Raspberry Pi 3B+ with 3.5Amp volt+ power supplies, OctoPrint 1.4.2, OctoPi 0.17, Creality Ender-3, 1.1.5 silent board stock, FireFox 81.0, Windows 10

rPi's are all wired 1Gbit port to a switch to desktop. Nothing is on wireless.

All OctoPi's were originally fresh loaded months ago with OctoPi 0.17 (not upgraded), and then simple config added, upload folder(s) copied back.

m.hutchinson · September 28, 2020, 9:12pm

I take it this is the interesting code from bottom of this log (after safe mode restart):

octoprint.filemanager.analysis - INFO - Starting analysis of local:Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:45:14,858 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:45:35,472 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Ut-test/Rivit_10mm_support.gcode finished, needed 20.62s

Full Second log, after Safe mode Restart and repeating upload:

2020-09-28 21:44:20,046 - octoprint.startup - INFO - ******************************************************************************
2020-09-28 21:44:20,048 - octoprint.startup - INFO - Starting OctoPrint 1.4.2
2020-09-28 21:44:20,048 - octoprint.startup - INFO - Starting in SAFE MODE. Third party plugins will be disabled!
2020-09-28 21:44:20,049 - octoprint.startup - INFO - Reason for safe mode: setting in config.yaml
2020-09-28 21:44:20,049 - octoprint.startup - INFO - ******************************************************************************
2020-09-28 21:44:20,504 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity changed from offline to online
2020-09-28 21:44:20,569 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity state is currently: online
2020-09-28 21:44:20,569 - octoprint.util.connectivity.connectivity_checker - INFO - Connecting to 8.8.8.8:53 is working
2020-09-28 21:44:20,570 - octoprint.util.connectivity.connectivity_checker - INFO - Resolving octoprint.org is working
2020-09-28 21:44:20,587 - octoprint.startup - INFO - Blacklist processing done, adding 10 blacklisted plugin versions: roomtemp (any), GcodeEditor (0.1.1), GcodeEditor (0.2.0), GcodeEditor (0.2.1), GcodeEditor (0.2.2), GcodeEditor (0.2.3), GcodeEditor (0.2.4), GcodeEditor (0.2.5), GcodeEditor (0.2.6), GcodeEditor (0.2.8)
2020-09-28 21:44:20,694 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-28 21:44:21,871 - octoprint.plugins.octoprint.plugins.discovery - INFO - pybonjour is not installed, Zeroconf Discovery won't be available
2020-09-28 21:44:21,887 - octoprint.plugin.core - INFO - Found 21 plugin(s) providing 18 mixin implementations, 32 hook handlers
2020-09-28 21:44:22,145 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2020-09-28 21:44:22,153 - octoprint.server - INFO - Intermediary server started
2020-09-28 21:44:22,153 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-28 21:44:22,219 - octoprint.plugin.core - INFO - Found 21 plugin(s) providing 18 mixin implementations, 32 hook handlers
2020-09-28 21:44:22,251 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2020-09-28 21:44:23,767 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2020-09-28 21:44:23,771 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_SHOW (needs: "Need(method='role', value='plugin_action_command_notification_show')")
2020-09-28 21:44:23,772 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_CLEAR (needs: "Need(method='role', value='plugin_action_command_notification_clear')")
2020-09-28 21:44:23,772 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: "Need(method='role', value='plugin_action_command_prompt_interact')")
2020-09-28 21:44:23,772 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: "Need(method='role', value='plugin_announcements_read')")
2020-09-28 21:44:23,773 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: "Need(method='role', value='plugin_announcements_manage'), Need(method='role', value='plugin_announcements_read')")
2020-09-28 21:44:23,773 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: "Need(method='role', value='plugin_appkeys_admin')")
2020-09-28 21:44:23,774 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: "Need(method='role', value='plugin_backup_access')")
2020-09-28 21:44:23,774 - octoprint.server - INFO - Added new permission from plugin firmware_check: PLUGIN_FIRMWARE_CHECK_DISPLAY (needs: "Need(method='role', value='plugin_firmware_check_display')")
2020-09-28 21:44:23,775 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: "Need(method='role', value='plugin_logging_manage')")
2020-09-28 21:44:23,775 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: "Need(method='role', value='plugin_pi_support_check')")
2020-09-28 21:44:23,775 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: "Need(method='role', value='plugin_pluginmanager_manage')")
2020-09-28 21:44:23,776 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: "Need(method='role', value='plugin_pluginmanager_manage'), Need(method='role', value='plugin_pluginmanager_install')")
2020-09-28 21:44:23,778 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: "Need(method='role', value='plugin_softwareupdate_check')")
2020-09-28 21:44:23,779 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: "Need(method='role', value='plugin_softwareupdate_update')")
2020-09-28 21:44:24,765 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-28 21:44:25,716 - octoprint.util.pip - INFO - Version of pip is 20.2.3
2020-09-28 21:44:25,718 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-28 21:44:25,718 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-28 21:44:25,816 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2020-09-28 21:44:25,824 - octoprint.plugin.core - INFO - Initialized 18 plugin implementation(s)
2020-09-28 21:44:25,835 - octoprint.plugin.core - INFO - 21 plugin(s) registered with the system:
|  Action Command Notification Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/discovery
|  Error Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  File Check (2020.8.7) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_file_check
| !FileManager (0.1.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_filemanager
|  Firmware Check (2020.9.23) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmware_check
| !Firmware Updater (1.7.0) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmwareupdater
|  GCode Viewer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/gcodeviewer
| !ipOnConnect (0.2.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_ipOnConnect
|  Logging (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/logging
|  Login UI (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/loginui
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Software Update (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2020-09-28 21:44:25,849 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1200.0
|      ram: 917016576
|  os:
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 3 Model B Rev 1.2
|          octopi_version: 0.17.0
|  python:
|      pip: 20.2.3
|      version: 3.7.3
|      virtualenv: /home/pi/oprint
2020-09-28 21:44:25,860 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2020-09-28 21:44:25,880 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2020-09-28 21:44:26,681 - octoprint.server - INFO - Shutting down intermediary server...
2020-09-28 21:44:26,889 - octoprint.server - INFO - Intermediary server shut down
2020-09-28 21:44:26,891 - octoprint.events - INFO - Processing startup event, this is our first event
2020-09-28 21:44:26,892 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2020-09-28 21:44:26,892 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2020-09-28 21:44:26,897 - octoprint.server - INFO - Autoconnect on startup is configured, trying to connect to the printer...
2020-09-28 21:44:26,932 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-28 21:44:28,454 - octoprint.server - INFO - Trying to connect to configured serial port None
2020-09-28 21:44:28,611 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2020-09-28 21:44:28,653 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2020-09-28 21:44:28,693 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2020-09-28 21:44:28,825 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "Ender 3 Pro #2 - New" for SSDP
2020-09-28 21:44:28,829 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2020-09-28 21:44:28,840 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2020-09-28 21:44:28,841 - octoprint.server - INFO - Server started successfully in safe mode as requested from config, removing flag
2020-09-28 21:44:29,055 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-28 21:44:29,150 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-28 21:44:29,289 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:44:29,290 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:44:29,422 - octoprint.util.comm - INFO - Serial detection: Performing autodetection with 1 port/baudrate candidates: /dev/ttyUSB0@115200
2020-09-28 21:44:29,422 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyUSB0, baudrate 115200
2020-09-28 21:44:29,423 - octoprint.util.comm - INFO - Connecting to port /dev/ttyUSB0, baudrate 115200
2020-09-28 21:44:29,585 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2020-09-28 21:44:29,666 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-09-28 21:44:30,240 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-28 21:44:30,243 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-28 21:44:30,243 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-28 21:44:30,302 - octoprint.plugins.softwareupdate - INFO - Minimum free storage across all update relevant locations is 48.1GB. That is considered sufficient for updating.
2020-09-28 21:44:30,381 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Operational"
2020-09-28 21:44:30,388 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-09-28 21:44:30,940 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'base_url': 'http://192.168.3.53/', 'path': '/', 'query_string': 'l10n=en'}
2020-09-28 21:44:31,234 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 9}
2020-09-28 21:44:31,726 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2020-09-28 21:44:31,858 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0', 'plugins': ''}
2020-09-28 21:44:32,395 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0'}
2020-09-28 21:44:32,621 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2020-09-28 21:44:33,863 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:44:33,863 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:44:38,922 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin Creality 3D"
2020-09-28 21:44:38,942 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2020-09-28 21:44:39,394 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {'firmware_name': 'Marlin Creality 3D', 'printer_port': None, 'printer_baudrate': 115200}
2020-09-28 21:44:47,152 - octoprint.server.preemptive_cache - INFO - ... done in 16.21s
2020-09-28 21:44:47,165 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-28 21:44:47,186 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.3.107
2020-09-28 21:44:47,690 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-28 21:44:47,764 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-28 21:44:47,765 - octoprint.access.users - INFO - Logged in user: mark
2020-09-28 21:44:51,022 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-28 21:45:14,857 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:45:14,858 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Ut-test/Rivit_10mm_support.gcode
2020-09-28 21:45:35,472 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Ut-test/Rivit_10mm_support.gcode finished, needed 20.62s

Charlie_Powell · September 28, 2020, 9:56pm

Looking at the log as I upload a (large) file, it uploads in what I would consider 'usual' time, the analysis does take a while (160s for the file I found) but the 'Saving' bar does not hang for this length of time. When the file is uploaded, it is 'finished' and then the analysis starts.
So that may not be your issue here although, I can't rule out different behaviour as I am running a development version.

m.hutchinson · September 29, 2020, 2:22am

Here's the log from my #4 spare - this rPi does not experience this issue. Indeed, if I grab the log a few seconds after the file is uploaded, the analysis portion is not logged, so that would indeed jive with what you see as it forks off a separate process to do the analysis and does not hang the web daemon waiting for the analysis to complete.

2020-09-29 03:15:23,066 - octoprint.startup - INFO - ******************************************************************************
2020-09-29 03:15:23,068 - octoprint.startup - INFO - Starting OctoPrint 1.4.2
2020-09-29 03:15:23,069 - octoprint.startup - INFO - ******************************************************************************
2020-09-29 03:15:23,513 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity changed from offline to online
2020-09-29 03:15:23,572 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity state is currently: online
2020-09-29 03:15:23,572 - octoprint.util.connectivity.connectivity_checker - INFO - Connecting to 8.8.8.8:53 is working
2020-09-29 03:15:23,572 - octoprint.util.connectivity.connectivity_checker - INFO - Resolving octoprint.org is working
2020-09-29 03:15:24,152 - octoprint.startup - INFO - Blacklist processing done, adding 10 blacklisted plugin versions: roomtemp (any), GcodeEditor (0.1.1), GcodeEditor (0.2.0), GcodeEditor (0.2.1), GcodeEditor (0.2.2), GcodeEditor (0.2.3), GcodeEditor (0.2.4), GcodeEditor (0.2.5), GcodeEditor (0.2.6), GcodeEditor (0.2.8)
2020-09-29 03:15:24,209 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-29 03:15:25,397 - octoprint.plugins.octoprint.plugins.discovery - INFO - pybonjour is not installed, Zeroconf Discovery won't be available
2020-09-29 03:15:25,419 - octoprint.plugin.core - INFO - Found 22 plugin(s) providing 22 mixin implementations, 37 hook handlers
2020-09-29 03:15:25,576 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2020-09-29 03:15:25,584 - octoprint.server - INFO - Intermediary server started
2020-09-29 03:15:25,585 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-09-29 03:15:25,652 - octoprint.plugin.core - INFO - Found 22 plugin(s) providing 22 mixin implementations, 37 hook handlers
2020-09-29 03:15:25,684 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2020-09-29 03:15:26,107 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2020-09-29 03:15:26,110 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_SHOW (needs: "Need(method='role', value='plugin_action_command_notification_show')")
2020-09-29 03:15:26,111 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_CLEAR (needs: "Need(method='role', value='plugin_action_command_notification_clear')")
2020-09-29 03:15:26,111 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: "Need(method='role', value='plugin_action_command_prompt_interact')")
2020-09-29 03:15:26,112 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: "Need(method='role', value='plugin_announcements_read')")
2020-09-29 03:15:26,112 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: "Need(method='role', value='plugin_announcements_read'), Need(method='role', value='plugin_announcements_manage')")
2020-09-29 03:15:26,113 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: "Need(method='role', value='plugin_appkeys_admin')")
2020-09-29 03:15:26,113 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: "Need(method='role', value='plugin_backup_access')")
2020-09-29 03:15:26,114 - octoprint.server - INFO - Added new permission from plugin firmware_check: PLUGIN_FIRMWARE_CHECK_DISPLAY (needs: "Need(method='role', value='plugin_firmware_check_display')")
2020-09-29 03:15:26,114 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: "Need(method='role', value='plugin_logging_manage')")
2020-09-29 03:15:26,114 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: "Need(method='role', value='plugin_pi_support_check')")
2020-09-29 03:15:26,115 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: "Need(method='role', value='plugin_pluginmanager_manage')")
2020-09-29 03:15:26,115 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: "Need(method='role', value='plugin_pluginmanager_install'), Need(method='role', value='plugin_pluginmanager_manage')")
2020-09-29 03:15:26,118 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: "Need(method='role', value='plugin_softwareupdate_check')")
2020-09-29 03:15:26,118 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: "Need(method='role', value='plugin_softwareupdate_update')")
2020-09-29 03:15:27,117 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-29 03:15:28,070 - octoprint.util.pip - INFO - Version of pip is 20.2.3
2020-09-29 03:15:28,072 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-29 03:15:28,072 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-29 03:15:28,183 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2020-09-29 03:15:28,199 - octoprint.plugin.core - INFO - Initialized 22 plugin implementation(s)
2020-09-29 03:15:28,211 - octoprint.plugin.core - INFO - 22 plugin(s) registered with the system:
|  Action Command Notification Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/discovery
|  Error Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  File Check (2020.8.7) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_file_check
|  FileManager (0.1.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_filemanager
|  Firmware Check (2020.9.23) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmware_check
|  Firmware Updater (1.7.0) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmwareupdater
|  GCode Viewer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/gcodeviewer
|  ipOnConnect (0.2.4) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_ipOnConnect
|  Logging (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/logging
|  Login UI (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/loginui
|  Marlin GCode Documentation (0.9.0) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_marlingcodedocumentation
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Software Update (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2020-09-29 03:15:28,226 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1200.0
|      ram: 917016576
|  os:
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 3 Model B Rev 1.2
|          octopi_version: 0.17.0
|  python:
|      pip: 20.2.3
|      version: 3.7.3
|      virtualenv: /home/pi/oprint
2020-09-29 03:15:28,236 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2020-09-29 03:15:28,257 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2020-09-29 03:15:29,113 - octoprint.server - INFO - Shutting down intermediary server...
2020-09-29 03:15:29,287 - octoprint.server - INFO - Intermediary server shut down
2020-09-29 03:15:29,289 - octoprint.events - INFO - Processing startup event, this is our first event
2020-09-29 03:15:29,289 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2020-09-29 03:15:29,293 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2020-09-29 03:15:29,301 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2020-09-29 03:15:29,317 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2020-09-29 03:15:29,318 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2020-09-29 03:15:29,352 - octoprint.plugins.ipOnConnect - INFO - ipOnConnectPlugin: M117 192.168.3.54
2020-09-29 03:15:29,356 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "Spare" for SSDP
2020-09-29 03:15:29,363 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-29 03:15:29,469 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2020-09-29 03:15:29,645 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-09-29 03:15:29,708 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-29 03:15:29,972 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.67s
2020-09-29 03:15:30,140 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.62s
2020-09-29 03:15:30,249 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-29 03:15:30,283 - octoprint.access.users - INFO - Logged in user: mark
2020-09-29 03:15:30,751 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2020-09-29 03:15:30,757 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-09-29 03:15:30,758 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-09-29 03:15:30,780 - octoprint.plugins.softwareupdate - INFO - Minimum free storage across all update relevant locations is 25.9GB. That is considered sufficient for updating.
2020-09-29 03:15:31,335 - octoprint.plugins.marlingcodedocumentation - INFO - Hello MarlingcodedocumentationPlugin!
2020-09-29 03:15:31,338 - octoprint.plugins.ipOnConnect - INFO - ipOnConnectPlugin: M117 192.168.3.54
2020-09-29 03:15:31,931 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 6}
2020-09-29 03:15:31,960 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.73s
2020-09-29 03:15:31,973 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.78s
2020-09-29 03:15:32,407 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'base_url': 'http://192.168.3.54/', 'path': '/', 'query_string': 'l10n=en'}
2020-09-29 03:15:32,661 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0', 'plugins': 'iponconnect:0.2.4,firmwareupdater:1.7.0,filemanager:0.1.4,marlingcodedocumentation:0.9.0'}
2020-09-29 03:15:32,992 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.58s
2020-09-29 03:15:33,082 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.7s
2020-09-29 03:15:33,356 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'version': '1.4.2', 'os': 'linux', 'python': '3.7.3', 'pip': '20.2.3', 'cores': 4, 'freq': 1200.0, 'ram': 917016576, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'octopi_version': '0.17.0'}
2020-09-29 03:15:33,980 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.56s
2020-09-29 03:15:34,068 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.71s
2020-09-29 03:15:34,269 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2020-09-29 03:15:34,694 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2020-09-29 03:15:34,821 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.48s
2020-09-29 03:15:34,831 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.54s
2020-09-29 03:15:35,713 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-29 03:15:35,714 - octoprint.access.users - INFO - Logged in user: mark
2020-09-29 03:15:51,598 - octoprint.server.preemptive_cache - INFO - ... done in 19.19s
2020-09-29 03:15:51,619 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-29 03:15:51,632 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.3.107
2020-09-29 03:15:52,239 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.3.107
2020-09-29 03:15:52,309 - octoprint.server.util.flask - INFO - Passively logging in user mark from ::ffff:192.168.3.107
2020-09-29 03:15:52,310 - octoprint.access.users - INFO - Logged in user: mark
2020-09-29 03:15:54,347 - octoprint.server.util.sockjs - INFO - User mark logged in on the socket from client ::ffff:192.168.3.107
2020-09-29 03:16:03,331 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Rivit_10mm.gcode
2020-09-29 03:16:03,332 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Rivit_10mm.gcode
2020-09-29 03:16:23,749 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Rivit_10mm.gcode finished, needed 20.42s
2020-09-29 03:16:47,922 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Rivit_10mm_support.gcode
2020-09-29 03:16:47,924 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/Rivit_10mm_support.gcode
2020-09-29 03:17:08,300 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Rivit_10mm_support.gcode finished, needed 20.38s

m.hutchinson · September 29, 2020, 2:24am

Oh, and the files I'm uploading here to test with are 3 to 5 MB. Certainly not Killer 136 - 200 MB files like I sometimes have.

Normal end upload "saving..." pause is 1-2 seconds at most, not the 30 seconds give or take for my "production" rPi units.

m.hutchinson · September 29, 2020, 2:45am

Last point of interest - possibly.

The three units with the delay have 64GB cards, the Spare #4 without the delay is only (grin) a 32GB card.

foosel · September 29, 2020, 8:41am

Analysis indeed happens in a different thread than the upload. It only gets enqueued then, that's all. It cannot hold the upload from completing. What happens between 100% and saving is moving the file to its final location. Upload happens to a temporary file on disk. That path then gets handed over to the upload handler, which moves the file to its final destination and collects some metadata (on a clean/safe mode OctoPrint that is only a file hash).

I see two possible reasons for a slow down here. One is that the move is not an atomic move but instead has to be done as a copy and delete, which would happen if your temporary directory is located on a different partition or drive than the final upload folder. The other is there being a whole TON of files in the target folder, meaning the metadata.json file that has to be first read, then updated, then written back to disk takes a lot of time to process.

m.hutchinson · September 29, 2020, 3:09pm

I have subfolders on each device that drills down to no more than 40 files in a folder (and usually between 1 and 10 per folder). I can certainly try backing up one of the .octoprint/uploads folder on a slow unit to my Spare and see if replicating that structure causes the issue to appear.

I thought the metadata.json might be an issue, so I had started with a newly created folder. Problem occurs with a newly created folder, too. That should not have a metadata.json in it until I upload a .gcode. I verified that to be true with WinSCP.

There are only two partitions on the OctoPi. the FAT32 pre-boot partition and the ext4 of the Linux system.

Does the temporary directory (unsure where that is) contain a metadata.json?

Interesting. While watching the folder with WinSCP during the save, and refreshing I noticed that the metadata.json and the uploaded .gcode gets written to the target folder nearly immediately (one to two seconds max) - then the hang starts. And if I try to refresh my browser, It hangs until that ~30 seconds pass. Replicated this with Firefox and Chrome.

Good news, the delay is down to 24 seconds now.

@foosel - As I have three units all doing the same thing, I can try reimaging one with stock OctoPi 0.17, and upgrading to 1.4.2 (no python upgrade) and see if this issue reproduces itself, then do the Python 3 update and repeat tests. If this sounds like a valid test, I will make that so.

Original upgrade path was OctoPi 0.17 with it's OctoPrint 1.3x, upgraded to 1.40 (and in use for months with no issue), then 1.42 upgrade last week, followed closely by Python 3. I did not upload to my production Pi's on 1.42 before upgrading Python. Thoughts?

foosel · September 29, 2020, 4:32pm

Certainly sounds like a good test to do, please make it so

m.hutchinson · September 29, 2020, 11:01pm

OctoPi included OctoPrint 1.3.12 - uploads instant. "Saving" bar doesn't even show 100% before file is listed.

Upgraded to 1.4.2 - Same excellent results.

Restore my back up (no .gcode's) - Same excellent results.

Restore my .gcodes (8 Gigs, 720 Files, 154 folders) - slowness pops up. File uploads take 15-20 seconds to complete once the bar hits 100%. Also, creating a folder takes a few seconds now.

Python isn't upgraded yet, but I don't think we need to look at that yet.

So, it would look like perhaps there is a difference in file saving/handling & folder creation between 1.4.0 and 1.4.2 affecting large upload collections?

foosel · October 1, 2020, 9:48am

I've just pushed a change to the maintenance branch that should hopefully mitigate that. I've added more granular and aggressive caching right into the local storage manager, on a folder base. If you now upload to a folder, only the data for that folder will be invalidated, everything else can still be served from the cache instead of having to be rescanned again from the file system. Greatly reduces the time needed to produce a file list in such cases. Before, it meant the whole recursive scan needed to be done again since caching only happened at storage level.

Will be part of 1.5.0.

I'll still look though if I can find anything that changed between 1.4.0 and 1.4.1/2 that would explain worse performance here in the first place.

m.hutchinson · October 1, 2020, 7:17pm

Thank you @foosel - that does explain why larger collections could experience the delay to begin with. And likely would not change results if I swapped rPi boards around.

10 existing files in the folder, I upload one, the scan hits all 11 files to generate a fresh .metadata.json file?

I'm still on release/stable - and tried again (before trying to switch over to maintenance branch) on rPi #1 through #4 - mostly to confirm status of the issue.

I'm now down to a 6-8 second delay on my #1 re-imaged, 1.4.2/Python2 device. I have not printed (maybe once) or rebooted that device since I last posted. No updates, no plug-in changes, nothing.

Units #2 and #3 (1.4.2/Python3) are at about a 25 second delay.

Unit #4 - my Spare that had no issues before, now has a 5-6 second delay. That is with two files in the upload root, and a folder. Created a folder, and uploaded to that folder, and now there's a delay. (#4 is OctoPrint 1.4.2, Python 3.7.3, OctoPi 0.17.0, same as Unit #2 and #3)

I have no idea why #1 is gaining speed, while #2 and #3 are the same speed, and #4 is slowing down. Same model rPi, and quality, fast Samsung SD cards.

Curious.

And I'm sorry this doesn't seem to help much.

My next test will be take my #4, load 1 GB of uploads, and retest. Then go maintenance release, load the entire 4.8 GB upload folder to it and perform the "create folder, upload file" test.

Question: does the .metadata.json file in each upload folder tie in any way back to the original rPi, in that the hash value is based in part on the salt, or is it more independent like a CRC32 of the file? i.e. should I copy the .metadata.json in each upload folder between units, or should I not copy it?

foosel · October 2, 2020, 8:33am

The hash is just a hash of the file itself (md5sum if I remember correctly, so nothing fancy), so definitely not device dependent. It's weird that you get so different results. Just to rule out any third party plugins interfering here - best make any kind of tests in safe mode if you don't already. Plugins that process the file during upload (there are hooks for that) COULD cause this, completely unrelated to the library size.

I've also spent some hours yesterday going over the code and trying to figure out if there are any specific changes between 1.4.0 and 1.4.2 that could cause a slowdown here but I haven't found anything. I'm wondering though if I should add a new status to that progress bar to at least give us a bit more to work with in the future - "Saving..." will be displayed while the file is still being written to the backend, but also until the fresh file list has been fetched from the server. So it's currently not possible to say if it staying on "saving" for a long time means it's being slow to write or slow to refresh the list. I'll see that I can make this more transparent so that we get more options for debugging such situations in the future.

jandar · October 2, 2020, 10:12pm

@foosel I don't know if this is suitable for a cross platform application like OctoPrint but on Linux one can use inotify to keep the cached version of a directory tree in sync with the filesystem. Maybe there are similar functionalities available on Windows and Mac.

For Python on Linux I have found PyInotify

I have used this for a c++ application and it was moderately easy.

m.hutchinson · October 3, 2020, 7:11am

I see little to no difference in safe mode on any of the units. An upload may take a couple seconds less to upload in safe mode, but it's the difference between a 30 second pause and a 28 second pause.

Same thing on my mostly empty #4 Spare - it goes from 5 seconds to, well, 4.5 seconds.

Certainly having a Saving.../Scanning.../Refreshing List... status on an upload may clue in further where that delay is. I like that idea!

With the slight variations in time (30 second delay one day, 25 the next) It's almost like there's mandatory wear leveling forced on the microSD card or the volume with 1.4.2 that wasn't in place with 1.4.0.

If I were to add a USB 3.0 thumbdrive, and moved the uploads to it, I wonder what would happen...

m.hutchinson · February 27, 2021, 10:43pm

I hate to moldypost like this, but... yes, the additional status change was noticed and it sits at the "Refreshing List" message point since I last posted.

Continued to update, now running 1.5.3, I still get the delay at the "Refreshing List" message.

BUT! I noticed that if I upload a file, wait for the "Refreshing List" delay to clear, then start a print job, I can immediately upload further files with no delay. Uploads take seconds like expected.

Now at: OctoPrint 1.5.3 Python 3.7.3 OctoPi 0.17.0

Next test will be with a OctoPi 0.18 image once I backup/image/restore.

m.hutchinson · March 12, 2021, 3:18am

Now at OctoPrint 1.5.3 Python 3.7.3 OctoPi 0.18.0

Fresh image of octopi-buster-armhf-lite-0.18.0 onto a 64GB Samsung TF card

About a 20-25 second delay on the upload.

looking at the log:

2021-03-12 03:04:32,836 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Test/Folder/Testfile.gcode
2021-03-12 03:04:32,837 - 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 /home/pi/.octoprint/uploads/Test/Folder/Testfile.gcode
2021-03-12 03:04:54,677 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Test/Folder/Testfile.gcode finished, needed 21.84s

so appears to be waiting for the analysis to complete.

foosel · March 12, 2021, 10:01am

Analysis should be happening asynchronously and not make the upload wait. But I can reproduce. So that is a bug and needs to be investigated.

ETA It doesn't do it always though... my current guess is that there's a race condition in there somewhere. A lock that sometimes gets taken by the API and sometimes by the analysis would explain this behaviour, but right now I don't see something like that.

foosel · March 12, 2021, 12:53pm

@m.hutchinson Can you do me a favor and instead of uploading a file simply click the refresh icon on the list and share how long that takes? Should be visible in the log or your browser's network console. After further testing here I cannot confirm that it waits for the analysis, I explicitly set that to wait 20s more and the request still isn't as fast as I wish it was, but definitely finishes before the analysis finishes.

m.hutchinson · March 12, 2021, 3:08pm

Refreshes show about 2.2 - 2.4 seconds in the Firefox network console. This is testing with a few folders, with between 1 and 10 files, and 1-35 folders in each.

I did it from the root, and with probably 200 folders and an average of 6 .gcodes per folder, it took about 2.3 sec. Each file in the log took around 6-50ms each, ending in:

2021-03-12 15:02:23,399 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726cd370>,'/home/pi/.octoprint/uploads',base='',force_refresh=True) took 1730.04ms
2021-03-12 15:02:48,722 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff: (removed IP)