Slow boot up post upgrade to Octoprint 1.7.0

Since I updated to the latest version, the system take much longer to boot, and then even longer for the files / file manager to show any uploaded files, and then additional wait time for pre-heat to become active, in total approximately 10-15 minutes, whereas pre the update I could boot from cold and be ready in 2-3 minutes....

System info:
browser.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36 Edg/94.0.992.50
connectivity.connection_check: 192.168.0.252:53
connectivity.connection_ok: true
connectivity.enabled: true
connectivity.online: true
connectivity.resolution_check: octoprint.org
connectivity.resolution_ok: true
env.hardware.cores: 4
env.hardware.freq: 1200
env.hardware.ram: 914006016
env.os.bits: 32
env.os.id: linux
env.os.platform: linux
env.plugins.pi_support.model: Raspberry Pi 3 Model B Rev 1.2
env.plugins.pi_support.octopi_version: 0.18.0
env.plugins.pi_support.throttle_state: 0x0
env.python.pip: 20.3.3
env.python.version: 3.7.3
env.python.virtualenv: true
octoprint.safe_mode: false
octoprint.version: 1.7.0
printer.firmware: Prusa-Firmware 3.2.3 based on Marlin
systeminfo.generator: systemapi

This should have been posted in the Get Help - section of the forum and I think you should start a new post there. You' have a template available which sort of guides you through gathering the required infos.

(Spoiler:

  • turn on Serial logging first
  • then stop octoprint, shutdown the pi, just like you always do.
  • then start it up, so all that you described above happens and communication between OctoPrint and the printer is logged
    -then download the systeminfo bundle and attach it to the new posting)

And also test safe mode.

I've just started an 18 Hr print, so I'll do what you want when finished....

As requested sys info bundles with serial logging enabled and also safe mode start up. Note that I've also set the logging to debug to get the maximum amount of info, and from what I can see, I suspect that the slow boot up maybe related to the number of gcode files on the system, which appear to be being parsed on start up ?
octoprint-systeminfo-20211021105218.zip (67.8 KB)
safemode-octoprint-systeminfo-20211021110432.zip (89.3 KB)

It's checking your uploads folder and making sure it has all metadata for operation. For some reason it takes a whopping 3min to do this in your OLD folder. We are only talking iterating through the files and checking, NOT generating new metadata or anything as far as I can see. What is in this OLD folder? How many files? Any really big ones? Is it maybe located on a network drive? Anything else peculiar about it?

I created the old folder a few days ago, when I started doing print runs for a Voron2 printer...
The folder has 360 files (1.83 GB total) I keep the files available, as it makes it easier when I need to re-print some parts for focusers etc. all files are held on the Pi3, one thought that just struck me, should I be up dating the the Pi to a Pi4 ??

IMO, you don't need to upgrade the RPi. What I believe you should do is move the old folder. I use WinSCP to move files between my RPi and my main system.

If you leave the files on the RPi, I hope you have a good backup system in place because SD cards do fail. I have a USB SD card reader/writer and use something like rpi-clone to make a copy.

As a safety measure, I auto backup the octoprint folder using ssh tools to a network drive, but I do not want to remove the files as I regularly re-print some files. .

I have a couple of Pi4's knocking around, so I could try an upgrade, but I'm not sure if a clone of the running SD card, off a Pi3, would work on a Pi4, I'll just have to give it a go....

I'm running OctoPrint on a pi3b and I just checked the size of the uploads folder. It's 1,5GB and my instance of OctoPrint doesn't take ages to restart.
It might be something about the sd-card. Almost 3 min to just open and enter a directory is strange.
Did you check /var/log/syslog for strange messages? Take a look at what sudo dmesg shows?

I've just cloned the card and while at it gave it a check & all ok, the syslog file doesn't show anything untoward same with dmesg

Could it be the network syncing that is slowing it down entering/reading the folder?

FYI, all my network is wired Gb, wifi is just for the toys, and any services/servers, e.g. proxy, are all run locally and connect to the internet via a Ubiquiti firewall/router @ 75MB/sec, so I don't think its network related...

Also fyi, I did a clean install, using Pi Imager / Octopi (Stable), onto a 4GB Pi4 device and on initial logon to web interface, restored a backup from the 'original' such that the Pi4 has all the same files, plugins etc. On rebooting, I get the same long boot up time, as per the original Pi3, so I suspect the problem lies with the parsing of the metadata, is it doing a comparison with what it thinks the metadata is to what is already stored ??

Based on the log the problem is definitely something with the OLD folder or its contents that's causing the slow down here. It's impossible to say what that is however, from afar.

Let me maybe explain what exactly is happening here regarding metadata. It's walking through the folders and taking inventory of the files, building a cache in the process, and that also includes reading the .metadata.json file associated with each subfolder and using that for further entry information (e.g. different display name than on disk name). If a file is found that's not present in the metadata file, or no metadata file is found, THEN metadata will actually have to be created and written, but under normal circumstances that should rarely ever be the case during this phase. Normal circumstances here is, iterating through files and folders that were created through OctoPrint.

You said you moved the OLD folder. How did you move it? If you did this outside of OctoPrint and somehow the .metadata.json file got lost in the process, that would explain why it would take long. However, once it actually runs through it should have collected all it needs and not take ages again.

Hi Gina, I understand what you are saying, but looking at the timestamp of the current metadata file, it looks like its being re-created on each boot (I've attached the metadata file from today).. whereas the metadata files for the 2 other folders and the root directory, are not showing an updated timestamp. is there a size limit on the metadata file, so that it gets recreated ?

Metatdata.zip (7.3 KB)

No limits or anything. It will open the existing one and see if anything needs updating/recreation. If it's doing this on every boot, something's really fishy here that I have no idea what it could be right now, because the only way I can imagine that happening is if for some reason the file can't actually be written to disk.

There is 7.1 GB free space on the card, and the file is being written to disk ok, so I don't think it's space or permissions etc.
Using an SSH session, I've shutdown the octoprint service (sudo service octoprint stop) and moved the OLD folder to /home/pi, using a Bitvise client. on re-starting the service the system booted quickly again, so I'll try & identify which files may or may not be causing an issue, by re-creating the OLD folder using octoprints' file manager and copying the files back a few at a time...
octoprint.log.zip (2.7 KB)

A systemd-analyze blame might also be useful here.

Do any of your files have a # symbol in the name?

[quote="kantlivelong, post:18, topic:38104"]
systemd-analyze blame
[/quote] just the service with the longest boot up time was
dhcpcd.service at 11 seconds

there are no # or other characters apart from "_" and "-" in the file names, but that leads me to suspect that it may be related to total path with filename length, as some are quite long e.g. '20mm_Square_Tube_3_Way_Connector_v7_PSlicer-version_2.3.0_0.2mm_EDGE_MK2S_3h34m.gcode', and why I didn't see any issues earlier, before I moved the files ??